lkml.org 
[lkml]   [2018]   [Dec]   [10]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: [PATCH] pseries/hotplug: Add more delay in pseries_cpu_die while waiting for rtas-stop
    From
    Date
    I have asked Scott Mayes to take a look at one of these crashes from
    the phyp side. I will let you know if he finds anything notable.

    Michael

    On 12/07/2018 08:40 PM, Thiago Jung Bauermann wrote:
    >
    > Gautham R Shenoy <ego@linux.vnet.ibm.com> writes:
    >> On Fri, Dec 07, 2018 at 04:13:11PM +0530, Gautham R Shenoy wrote:
    >>> Sure. I will test the patch and report back.
    >>
    >> I added the following debug patch on top of your patch, and after an
    >> hour's run, the system crashed. Appending the log at the end.
    >
    > Thank you very much for testing! Your debug patch was very helpful as
    > well.
    >
    >> I suppose we still need to increase the number of tries since we wait
    >> only for 2.5ms looping before giving up.
    >
    > Do you think it would have helped? In the debug output you posted I
    > would have expected the following message to show up if the loop
    > finished too early, and it didn't:
    >
    > "Querying DEAD? cpu %i (%i) shows %i\n"
    >
    > So I don't think increasing the loop length would have made a
    > difference. In fact, the call to smp_query_cpu_stopped() always
    > succeeded on the first iteration.
    >
    > I think there is something else going on which we don't fully understand
    > yet. From your other email:
    >
    >> I agree that the Kernel has to respect RTAS's restriction. The PAPR
    >> v2.8.1, Requirement R1-7.2.3-8 under section 7.2.3 says the following:
    >>
    >> "The stop-self service needs to be serialized with calls to the
    >> stop-self, start-cpu, and set-power-level services. The OS must
    >> be able to call RTAS services on other processors while the
    >> processor is stopped or being stopped"
    >>
    >> Thus the onus is on the OS to ensure that there are no concurrent rtas
    >> calls with "stop-self" token.
    >
    > As you say perhaps there's another call to stop-self, start-cpu or
    > set-power-level being made concurrently. I don't currently see how more
    > than one stop-self or start-cpu call could be in flight at the same time
    > given that there are a number of locks being grabbed during CPU hotplug
    > and unplug. OTOH the CPU that actually calls stop-self doesn't seem to
    > grab any locks itself so it's a possibility.
    >
    > As for set-power-level, it's only used in the case of PCI hotplug from
    > what I can see, and that isn't part of the picture in this case, right?
    >
    > We could address this problem directly by adding another lock separate
    > from rtas.lock to serialize just these calls. The challenge is with
    > stop-self, because the CPU calling it will never return to release the
    > lock. Is it possible to grab a lock (or down a semaphore) in the CPU
    > calling stop-self and then release the lock (or up the semaphore) in the
    > CPU running pseries_cpu_die()?
    >
    >>> There's also a race between the CPU driving the unplug and the CPU
    >>> being unplugged which I think is not easy for the CPU being
    >>> unplugged to win, which makes the busy loop in pseries_cpu_die() a
    >>> bit fragile. I describe the race in the patch description.
    >>>
    >>> My solution to make the race less tight is to make the CPU driving
    >>> the unplug to only start the busy loop only after the CPU being
    >>> unplugged is in the CPU_STATE_OFFLINE state. At that point, we know
    >>> that it either is about to call RTAS or it already has.
    >>
    >> Ah, yes this is good optimization. Though, I think we ought to
    >> unconditionally wait until the target CPU has woken up from CEDE and
    >> changed its state to CPU_STATE_OFFLINE. After if PROD failed, then we
    >> would have caught it in dlpar_offline_cpu() itself.
    >
    > I recently saw a QEMU-implemented hcall (H_LOGICAL_CI_LOAD) return
    > success when it had been given an invalid memory address to load from,
    > so my confidence in the error reporting of hcalls is a bit shaken. :-)
    >
    > In that case the CPU would wait forever for the CPU state to change. If
    > you believe 100 ms is too short a timeout, we could make it 500 ms or
    > even 1s. What do you think?
    >
    >> cpu 112 (hwid 112) Ready to die...
    >> [DEBUG] Waited for CPU 112 to enter rtas: tries=0, time=65
    >> cpu 113 (hwid 113) Ready to die...
    >> [DEBUG] Waited for CPU 113 to enter rtas: tries=0, time=1139
    >> cpu 114 (hwid 114) Ready to die...
    >> [DEBUG] Waited for CPU 114 to enter rtas: tries=0, time=1036
    >> cpu 115 (hwid 115) Ready to die...
    >> [DEBUG] Waited for CPU 115 to enter rtas: tries=0, time=133
    >> cpu 116 (hwid 116) Ready to die...
    >> [DEBUG] Waited for CPU 116 to enter rtas: tries=0, time=1231
    >> cpu 117 (hwid 117) Ready to die...
    >> [DEBUG] Waited for CPU 117 to enter rtas: tries=0, time=1231
    >> cpu 118 (hwid 118) Ready to die...
    >> [DEBUG] Waited for CPU 118 to enter rtas: tries=0, time=1231
    >> cpu 119 (hwid 119) Ready to die...
    >> [DEBUG] Waited for CPU 119 to enter rtas: tries=0, time=1131
    >> cpu 104 (hwid 104) Ready to die...
    >> [DEBUG] Waited for CPU 104 to enter rtas: tries=0, time=40
    >
    > Interesting, so 1.2 ms can pass before the dying CPU actually gets close
    > to making the stop-self call. And even in those cases the retry loop is
    > succeeding on the first try! So this shows that changing the code to
    > wait for the CPU_STATE_OFFLINE state is worth it.
    >
    >> ******* RTAS CALL BUFFER CORRUPTION *******
    >> 393: rtas32_call_buff_ptr=
    >> 0000 0060 0000 0060 0000 0060 0000 0060 [...`...`...`...`]
    >> 0000 0060 0000 0060 0000 0060 0000 0060 [...`...`...`...`]
    >> 0000 0060 0000 0060 0000 0060 0000 0060 [...`...`...`...`]
    >> 0000 0060 0800 E07F ACA7 0000 0000 00C0 [...`............]
    >> 2500 0000 0000 0000 0000 0000 0000 0000 [%...............]
    >> 0000 0000 0000 0000 0000 0000 306E 7572 [............0nur]
    >> 4800 0008 .... .... .... .... .... .... [H...........0nur]
    >> 394: rtas64_map_buff_ptr=
    >> 0000 0000 5046 5743 0000 0000 4F44 4500 [....PFWC....ODE.]
    >> 0000 0000 6000 0000 0000 0000 0000 0069 [....`..........i]
    >> 0000 0000 0000 0000 0000 0000 0000 0000 [................]
    >> 0000 0000 0000 0005 0000 0000 0000 0001 [................]
    >> 0000 0000 1A00 0000 0000 0000 0000 0000 [................]
    >> 0000 0000 8018 6398 0000 0000 0300 00C0 [......c.........]
    >> 0000 0000 .... .... .... .... .... .... [......c.........]
    >
    > Ah! I never saw this error message. So indeed the kernel is causing RTAS
    > to blow up. Perhaps it would be useful to instrument more RTAS calls
    > (especially start-cpu and set-power-level) to see if it's one of them
    > that is being called at the time this corruption happens.
    >
    >> cpu 105 (hwid 105) Ready to die...
    >> Bad kernel stack pointer 1fafb6c0 at 0
    >> Oops: Bad kernel stack pointer, sig: 6 [#1]
    >> LE SMP NR_CPUS=2048 NUMA pSeries
    >> Modules linked in:
    >> CPU: 105 PID: 0 Comm: swapper/105 Not tainted 4.20.0-rc5-thiago+ #45
    >> NIP: 0000000000000000 LR: 0000000000000000 CTR: 00000000007829c8
    >> REGS: c00000001e63bd30 TRAP: 0700 Not tainted (4.20.0-rc5-thiago+)
    >> MSR: 8000000000081000 <SF,ME> CR: 28000004 XER: 00000010
    >> CFAR: 000000001ec153f0 IRQMASK: 8000000000009033
    >> GPR00: 0000000000000000 000000001fafb6c0 000000001ec236a0 0000000000000040
    >> GPR04: 00000000000000c0 0000000000000080 00046c4fb4842557 00000000000000cd
    >> GPR08: 000000000001f400 000000001ed035dc 0000000000000000 0000000000000000
    >> GPR12: 0000000000000000 c00000001eb5e480 c0000003a1b53f90 000000001eea3e20
    >> GPR16: 0000000000000000 c0000006fd845100 c00000000004c8b0 c0000000013d5300
    >> GPR20: c0000006fd845300 0000000000000008 c0000000019d2cf8 c0000000013d6888
    >> GPR24: 0000000000000069 c0000000013d688c 0000000000000002 c0000000013d688c
    >> GPR28: c0000000019cecf0 0000000000000348 0000000000000000 0000000000000000
    >> NIP [0000000000000000] (null)
    >> LR [0000000000000000] (null)
    >> Call Trace:
    >> Instruction dump:
    >> XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
    >> XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX 60000000 60000000 60000000 60000000
    >> ---[ end trace 1aa3b4936949457e ]---
    >
    > Ok, so at about the time CPU 105 makes the stop-self call there is this
    > RTAS call buffer corruption and this bad kernel stack pointer in CPU 105.
    > We need to understand better what is causing this.
    >
    >> Bad kernel stack pointer 1fafb4b0 at 1ec15004
    >> rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
    >> rcu: 88-...!: (0 ticks this GP) idle=2ce/1/0x4000000000000000 softirq=28076/28076 fqs=78
    >> rcu: (detected by 72, t=10866 jiffies, g=180529, q=2526)
    >> Sending NMI from CPU 72 to CPUs 88:
    >> CPU 88 didn't respond to backtrace IPI, inspecting paca.
    >> irq_soft_mask: 0x01 in_mce: 0 in_nmi: 0 current: 22978 (drmgr)
    >> Back trace of paca->saved_r1 (0xc0000006f94ab750) (possibly stale):
    >> Call Trace:
    >> [c0000006f94ab750] [c0000006f94ab790] 0xc0000006f94ab790 (unreliable)
    >> [c0000006f94ab930] [c0000000000373f8] va_rtas_call_unlocked+0xc8/0xe0
    >> [c0000006f94ab950] [c000000000037a98] rtas_call+0x98/0x200
    >> [c0000006f94ab9a0] [c0000000000d7d28] smp_query_cpu_stopped+0x58/0xe0
    >> [c0000006f94aba20] [c0000000000d9dbc] pseries_cpu_die+0x1ec/0x240
    >> [c0000006f94abad0] [c00000000004f284] __cpu_die+0x44/0x60
    >> [c0000006f94abaf0] [c0000000000d8e10] dlpar_cpu_remove+0x160/0x340
    >> [c0000006f94abbc0] [c0000000000d9184] dlpar_cpu_release+0x74/0x100
    >> [c0000006f94abc10] [c000000000025a74] arch_cpu_release+0x44/0x70
    >> [c0000006f94abc30] [c0000000009bd1bc] cpu_release_store+0x4c/0x80
    >> [c0000006f94abc60] [c0000000009ae000] dev_attr_store+0x40/0x70
    >> [c0000006f94abc80] [c000000000495810] sysfs_kf_write+0x70/0xb0
    >> [c0000006f94abca0] [c00000000049453c] kernfs_fop_write+0x17c/0x250
    >> [c0000006f94abcf0] [c0000000003ccb6c] __vfs_write+0x4c/0x1f0
    >> [c0000006f94abd80] [c0000000003ccf74] vfs_write+0xd4/0x240
    >> [c0000006f94abdd0] [c0000000003cd338] ksys_write+0x68/0x110
    >> [c0000006f94abe20] [c00000000000b288] system_call+0x5c/0x70
    >
    > So CPU 88 is the one driving the hot unplug and waiting for CPU 105 to
    > die. But it is stuck inside RTAS. Perhaps because of the call buffer
    > corruption?
    >
    >> rcu: rcu_sched kthread starved for 10709 jiffies! g180529 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=72
    >> rcu: RCU grace-period kthread stack dump:
    >> rcu_sched I 0 11 2 0x00000808
    >> Call Trace:
    >> [c0000000061ab840] [c0000003a4a84800] 0xc0000003a4a84800 (unreliable)
    >> [c0000000061aba20] [c00000000001e24c] __switch_to+0x2dc/0x430
    >> [c0000000061aba80] [c000000000e5fb94] __schedule+0x3d4/0xa20
    >> [c0000000061abb50] [c000000000e6022c] schedule+0x4c/0xc0
    >> [c0000000061abb80] [c000000000e64ffc] schedule_timeout+0x1dc/0x4e0
    >> [c0000000061abc80] [c0000000001af40c] rcu_gp_kthread+0xc3c/0x11f0
    >> [c0000000061abdb0] [c00000000013c7c8] kthread+0x168/0x1b0
    >> [c0000000061abe20] [c00000000000b658] ret_from_kernel_thread+0x5c/0x64
    >
    > I don't know what to make of CPU 72. :-) Perhaps it's the one making
    > the other "rogue" RTAS call interfering with stop-self in CPU 105?
    >
    > It must be some RTAS call made with rtas_call_unlocked, because CPU 88
    > is holding the RTAS lock.
    >
    > -- Thiago Jung Bauermann
    > IBM Linux Technology Center
    >

    --
    Michael W. Bringmann
    Linux Technology Center
    IBM Corporation
    Tie-Line 363-5196
    External: (512) 286-5196
    Cell: (512) 466-0650
    mwb@linux.vnet.ibm.com

    \
     
     \ /
      Last update: 2018-12-10 21:16    [W:6.785 / U:0.020 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site