On Mon, Apr 05, 2021 at 09:37:40AM +0200, Juergen Gross wrote:
> On 02.04.21 18:11, Paul E. McKenney wrote:
> > On Fri, Apr 02, 2021 at 05:46:52PM +0200, Juergen Gross wrote:
> > > On 30.03.21 19:33, Paul E. McKenney wrote:
> > > > On Wed, Mar 24, 2021 at 11:18:03AM +0100, Jürgen Groß wrote:
> > > > > On 02.03.21 07:28, Juergen Gross wrote:
> > > > > > In order to help identifying problems with IPI handling and remote
> > > > > > function execution add some more data to IPI debugging code.
> > > > > >
> > > > > > There have been multiple reports of cpus looping long times (many
> > > > > > seconds) in smp_call_function_many() waiting for another cpu
> > > > > > executing
> > > > > > a function like tlb flushing. Most of these reports have been for
> > > > > > cases where the kernel was running as a guest on top of KVM or Xen
> > > > > > (there are rumours of that happening under VMWare, too, and even on
> > > > > > bare metal).
> > > > > >
> > > > > > Finding the root cause hasn't been successful yet, even after more
> > > > > > than
> > > > > > 2 years of chasing this bug by different developers.
> > > > > >
> > > > > > Commit 35feb60474bf4f7 ("kernel/smp: Provide CSD lock timeout
> > > > > > diagnostics") tried to address this by adding some debug code and by
> > > > > > issuing another IPI when a hang was detected. This helped mitigating
> > > > > > the problem (the repeated IPI unlocks the hang), but the root cause
> > > > > > is
> > > > > > still unknown.
> > > > > >
> > > > > > Current available data suggests that either an IPI wasn't sent when
> > > > > > it
> > > > > > should have been, or that the IPI didn't result in the target cpu
> > > > > > executing the queued function (due to the IPI not reaching the cpu,
> > > > > > the IPI handler not being called, or the handler not seeing the
> > > > > > queued
> > > > > > request).
> > > > > >
> > > > > > Try to add more diagnostic data by introducing a global atomic
> > > > > > counter
> > > > > > which is being incremented when doing critical operations (before
> > > > > > and
> > > > > > after queueing a new request, when sending an IPI, and when
> > > > > > dequeueing
> > > > > > a request). The counter value is stored in percpu variables which
> > > > > > can
> > > > > > be printed out when a hang is detected.
> > > > > >
> > > > > > The data of the last event (consisting of sequence counter, source
> > > > > > cpu, target cpu, and event type) is stored in a global variable.
> > > > > > When
> > > > > > a new event is to be traced, the data of the last event is stored in
> > > > > > the event related percpu location and the global data is updated
> > > > > > with
> > > > > > the new event's data. This allows to track two events in one data
> > > > > > location: one by the value of the event data (the event before the
> > > > > > current one), and one by the location itself (the current event).
> > > > > >
> > > > > > A typical printout with a detected hang will look like this:
> > > > > >
> > > > > > csd: Detected non-responsive CSD lock (#1) on CPU#1, waiting
> > > > > > 5000000003 ns for CPU#06 scf_handler_1+0x0/0x50(0xffffa2a881bb1410).
> > > > > > csd: CSD lock (#1) handling prior
> > > > > > scf_handler_1+0x0/0x50(0xffffa2a8813823c0) request.
> > > > > > csd: cnt(00008cc): ffff->0000 dequeue (src cpu 0 ==
> > > > > > empty)
> > > > > > csd: cnt(00008cd): ffff->0006 idle
> > > > > > csd: cnt(0003668): 0001->0006 queue
> > > > > > csd: cnt(0003669): 0001->0006 ipi
> > > > > > csd: cnt(0003e0f): 0007->000a queue
> > > > > > csd: cnt(0003e10): 0001->ffff ping
> > > > > > csd: cnt(0003e71): 0003->0000 ping
> > > > > > csd: cnt(0003e72): ffff->0006 gotipi
> > > > > > csd: cnt(0003e73): ffff->0006 handle
> > > > > > csd: cnt(0003e74): ffff->0006 dequeue (src cpu 0 ==
> > > > > > empty)
> > > > > > csd: cnt(0003e7f): 0004->0006 ping
> > > > > > csd: cnt(0003e80): 0001->ffff pinged
> > > > > > csd: cnt(0003eb2): 0005->0001 noipi
> > > > > > csd: cnt(0003eb3): 0001->0006 queue
> > > > > > csd: cnt(0003eb4): 0001->0006 noipi
> > > > > > csd: cnt now: 0003f00
> > > > > >
> > > > > > This example (being an artificial one, produced with a previous
> > > > > > version
> > > > > > of this patch without the "hdlend" event), shows that cpu#6 started
> > > > > > to
> > > > > > handle an IPI (cnt 3e72-3e74), bit didn't start to handle another
> > > > > > IPI
> > > > > > (sent by cpu#4, cnt 3e7f). The next request from cpu#1 for cpu#6 was
> > > > > > queued (3eb3), but no IPI was needed (cnt 3eb4, there was the event
> > > > > > from cpu#4 in the queue already).
> > > > > >
> > > > > > The idea is to print only relevant entries. Those are all events
> > > > > > which
> > > > > > are associated with the hang (so sender side events for the source
> > > > > > cpu
> > > > > > of the hanging request, and receiver side events for the target
> > > > > > cpu),
> > > > > > and the related events just before those (for adding data needed to
> > > > > > identify a possible race). Printing all available data would be
> > > > > > possible, but this would add large amounts of data printed on larger
> > > > > > configurations.
> > > > > >
> > > > > > Signed-off-by: Juergen Gross <jgr...@suse.com>
> > > > > > Tested-by: Paul E. McKenney <paul...@kernel.org>
> > > > >
> > > > > Just an update regarding current status with debugging the underlying
> > > > > issue:
> > > > >
> > > > > On a customer's machine with a backport of this patch applied we've
> > > > > seen another case of the hang. In the logs we've found:
> > > > >
> > > > > smp: csd: Detected non-responsive CSD lock (#1) on CPU#18, waiting
> > > > > 5000000046 ns for CPU#06 do_flush_tlb_all+0x0/0x30( (null)).
> > > > > smp: csd: CSD lock (#1) unresponsive.
> > > > > smp: csd: cnt(0000000): 0000->0000 queue
> > > > > smp: csd: cnt(0000001): ffff->0006 idle
> > > > > smp: csd: cnt(0025dba): 0012->0006 queue
> > > > > smp: csd: cnt(0025dbb): 0012->0006 noipi
> > > > > smp: csd: cnt(01d1333): 001a->0006 pinged
> > > > > smp: csd: cnt(01d1334): ffff->0006 gotipi
> > > > > smp: csd: cnt(01d1335): ffff->0006 handle
> > > > > smp: csd: cnt(01d1336): ffff->0006 dequeue (src cpu 0 == empty)
> > > > > smp: csd: cnt(01d1337): ffff->0006 hdlend (src cpu 0 == early)
> > > > > smp: csd: cnt(01d16cb): 0012->0005 ipi
> > > > > smp: csd: cnt(01d16cc): 0012->0006 queue
> > > > > smp: csd: cnt(01d16cd): 0012->0006 ipi
> > > > > smp: csd: cnt(01d16f3): 0012->001a ipi
> > > > > smp: csd: cnt(01d16f4): 0012->ffff ping
> > > > > smp: csd: cnt(01d1750): ffff->0018 hdlend (src cpu 0 == early)
> > > > > smp: csd: cnt(01d1751): 0012->ffff pinged
> > > > > smp: csd: cnt now: 01d1769
> > > > >
> > > > > So we see that cpu#18 (0012 hex) is waiting for cpu#06 (first line of
> > > > > the
> > > > > data).
> > > > >
> > > > > The next 4 lines of the csd actions are not really interesting, as
> > > > > they are
> > > > > rather old.
> > > > >
> > > > > Then we see that cpu 0006 did handle a request rather recently (cnt
> > > > > 01d1333
> > > > > - 01d1337): cpu 001a pinged it via an IPI and it got the IPI, entered
> > > > > the
> > > > > handler, dequeued a request, and handled it.
> > > > >
> > > > > Nearly all of the rest shows the critical request: cpu 0012 did a
> > > > > loop over
> > > > > probably all other cpus and queued the requests and marked them to be
> > > > > IPI-ed
> > > > > (including cpu 0006, cnt 01d16cd). Then the cpus marked to receive an
> > > > > IPI
> > > > > were pinged (cnt 01d16f4 and cnt 01d1751).
> > > > >
> > > > > The entry cnt 01d1750 is not of interest here.
> > > > >
> > > > > This data confirms that on sending side everything seems to be okay
> > > > > at the
> > > > > level above the actual IPI sending. On receiver side there seems no
> > > > > IPI to
> > > > > be seen, but there is no visible reason for a race either.
> > > > >
> > > > > It seems as if we need more debugging in the deeper layers: is the IPI
> > > > > really sent out, and is something being received on the destination
> > > > > cpu?
> > > > > I'll have another try with even more debugging code, probably in
> > > > > private
> > > > > on the customer machine first.
> > > >
> > > > Apologies for the late reply, was out last week.
> > > >
> > > > Excellent news, and thank you!
> > > >
> > > > For my part, I have put together a rough prototype script that allows
> > > > me to run scftorture on larger groups of systems and started running it,
> > > > though I am hoping that 1,000 is far more than will be required.
> > > >
> > > > Your diagnosis of a lost IPI matches what we have been able to glean
> > > > from the occasional occurrences in the wild on our systems, for whatever
> > > > that might be worth. The hope is to get something that reproduces more
> > > > quickly, which would allow deeper debugging at this end as well.
> > >
> > > Sometimes one is lucky.
> > >
> > > I've found a reproducer while hunting another bug. The test on that
> > > machine will trigger the csd_lock timeout about once a day.
> >
> > Nice!!! You are way ahead of me!
> >
> > > I've used my new debug kernel and found that the IPI is really sent
> > > out (more precise: the hypervisor has been requested to do so, and
> > > it didn't report an error). On the target cpu there was no interrupt
> > > received after that, so the IPI has not been swallowed on the target
> > > cpu by the Linux kernel.
> > >
> > > Will now try to instrument the hypervisor to get more data.
> >
> > I am increasing the number and types of systems and the test duration.
> > Ijust started running three different systems with IPI workloads in both
> > guests and within host over the weekend.
>
> Maybe you can try my kind of workload:
>
> I have a guest with 16 vcpus and 8 GB of memory running 8 instances of
>
> sysbench --test=fileio --file-test-mode=rndrw --rand-seed=0 --max-time=300
> --max-requests=0 run
>
> on disjunct nfs mounts. Those have been created with:
>
> mount -t nfs -o
> rw,proto=tcp,nolock,nfsvers=3,rsize=65536,wsize=65536,nosharetransport
> server:/share[1-8] /mount[1-8]
>
> with the server running on the host system of the guest and the shares
> located in a ramdisk.
>
> The host has 72 cpus and 48 GB of RAM.
>
> A csd lock timeout happens about once per day on the host.
Thank you! I will give it a try. It has been quite some time since I
have done anything with NFS, so it should be entertaining. ;-)
Thanx, Paul
