RCU lockup issues when CONFIG_SOFTLOCKUP_DETECTOR=n - any one else seeing this?
Jonathan Cameron
Jonathan.Cameron at huawei.com
Fri Jul 28 00:44:11 PDT 2017
On Thu, 27 Jul 2017 09:52:45 -0700
"Paul E. McKenney" <paulmck at linux.vnet.ibm.com> wrote:
> On Thu, Jul 27, 2017 at 05:39:23PM +0100, Jonathan Cameron wrote:
> > On Thu, 27 Jul 2017 14:49:03 +0100
> > Jonathan Cameron <Jonathan.Cameron at huawei.com> wrote:
> >
> > > On Thu, 27 Jul 2017 05:49:13 -0700
> > > "Paul E. McKenney" <paulmck at linux.vnet.ibm.com> wrote:
> > >
> > > > On Thu, Jul 27, 2017 at 02:34:00PM +1000, Nicholas Piggin wrote:
> > > > > On Wed, 26 Jul 2017 18:42:14 -0700
> > > > > "Paul E. McKenney" <paulmck at linux.vnet.ibm.com> wrote:
> > > > >
> > > > > > On Wed, Jul 26, 2017 at 04:22:00PM -0700, David Miller wrote:
> > > > >
> > > > > > > Indeed, that really wouldn't explain how we end up with a RCU stall
> > > > > > > dump listing almost all of the cpus as having missed a grace period.
> > > > > >
> > > > > > I have seen stranger things, but admittedly not often.
> > > > >
> > > > > So the backtraces show the RCU gp thread in schedule_timeout.
> > > > >
> > > > > Are you sure that it's timeout has expired and it's not being scheduled,
> > > > > or could it be a bad (large) timeout (looks unlikely) or that it's being
> > > > > scheduled but not correctly noting gps on other CPUs?
> > > > >
> > > > > It's not in R state, so if it's not being scheduled at all, then it's
> > > > > because the timer has not fired:
> > > >
> > > > Good point, Nick!
> > > >
> > > > Jonathan, could you please reproduce collecting timer event tracing?
> > > I'm a little new to tracing (only started playing with it last week)
> > > so fingers crossed I've set it up right. No splats yet. Was getting
> > > splats on reading out the trace when running with the RCU stall timer
> > > set to 4 so have increased that back to the default and am rerunning.
> > >
> > > This may take a while. Correct me if I've gotten this wrong to save time
> > >
> > > echo "timer:*" > /sys/kernel/debug/tracing/set_event
> > >
> > > when it dumps, just send you the relevant part of what is in
> > > /sys/kernel/debug/tracing/trace?
> >
> > Interestingly the only thing that can make trip for me with tracing on
> > is peaking in the tracing buffers. Not sure this is a valid case or
> > not.
> >
> > Anyhow all timer activity seems to stop around the area of interest.
> >
> >
> > [ 9442.413624] INFO: rcu_sched detected stalls on CPUs/tasks:
> > [ 9442.419107] 1-...: (1 GPs behind) idle=844/0/0 softirq=27747/27755 fqs=0 last_accelerate: dd6a/de80, nonlazy_posted: 0, L.
> > [ 9442.430224] 3-...: (2 GPs behind) idle=8f8/0/0 softirq=32197/32198 fqs=0 last_accelerate: 29b1/de80, nonlazy_posted: 0, L.
> > [ 9442.441340] 4-...: (7 GPs behind) idle=740/0/0 softirq=22351/22352 fqs=0 last_accelerate: ca88/de80, nonlazy_posted: 0, L.
> > [ 9442.452456] 5-...: (2 GPs behind) idle=9b0/0/0 softirq=21315/21319 fqs=0 last_accelerate: b280/de88, nonlazy_posted: 0, L.
> > [ 9442.463572] 6-...: (2 GPs behind) idle=794/0/0 softirq=19699/19707 fqs=0 last_accelerate: ba62/de88, nonlazy_posted: 0, L.
> > [ 9442.474688] 7-...: (2 GPs behind) idle=ac4/0/0 softirq=22547/22554 fqs=0 last_accelerate: b280/de88, nonlazy_posted: 0, L.
> > [ 9442.485803] 8-...: (9 GPs behind) idle=118/0/0 softirq=281/291 fqs=0 last_accelerate: c3fe/de88, nonlazy_posted: 0, L.
> > [ 9442.496571] 9-...: (9 GPs behind) idle=8fc/0/0 softirq=284/292 fqs=0 last_accelerate: 6030/de88, nonlazy_posted: 0, L.
> > [ 9442.507339] 10-...: (14 GPs behind) idle=f78/0/0 softirq=254/254 fqs=0 last_accelerate: 5487/de88, nonlazy_posted: 0, L.
> > [ 9442.518281] 11-...: (9 GPs behind) idle=c9c/0/0 softirq=301/308 fqs=0 last_accelerate: 3d3e/de99, nonlazy_posted: 0, L.
> > [ 9442.529136] 12-...: (9 GPs behind) idle=4a4/0/0 softirq=735/737 fqs=0 last_accelerate: 6010/de99, nonlazy_posted: 0, L.
> > [ 9442.539992] 13-...: (9 GPs behind) idle=34c/0/0 softirq=1121/1131 fqs=0 last_accelerate: b280/de99, nonlazy_posted: 0, L.
> > [ 9442.551020] 14-...: (9 GPs behind) idle=2f4/0/0 softirq=707/713 fqs=0 last_accelerate: 6030/de99, nonlazy_posted: 0, L.
> > [ 9442.561875] 15-...: (2 GPs behind) idle=b30/0/0 softirq=821/976 fqs=0 last_accelerate: c208/de99, nonlazy_posted: 0, L.
> > [ 9442.572730] 17-...: (2 GPs behind) idle=5a8/0/0 softirq=1456/1565 fqs=0 last_accelerate: ca88/de99, nonlazy_posted: 0, L.
> > [ 9442.583759] 18-...: (2 GPs behind) idle=2e4/0/0 softirq=1923/1936 fqs=0 last_accelerate: ca88/dea7, nonlazy_posted: 0, L.
> > [ 9442.594787] 19-...: (2 GPs behind) idle=138/0/0 softirq=1421/1432 fqs=0 last_accelerate: b280/dea7, nonlazy_posted: 0, L.
> > [ 9442.605816] 20-...: (50 GPs behind) idle=634/0/0 softirq=217/219 fqs=0 last_accelerate: c96f/dea7, nonlazy_posted: 0, L.
> > [ 9442.616758] 21-...: (2 GPs behind) idle=eb8/0/0 softirq=1368/1369 fqs=0 last_accelerate: b599/deb2, nonlazy_posted: 0, L.
> > [ 9442.627786] 22-...: (1 GPs behind) idle=aa8/0/0 softirq=229/232 fqs=0 last_accelerate: c604/deb2, nonlazy_posted: 0, L.
> > [ 9442.638641] 23-...: (1 GPs behind) idle=488/0/0 softirq=247/248 fqs=0 last_accelerate: c600/deb2, nonlazy_posted: 0, L.
> > [ 9442.649496] 24-...: (33 GPs behind) idle=f7c/0/0 softirq=319/319 fqs=0 last_accelerate: 5290/deb2, nonlazy_posted: 0, L.
> > [ 9442.660437] 25-...: (33 GPs behind) idle=944/0/0 softirq=308/308 fqs=0 last_accelerate: 52c0/deb2, nonlazy_posted: 0, L.
> > [ 9442.671379] 26-...: (9 GPs behind) idle=6d4/0/0 softirq=265/275 fqs=0 last_accelerate: 6034/dec0, nonlazy_posted: 0, L.
> > [ 9442.682234] 27-...: (115 GPs behind) idle=e3c/0/0 softirq=212/226 fqs=0 last_accelerate: 5420/dec0, nonlazy_posted: 0, L.
> > [ 9442.693263] 28-...: (9 GPs behind) idle=ea4/0/0 softirq=540/552 fqs=0 last_accelerate: 603c/dec0, nonlazy_posted: 0, L.
> > [ 9442.704118] 29-...: (115 GPs behind) idle=83c/0/0 softirq=342/380 fqs=0 last_accelerate: 5420/dec0, nonlazy_posted: 0, L.
> > [ 9442.715147] 30-...: (33 GPs behind) idle=e3c/0/0 softirq=509/509 fqs=0 last_accelerate: 52bc/dec0, nonlazy_posted: 0, L.
> > [ 9442.726088] 31-...: (9 GPs behind) idle=df4/0/0 softirq=619/641 fqs=0 last_accelerate: 603c/decb, nonlazy_posted: 0, L.
> > [ 9442.736944] 32-...: (9 GPs behind) idle=aa4/0/0 softirq=1841/1848 fqs=0 last_accelerate: 6030/decb, nonlazy_posted: 0, L.
> > [ 9442.747972] 34-...: (9 GPs behind) idle=e6c/0/0 softirq=5082/5086 fqs=0 last_accelerate: 6039/decb, nonlazy_posted: 0, L.
> > [ 9442.759001] 35-...: (9 GPs behind) idle=7fc/0/0 softirq=1396/1406 fqs=0 last_accelerate: 603e/decb, nonlazy_posted: 0, L.
> > [ 9442.770030] 36-...: (0 ticks this GP) idle=f28/0/0 softirq=255/255 fqs=0 last_accelerate: c9fc/decb, nonlazy_posted: 0, L.
> > [ 9442.781145] 37-...: (50 GPs behind) idle=53c/0/0 softirq=227/230 fqs=0 last_accelerate: 45c0/decb, nonlazy_posted: 0, L.
> > [ 9442.792087] 38-...: (9 GPs behind) idle=958/0/0 softirq=185/192 fqs=0 last_accelerate: 6030/decb, nonlazy_posted: 0, L.
> > [ 9442.802942] 40-...: (389 GPs behind) idle=41c/0/0 softirq=131/136 fqs=0 last_accelerate: 5800/decb, nonlazy_posted: 0, L.
> > [ 9442.813971] 41-...: (389 GPs behind) idle=258/0/0 softirq=133/138 fqs=0 last_accelerate: c00f/decb, nonlazy_posted: 0, L.
> > [ 9442.825000] 43-...: (50 GPs behind) idle=254/0/0 softirq=113/117 fqs=0 last_accelerate: 5420/dee5, nonlazy_posted: 0, L.
> > [ 9442.835942] 44-...: (115 GPs behind) idle=178/0/0 softirq=1271/1276 fqs=0 last_accelerate: 68e9/dee5, nonlazy_posted: 0, L.
> > [ 9442.847144] 45-...: (2 GPs behind) idle=04a/1/0 softirq=364/389 fqs=0 last_accelerate: dee5/dee5, nonlazy_posted: 0, L.
> > [ 9442.857999] 46-...: (9 GPs behind) idle=ec4/0/0 softirq=183/189 fqs=0 last_accelerate: 6030/dee5, nonlazy_posted: 0, L.
> > [ 9442.868854] 47-...: (115 GPs behind) idle=088/0/0 softirq=135/149 fqs=0 last_accelerate: 5420/dee5, nonlazy_posted: 0, L.
> > [ 9442.879883] 48-...: (389 GPs behind) idle=200/0/0 softirq=103/110 fqs=0 last_accelerate: 58b0/dee5, nonlazy_posted: 0, L.
> > [ 9442.890911] 49-...: (9 GPs behind) idle=a24/0/0 softirq=205/211 fqs=0 last_accelerate: 6030/dee5, nonlazy_posted: 0, L.
> > [ 9442.901766] 50-...: (25 GPs behind) idle=a74/0/0 softirq=144/144 fqs=0 last_accelerate: 5420/dee5, nonlazy_posted: 0, L.
> > [ 9442.912708] 51-...: (50 GPs behind) idle=f68/0/0 softirq=116/122 fqs=0 last_accelerate: 57bc/dee5, nonlazy_posted: 0, L.
> > [ 9442.923650] 52-...: (9 GPs behind) idle=e08/0/0 softirq=202/486 fqs=0 last_accelerate: c87f/defe, nonlazy_posted: 0, L.
> > [ 9442.934505] 53-...: (2 GPs behind) idle=128/0/0 softirq=365/366 fqs=0 last_accelerate: ca88/defe, nonlazy_posted: 0, L.
> > [ 9442.945360] 54-...: (9 GPs behind) idle=ce8/0/0 softirq=126/373 fqs=0 last_accelerate: bef8/defe, nonlazy_posted: 0, L.
> > [ 9442.956215] 56-...: (9 GPs behind) idle=330/0/0 softirq=2116/2126 fqs=0 last_accelerate: 6030/defe, nonlazy_posted: 0, L.
> > [ 9442.967243] 57-...: (1 GPs behind) idle=288/0/0 softirq=1707/1714 fqs=0 last_accelerate: c87c/defe, nonlazy_posted: 0, L.
> > [ 9442.978272] 58-...: (37 GPs behind) idle=390/0/0 softirq=1716/1721 fqs=0 last_accelerate: 53f7/defe, nonlazy_posted: 0, L.
> > [ 9442.989387] 59-...: (37 GPs behind) idle=e54/0/0 softirq=1700/1701 fqs=0 last_accelerate: 40a1/defe, nonlazy_posted: 0, L.
> > [ 9443.000502] 60-...: (116 GPs behind) idle=7b4/0/0 softirq=92/96 fqs=0 last_accelerate: 57d8/df10, nonlazy_posted: 0, L.
> > [ 9443.011357] 61-...: (9 GPs behind) idle=9d8/0/0 softirq=161/170 fqs=0 last_accelerate: 6030/df10, nonlazy_posted: 0, L.
> > [ 9443.022212] 62-...: (115 GPs behind) idle=aa8/0/0 softirq=95/101 fqs=0 last_accelerate: 5420/df17, nonlazy_posted: 0, L.
> > [ 9443.033154] 63-...: (50 GPs behind) idle=958/0/0 softirq=81/84 fqs=0 last_accelerate: 57b8/df17, nonlazy_posted: 0, L.
> > [ 9443.043920] (detected by 39, t=5403 jiffies, g=443, c=442, q=1)
> > [ 9443.049919] Task dump for CPU 1:
> > [ 9443.053134] swapper/1 R running task 0 0 1 0x00000000
> > [ 9443.060173] Call trace:
> > [ 9443.062619] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.067744] [< (null)>] (null)
> > [ 9443.072434] Task dump for CPU 3:
> > [ 9443.075650] swapper/3 R running task 0 0 1 0x00000000
> > [ 9443.082686] Call trace:
> > [ 9443.085121] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.090246] [< (null)>] (null)
> > [ 9443.094936] Task dump for CPU 4:
> > [ 9443.098152] swapper/4 R running task 0 0 1 0x00000000
> > [ 9443.105188] Call trace:
> > [ 9443.107623] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.112752] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.118224] Task dump for CPU 5:
> > [ 9443.121440] swapper/5 R running task 0 0 1 0x00000000
> > [ 9443.128476] Call trace:
> > [ 9443.130910] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.136035] [< (null)>] (null)
> > [ 9443.140725] Task dump for CPU 6:
> > [ 9443.143941] swapper/6 R running task 0 0 1 0x00000000
> > [ 9443.150976] Call trace:
> > [ 9443.153411] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.158535] [< (null)>] (null)
> > [ 9443.163226] Task dump for CPU 7:
> > [ 9443.166442] swapper/7 R running task 0 0 1 0x00000000
> > [ 9443.173478] Call trace:
> > [ 9443.175912] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.181037] [< (null)>] (null)
> > [ 9443.185727] Task dump for CPU 8:
> > [ 9443.188943] swapper/8 R running task 0 0 1 0x00000000
> > [ 9443.195979] Call trace:
> > [ 9443.198412] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.203537] [< (null)>] (null)
> > [ 9443.208227] Task dump for CPU 9:
> > [ 9443.211443] swapper/9 R running task 0 0 1 0x00000000
> > [ 9443.218479] Call trace:
> > [ 9443.220913] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.226039] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.231510] Task dump for CPU 10:
> > [ 9443.234812] swapper/10 R running task 0 0 1 0x00000000
> > [ 9443.241848] Call trace:
> > [ 9443.244283] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.249408] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.254879] Task dump for CPU 11:
> > [ 9443.258182] swapper/11 R running task 0 0 1 0x00000000
> > [ 9443.265218] Call trace:
> > [ 9443.267652] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.272776] [< (null)>] (null)
> > [ 9443.277467] Task dump for CPU 12:
> > [ 9443.280769] swapper/12 R running task 0 0 1 0x00000000
> > [ 9443.287806] Call trace:
> > [ 9443.290240] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.295364] [< (null)>] (null)
> > [ 9443.300054] Task dump for CPU 13:
> > [ 9443.303357] swapper/13 R running task 0 0 1 0x00000000
> > [ 9443.310394] Call trace:
> > [ 9443.312828] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.317953] [< (null)>] (null)
> > [ 9443.322643] Task dump for CPU 14:
> > [ 9443.325945] swapper/14 R running task 0 0 1 0x00000000
> > [ 9443.332981] Call trace:
> > [ 9443.335416] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.340540] [< (null)>] (null)
> > [ 9443.345230] Task dump for CPU 15:
> > [ 9443.348533] swapper/15 R running task 0 0 1 0x00000000
> > [ 9443.355568] Call trace:
> > [ 9443.358002] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.363128] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.368599] Task dump for CPU 17:
> > [ 9443.371901] swapper/17 R running task 0 0 1 0x00000000
> > [ 9443.378937] Call trace:
> > [ 9443.381372] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.386497] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.391968] Task dump for CPU 18:
> > [ 9443.395270] swapper/18 R running task 0 0 1 0x00000000
> > [ 9443.402306] Call trace:
> > [ 9443.404740] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.409865] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.415336] Task dump for CPU 19:
> > [ 9443.418639] swapper/19 R running task 0 0 1 0x00000000
> > [ 9443.425675] Call trace:
> > [ 9443.428109] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.433234] [< (null)>] (null)
> > [ 9443.437924] Task dump for CPU 20:
> > [ 9443.441226] swapper/20 R running task 0 0 1 0x00000000
> > [ 9443.448263] Call trace:
> > [ 9443.450697] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.455826] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9443.462600] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9443.467986] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.473458] Task dump for CPU 21:
> > [ 9443.476760] swapper/21 R running task 0 0 1 0x00000000
> > [ 9443.483796] Call trace:
> > [ 9443.486230] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.491354] [< (null)>] (null)
> > [ 9443.496045] Task dump for CPU 22:
> > [ 9443.499347] swapper/22 R running task 0 0 1 0x00000000
> > [ 9443.506383] Call trace:
> > [ 9443.508817] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.513943] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.519414] Task dump for CPU 23:
> > [ 9443.522716] swapper/23 R running task 0 0 1 0x00000000
> > [ 9443.529752] Call trace:
> > [ 9443.532186] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.537312] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.542784] Task dump for CPU 24:
> > [ 9443.546086] swapper/24 R running task 0 0 1 0x00000000
> > [ 9443.553122] Call trace:
> > [ 9443.555556] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.560681] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.566153] Task dump for CPU 25:
> > [ 9443.569455] swapper/25 R running task 0 0 1 0x00000000
> > [ 9443.576491] Call trace:
> > [ 9443.578925] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.584051] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9443.590825] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9443.596211] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.601682] Task dump for CPU 26:
> > [ 9443.604985] swapper/26 R running task 0 0 1 0x00000000
> > [ 9443.612021] Call trace:
> > [ 9443.614455] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.619581] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.625052] Task dump for CPU 27:
> > [ 9443.628355] swapper/27 R running task 0 0 1 0x00000000
> > [ 9443.635390] Call trace:
> > [ 9443.637824] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.642949] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.648421] Task dump for CPU 28:
> > [ 9443.651723] swapper/28 R running task 0 0 1 0x00000000
> > [ 9443.658759] Call trace:
> > [ 9443.661193] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.666318] [< (null)>] (null)
> > [ 9443.671008] Task dump for CPU 29:
> > [ 9443.674310] swapper/29 R running task 0 0 1 0x00000000
> > [ 9443.681346] Call trace:
> > [ 9443.683780] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.688905] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.694377] Task dump for CPU 30:
> > [ 9443.697679] swapper/30 R running task 0 0 1 0x00000000
> > [ 9443.704715] Call trace:
> > [ 9443.707150] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.712275] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9443.719050] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9443.724436] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.729907] Task dump for CPU 31:
> > [ 9443.733210] swapper/31 R running task 0 0 1 0x00000000
> > [ 9443.740246] Call trace:
> > [ 9443.742680] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.747805] [< (null)>] (null)
> > [ 9443.752496] Task dump for CPU 32:
> > [ 9443.755798] swapper/32 R running task 0 0 1 0x00000000
> > [ 9443.762833] Call trace:
> > [ 9443.765267] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.770392] [< (null)>] (null)
> > [ 9443.775082] Task dump for CPU 34:
> > [ 9443.778384] swapper/34 R running task 0 0 1 0x00000000
> > [ 9443.785420] Call trace:
> > [ 9443.787854] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.792980] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.798451] Task dump for CPU 35:
> > [ 9443.801753] swapper/35 R running task 0 0 1 0x00000000
> > [ 9443.808789] Call trace:
> > [ 9443.811224] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.816348] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.821820] Task dump for CPU 36:
> > [ 9443.825122] swapper/36 R running task 0 0 1 0x00000000
> > [ 9443.832158] Call trace:
> > [ 9443.834592] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.839718] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9443.846493] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9443.851878] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.857350] Task dump for CPU 37:
> > [ 9443.860652] swapper/37 R running task 0 0 1 0x00000000
> > [ 9443.867688] Call trace:
> > [ 9443.870122] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.875248] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9443.882022] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9443.887408] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.892880] Task dump for CPU 38:
> > [ 9443.896182] swapper/38 R running task 0 0 1 0x00000000
> > [ 9443.903218] Call trace:
> > [ 9443.905652] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.910776] [< (null)>] (null)
> > [ 9443.915466] Task dump for CPU 40:
> > [ 9443.918769] swapper/40 R running task 0 0 1 0x00000000
> > [ 9443.925805] Call trace:
> > [ 9443.928239] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.933365] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.938836] Task dump for CPU 41:
> > [ 9443.942138] swapper/41 R running task 0 0 1 0x00000000
> > [ 9443.949174] Call trace:
> > [ 9443.951609] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.956733] [< (null)>] (null)
> > [ 9443.961423] Task dump for CPU 43:
> > [ 9443.964725] swapper/43 R running task 0 0 1 0x00000000
> > [ 9443.971761] Call trace:
> > [ 9443.974195] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9443.979320] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9443.984791] Task dump for CPU 44:
> > [ 9443.988093] swapper/44 R running task 0 0 1 0x00000000
> > [ 9443.995130] Call trace:
> > [ 9443.997564] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.002688] [< (null)>] (null)
> > [ 9444.007378] Task dump for CPU 45:
> > [ 9444.010680] swapper/45 R running task 0 0 1 0x00000000
> > [ 9444.017716] Call trace:
> > [ 9444.020151] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.025275] [< (null)>] (null)
> > [ 9444.029965] Task dump for CPU 46:
> > [ 9444.033267] swapper/46 R running task 0 0 1 0x00000000
> > [ 9444.040302] Call trace:
> > [ 9444.042737] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.047862] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.053333] Task dump for CPU 47:
> > [ 9444.056636] swapper/47 R running task 0 0 1 0x00000000
> > [ 9444.063672] Call trace:
> > [ 9444.066106] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.071231] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.076702] Task dump for CPU 48:
> > [ 9444.080004] swapper/48 R running task 0 0 1 0x00000000
> > [ 9444.087041] Call trace:
> > [ 9444.089475] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.094600] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.100071] Task dump for CPU 49:
> > [ 9444.103374] swapper/49 R running task 0 0 1 0x00000000
> > [ 9444.110409] Call trace:
> > [ 9444.112844] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.117968] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.123440] Task dump for CPU 50:
> > [ 9444.126742] swapper/50 R running task 0 0 1 0x00000000
> > [ 9444.133777] Call trace:
> > [ 9444.136211] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.141336] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.146807] Task dump for CPU 51:
> > [ 9444.150109] swapper/51 R running task 0 0 1 0x00000000
> > [ 9444.157144] Call trace:
> > [ 9444.159578] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.164703] [< (null)>] (null)
> > [ 9444.169393] Task dump for CPU 52:
> > [ 9444.172695] swapper/52 R running task 0 0 1 0x00000000
> > [ 9444.179731] Call trace:
> > [ 9444.182165] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.187290] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.192761] Task dump for CPU 53:
> > [ 9444.196063] swapper/53 R running task 0 0 1 0x00000000
> > [ 9444.203099] Call trace:
> > [ 9444.205533] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.210658] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.216129] Task dump for CPU 54:
> > [ 9444.219431] swapper/54 R running task 0 0 1 0x00000000
> > [ 9444.226467] Call trace:
> > [ 9444.228901] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.234026] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.239498] Task dump for CPU 56:
> > [ 9444.242801] swapper/56 R running task 0 0 1 0x00000000
> > [ 9444.249837] Call trace:
> > [ 9444.252271] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.257396] [< (null)>] (null)
> > [ 9444.262086] Task dump for CPU 57:
> > [ 9444.265388] swapper/57 R running task 0 0 1 0x00000000
> > [ 9444.272424] Call trace:
> > [ 9444.274858] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.279982] [< (null)>] (null)
> > [ 9444.284672] Task dump for CPU 58:
> > [ 9444.287975] swapper/58 R running task 0 0 1 0x00000000
> > [ 9444.295011] Call trace:
> > [ 9444.297445] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.302570] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9444.309345] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9444.314731] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.320202] Task dump for CPU 59:
> > [ 9444.323504] swapper/59 R running task 0 0 1 0x00000000
> > [ 9444.330540] Call trace:
> > [ 9444.332974] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.338100] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.343571] Task dump for CPU 60:
> > [ 9444.346873] swapper/60 R running task 0 0 1 0x00000000
> > [ 9444.353909] Call trace:
> > [ 9444.356343] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.361469] [<ffff00000813cf78>] rcu_eqs_enter_common.isra.32+0x1b8/0x228
> > [ 9444.368243] [<ffff00000813d044>] rcu_idle_enter+0x5c/0x60
> > [ 9444.373629] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.379101] Task dump for CPU 61:
> > [ 9444.382402] swapper/61 R running task 0 0 1 0x00000000
> > [ 9444.389438] Call trace:
> > [ 9444.391872] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.396997] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.402469] Task dump for CPU 62:
> > [ 9444.405771] swapper/62 R running task 0 0 1 0x00000000
> > [ 9444.412808] Call trace:
> > [ 9444.415242] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.420367] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.425838] Task dump for CPU 63:
> > [ 9444.429141] swapper/63 R running task 0 0 1 0x00000000
> > [ 9444.436177] Call trace:
> > [ 9444.438611] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.443736] [<ffff0000090d9df0>] __cpu_online_mask+0x0/0x8
> > [ 9444.449211] rcu_sched kthread starved for 5743 jiffies! g443 c442 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
> > [ 9444.458416] rcu_sched S 0 10 2 0x00000000
> > [ 9444.463889] Call trace:
> > [ 9444.466324] [<ffff000008085cb8>] __switch_to+0x90/0xa8
> > [ 9444.471453] [<ffff000008ab70a4>] __schedule+0x1a4/0x720
> > [ 9444.476665] [<ffff000008ab7660>] schedule+0x40/0xa8
> > [ 9444.481530] [<ffff000008abac70>] schedule_timeout+0x178/0x358
> > [ 9444.487263] [<ffff00000813e694>] rcu_gp_kthread+0x534/0x7b8
> > [ 9444.492824] [<ffff0000080f33d0>] kthread+0x108/0x138
> > [ 9444.497775] [<ffff0000080836c0>] ret_from_fork+0x10/0x50
> >
> >
> >
> > And the relevant chunk of trace is:
> > (I have a lot more. There are substantial other pauses from to time, but not this long)
> >
> >
> > rcu_preempt-9 [057] .... 9419.837631: timer_init: timer=ffff8017d5fcfda0
> > rcu_preempt-9 [057] d..1 9419.837632: timer_start: timer=ffff8017d5fcfda0 function=process_timeout expires=4297246837 [timeout=1] cpu=57 idx=0 flags=
> > <idle>-0 [057] d..1 9419.837634: tick_stop: success=1 dependency=NONE
> > <idle>-0 [057] d..2 9419.837634: hrtimer_cancel: hrtimer=ffff8017db99e808
> > <idle>-0 [057] d..2 9419.837635: hrtimer_start: hrtimer=ffff8017db99e808 function=tick_sched_timer expires=9418164000000 softexpires=9418164000000
> > <idle>-0 [057] d.h2 9419.845621: hrtimer_cancel: hrtimer=ffff8017db99e808
> > <idle>-0 [057] d.h1 9419.845621: hrtimer_expire_entry: hrtimer=ffff8017db99e808 function=tick_sched_timer now=9418164001440
> > <idle>-0 [057] d.h1 9419.845622: hrtimer_expire_exit: hrtimer=ffff8017db99e808
> > <idle>-0 [057] d.s2 9419.845623: timer_cancel: timer=ffff8017d5fcfda0
> > <idle>-0 [057] ..s1 9419.845623: timer_expire_entry: timer=ffff8017d5fcfda0 function=process_timeout now=4297246838
> > <idle>-0 [057] .ns1 9419.845624: timer_expire_exit: timer=ffff8017d5fcfda0
> > <idle>-0 [057] dn.2 9419.845628: hrtimer_start: hrtimer=ffff8017db99e808 function=tick_sched_timer expires=9418168000000 softexpires=9418168000000
> > <idle>-0 [057] d..1 9419.845635: tick_stop: success=1 dependency=NONE
> > <idle>-0 [057] d..2 9419.845636: hrtimer_cancel: hrtimer=ffff8017db99e808
> > <idle>-0 [057] d..2 9419.845636: hrtimer_start: hrtimer=ffff8017db99e808 function=tick_sched_timer expires=9418188000000 softexpires=9418188000000
> > <idle>-0 [057] d.h2 9419.869621: hrtimer_cancel: hrtimer=ffff8017db99e808
> > <idle>-0 [057] d.h1 9419.869621: hrtimer_expire_entry: hrtimer=ffff8017db99e808 function=tick_sched_timer now=9418188001420
> > <idle>-0 [057] d.h1 9419.869622: hrtimer_expire_exit: hrtimer=ffff8017db99e808
> > <idle>-0 [057] d..2 9419.869626: hrtimer_start: hrtimer=ffff8017db99e808 function=tick_sched_timer expires=9858983202655 softexpires=9858983202655
> > <idle>-0 [016] d.h2 9419.885626: hrtimer_cancel: hrtimer=ffff8017fbc3d808
> > <idle>-0 [016] d.h1 9419.885627: hrtimer_expire_entry: hrtimer=ffff8017fbc3d808 function=tick_sched_timer now=9418204006760
> > <idle>-0 [016] d.h1 9419.885629: hrtimer_expire_exit: hrtimer=ffff8017fbc3d808
> > <idle>-0 [016] d.s2 9419.885629: timer_cancel: timer=ffff8017d37dbca0
> > <idle>-0 [016] ..s1 9419.885630: timer_expire_entry: timer=ffff8017d37dbca0 function=process_timeout now=4297246848
> > <idle>-0 [016] .ns1 9419.885631: timer_expire_exit: timer=ffff8017d37dbca0
> > <idle>-0 [016] dn.2 9419.885636: hrtimer_start: hrtimer=ffff8017fbc3d808 function=tick_sched_timer expires=9418208000000 softexpires=9418208000000
> > khugepaged-778 [016] .... 9419.885668: timer_init: timer=ffff8017d37dbca0
> > khugepaged-778 [016] d..1 9419.885668: timer_start: timer=ffff8017d37dbca0 function=process_timeout expires=4297249348 [timeout=2500] cpu=16 idx=0 flags=
> > <idle>-0 [016] d..1 9419.885670: tick_stop: success=1 dependency=NONE
> > <idle>-0 [016] d..2 9419.885671: hrtimer_cancel: hrtimer=ffff8017fbc3d808
> > <idle>-0 [016] d..2 9419.885671: hrtimer_start: hrtimer=ffff8017fbc3d808 function=tick_sched_timer expires=9428444000000 softexpires=9428444000000
> > <idle>-0 [045] d.h2 9419.890839: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9419.890839: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418209219940
> > <idle>-0 [045] d.h3 9419.890844: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418310221420 softexpires=9418309221420
> > <idle>-0 [045] d.h1 9419.890844: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [000] d.h2 9419.917625: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.h1 9419.917626: hrtimer_expire_entry: hrtimer=ffff8017fbe40808 function=tick_sched_timer now=9418236005860
> > <idle>-0 [000] d.h1 9419.917628: hrtimer_expire_exit: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.s2 9419.917628: timer_cancel: timer=ffff80177fdc0840
> > <idle>-0 [000] ..s1 9419.917629: timer_expire_entry: timer=ffff80177fdc0840 function=link_timeout_disable_link now=4297246856
> > <idle>-0 [000] d.s2 9419.917630: timer_start: timer=ffff80177fdc0840 function=link_timeout_enable_link expires=4297246881 [timeout=25] cpu=0 idx=81 flags=
> > <idle>-0 [000] ..s1 9419.917633: timer_expire_exit: timer=ffff80177fdc0840
> > <idle>-0 [000] d..2 9419.917648: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9418340000000 softexpires=9418340000000
> > <idle>-0 [045] d.h2 9419.991845: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9419.991845: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418310225960
> > <idle>-0 [045] d.h3 9419.991849: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418411227320 softexpires=9418410227320
> > <idle>-0 [045] d.h1 9419.991850: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [000] d.h2 9420.021625: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.h1 9420.021625: hrtimer_expire_entry: hrtimer=ffff8017fbe40808 function=tick_sched_timer now=9418340005520
> > <idle>-0 [000] d.h1 9420.021627: hrtimer_expire_exit: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.s2 9420.021627: timer_cancel: timer=ffff80177fdc0840
> > <idle>-0 [000] ..s1 9420.021628: timer_expire_entry: timer=ffff80177fdc0840 function=link_timeout_enable_link now=4297246882
> > <idle>-0 [000] d.s2 9420.021629: timer_start: timer=ffff80177fdc0840 function=link_timeout_disable_link expires=4297247107 [timeout=225] cpu=0 idx=34 flags=
> > <idle>-0 [000] ..s1 9420.021632: timer_expire_exit: timer=ffff80177fdc0840
> > <idle>-0 [000] d..2 9420.021639: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419260000000 softexpires=9419260000000
> > <idle>-0 [045] d.h2 9420.092851: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.092852: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418411231780
> > <idle>-0 [045] d.h3 9420.092856: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418512233720 softexpires=9418511233720
> > <idle>-0 [045] d.h1 9420.092856: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [055] d.h2 9420.141622: hrtimer_cancel: hrtimer=ffff8017db968808
> > <idle>-0 [055] d.h1 9420.141623: hrtimer_expire_entry: hrtimer=ffff8017db968808 function=tick_sched_timer now=9418460002540
> > <idle>-0 [055] d.h1 9420.141625: hrtimer_expire_exit: hrtimer=ffff8017db968808
> > <idle>-0 [055] d.s2 9420.141626: timer_cancel: timer=ffff80177db6cc08
> > <idle>-0 [055] d.s1 9420.141626: timer_expire_entry: timer=ffff80177db6cc08 function=delayed_work_timer_fn now=4297246912
> > <idle>-0 [055] dns1 9420.141628: timer_expire_exit: timer=ffff80177db6cc08
> > <idle>-0 [055] dn.2 9420.141632: hrtimer_start: hrtimer=ffff8017db968808 function=tick_sched_timer expires=9418464000000 softexpires=9418464000000
> > kworker/55:1-1246 [055] d..1 9420.141634: timer_start: timer=ffff80177db6cc08 function=delayed_work_timer_fn expires=4297247162 [timeout=250] cpu=55 idx=88 flags=I
> > <idle>-0 [055] d..1 9420.141637: tick_stop: success=1 dependency=NONE
> > <idle>-0 [055] d..2 9420.141637: hrtimer_cancel: hrtimer=ffff8017db968808
> > <idle>-0 [055] d..2 9420.141637: hrtimer_start: hrtimer=ffff8017db968808 function=tick_sched_timer expires=9419484000000 softexpires=9419484000000
> > <idle>-0 [045] d.h2 9420.193855: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.193855: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418512235660
> > <idle>-0 [045] d.h3 9420.193859: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418613237260 softexpires=9418612237260
> > <idle>-0 [045] d.h1 9420.193860: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9420.294858: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.294858: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418613238380
> > <idle>-0 [045] d.h3 9420.294862: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418714240000 softexpires=9418713240000
> > <idle>-0 [045] d.h1 9420.294863: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9420.395861: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.395861: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418714241380
> > <idle>-0 [045] d.h3 9420.395865: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418815242920 softexpires=9418814242920
> > <idle>-0 [045] d.h1 9420.395865: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [042] d.h2 9420.461621: hrtimer_cancel: hrtimer=ffff8017dbb69808
> > <idle>-0 [042] d.h1 9420.461622: hrtimer_expire_entry: hrtimer=ffff8017dbb69808 function=tick_sched_timer now=9418780002180
> > <idle>-0 [042] d.h1 9420.461623: hrtimer_expire_exit: hrtimer=ffff8017dbb69808
> > <idle>-0 [042] d.s2 9420.461624: timer_cancel: timer=ffff80177db6d408
> > <idle>-0 [042] d.s1 9420.461625: timer_expire_entry: timer=ffff80177db6d408 function=delayed_work_timer_fn now=4297246992
> > <idle>-0 [042] dns1 9420.461627: timer_expire_exit: timer=ffff80177db6d408
> > <idle>-0 [042] dns2 9420.461627: timer_cancel: timer=ffff8017797d7868
> > <idle>-0 [042] .ns1 9420.461628: timer_expire_entry: timer=ffff8017797d7868 function=hns_nic_service_timer now=4297246992
> > <idle>-0 [042] dns2 9420.461628: timer_start: timer=ffff8017797d7868 function=hns_nic_service_timer expires=4297247242 [timeout=250] cpu=42 idx=98 flags=
> > <idle>-0 [042] .ns1 9420.461629: timer_expire_exit: timer=ffff8017797d7868
> > <idle>-0 [042] dn.2 9420.461632: hrtimer_start: hrtimer=ffff8017dbb69808 function=tick_sched_timer expires=9418784000000 softexpires=9418784000000
> > kworker/42:1-1223 [042] d..1 9420.461773: timer_start: timer=ffff80177db6d408 function=delayed_work_timer_fn expires=4297247242 [timeout=250] cpu=42 idx=98 flags=I
> > <idle>-0 [042] d..1 9420.461866: tick_stop: success=1 dependency=NONE
> > <idle>-0 [042] d..2 9420.461867: hrtimer_cancel: hrtimer=ffff8017dbb69808
> > <idle>-0 [042] d..2 9420.461867: hrtimer_start: hrtimer=ffff8017dbb69808 function=tick_sched_timer expires=9419804000000 softexpires=9419804000000
> > <idle>-0 [045] d.h2 9420.496864: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.496864: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418815244580
> > <idle>-0 [045] d.h3 9420.496868: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9418916246140 softexpires=9418915246140
> > <idle>-0 [045] d.h1 9420.496868: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9420.597866: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.597867: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9418916247280
> > <idle>-0 [045] d.h3 9420.597871: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419017248760 softexpires=9419016248760
> > <idle>-0 [045] d.h1 9420.597871: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [033] d.h2 9420.621621: hrtimer_cancel: hrtimer=ffff8017dba76808
> > <idle>-0 [033] d.h1 9420.621622: hrtimer_expire_entry: hrtimer=ffff8017dba76808 function=tick_sched_timer now=9418940002160
> > <idle>-0 [033] d.h1 9420.621623: hrtimer_expire_exit: hrtimer=ffff8017dba76808
> > <idle>-0 [033] d.s2 9420.621624: timer_cancel: timer=ffff00000917be40
> > <idle>-0 [033] d.s1 9420.621625: timer_expire_entry: timer=ffff00000917be40 function=delayed_work_timer_fn now=4297247032
> > <idle>-0 [033] dns1 9420.621626: timer_expire_exit: timer=ffff00000917be40
> > <idle>-0 [033] dn.2 9420.621630: hrtimer_start: hrtimer=ffff8017dba76808 function=tick_sched_timer expires=9418944000000 softexpires=9418944000000
> > <...>-1631 [033] d..1 9420.621636: timer_start: timer=ffff00000917be40 function=delayed_work_timer_fn expires=4297247282 [timeout=250] cpu=33 idx=103 flags=I
> > <idle>-0 [033] d..1 9420.621639: tick_stop: success=1 dependency=NONE
> > <idle>-0 [033] d..2 9420.621639: hrtimer_cancel: hrtimer=ffff8017dba76808
> > <idle>-0 [033] d..2 9420.621639: hrtimer_start: hrtimer=ffff8017dba76808 function=tick_sched_timer expires=9419964000000 softexpires=9419964000000
> > <idle>-0 [000] dn.2 9420.691401: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] dn.2 9420.691401: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419012000000 softexpires=9419012000000
> > <idle>-0 [002] dn.2 9420.691408: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] dn.2 9420.691408: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419012000000 softexpires=9419012000000
> > <idle>-0 [000] d..1 9420.691409: tick_stop: success=1 dependency=NONE
> > <idle>-0 [000] d..2 9420.691409: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d..2 9420.691409: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419260000000 softexpires=9419260000000
> > <idle>-0 [002] d..1 9420.691423: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9420.691423: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9420.691424: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9859803202655 softexpires=9859803202655
> > <idle>-0 [045] d.h2 9420.698872: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.698873: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419017253180
> > <idle>-0 [045] d.h3 9420.698877: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419118254640 softexpires=9419117254640
> > <idle>-0 [045] d.h1 9420.698877: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9420.799875: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.799875: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419118255760
> > <idle>-0 [045] d.h3 9420.799879: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419219257140 softexpires=9419218257140
> > <idle>-0 [045] d.h1 9420.799880: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [000] dn.2 9420.871369: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] dn.2 9420.871370: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419192000000 softexpires=9419192000000
> > <idle>-0 [002] dn.2 9420.871375: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [000] d..1 9420.871376: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] dn.2 9420.871376: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419192000000 softexpires=9419192000000
> > <idle>-0 [000] d..2 9420.871376: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d..2 9420.871376: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419260000000 softexpires=9419260000000
> > <idle>-0 [002] d..1 9420.871398: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9420.871398: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9420.871398: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9859983202655 softexpires=9859983202655
> > <idle>-0 [045] d.h2 9420.900881: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9420.900881: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419219261580
> > <idle>-0 [045] d.h3 9420.900885: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419320263160 softexpires=9419319263160
> > <idle>-0 [045] d.h1 9420.900886: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [001] d..2 9420.913601: hrtimer_cancel: hrtimer=ffff8017fbe5b808
> > <idle>-0 [001] d..2 9420.913601: hrtimer_start: hrtimer=ffff8017fbe5b808 function=tick_sched_timer expires=9860023202655 softexpires=9860023202655
> > <idle>-0 [000] d.h2 9420.941621: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.h1 9420.941621: hrtimer_expire_entry: hrtimer=ffff8017fbe40808 function=tick_sched_timer now=9419260001400
> > <idle>-0 [000] d.h1 9420.941623: hrtimer_expire_exit: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.s2 9420.941623: timer_cancel: timer=ffff80177fdc0840
> > <idle>-0 [000] ..s1 9420.941624: timer_expire_entry: timer=ffff80177fdc0840 function=link_timeout_disable_link now=4297247112
> > <idle>-0 [000] d.s2 9420.941624: timer_start: timer=ffff80177fdc0840 function=link_timeout_enable_link expires=4297247137 [timeout=25] cpu=0 idx=113 flags=
> > <idle>-0 [000] ..s1 9420.941628: timer_expire_exit: timer=ffff80177fdc0840
> > <idle>-0 [000] d.s2 9420.941629: timer_cancel: timer=ffff8017fbe42558
> > <idle>-0 [000] d.s1 9420.941629: timer_expire_entry: timer=ffff8017fbe42558 function=delayed_work_timer_fn now=4297247112
> > <idle>-0 [000] dns1 9420.941630: timer_expire_exit: timer=ffff8017fbe42558
> > <idle>-0 [000] dns2 9420.941631: timer_cancel: timer=ffff00000910a628
> > <idle>-0 [000] dns1 9420.941631: timer_expire_entry: timer=ffff00000910a628 function=delayed_work_timer_fn now=4297247112
> > <idle>-0 [000] dns1 9420.941631: timer_expire_exit: timer=ffff00000910a628
> > <idle>-0 [000] dn.2 9420.941634: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419264000000 softexpires=9419264000000
> > <idle>-0 [002] dn.2 9420.941643: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] dn.2 9420.941643: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419264000000 softexpires=9419264000000
> > kworker/0:0-3 [000] d..1 9420.941650: timer_start: timer=ffff00000910a628 function=delayed_work_timer_fn expires=4297247500 [timeout=388] cpu=0 idx=100 flags=D|I
> > kworker/2:0-22 [002] d..1 9420.941651: timer_start: timer=ffff8017fbe78558 function=delayed_work_timer_fn expires=4297247494 [timeout=382] cpu=2 idx=114 flags=D|I
> > <idle>-0 [000] d..1 9420.941652: tick_stop: success=1 dependency=NONE
> > <idle>-0 [000] d..2 9420.941652: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d..2 9420.941653: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419364000000 softexpires=9419364000000
> > <idle>-0 [002] d..1 9420.941654: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9420.941654: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9420.941654: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9860055202655 softexpires=9860055202655
> > <idle>-0 [045] d.h2 9421.001887: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9421.001887: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419320267640
> > <idle>-0 [045] d.h3 9421.001891: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419421269000 softexpires=9419420269000
> > <idle>-0 [045] d.h1 9421.001892: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [000] d.h2 9421.045625: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.h1 9421.045625: hrtimer_expire_entry: hrtimer=ffff8017fbe40808 function=tick_sched_timer now=9419364005380
> > <idle>-0 [000] d.h1 9421.045626: hrtimer_expire_exit: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.s2 9421.045627: timer_cancel: timer=ffff80177fdc0840
> > <idle>-0 [000] ..s1 9421.045628: timer_expire_entry: timer=ffff80177fdc0840 function=link_timeout_enable_link now=4297247138
> > <idle>-0 [000] d.s2 9421.045628: timer_start: timer=ffff80177fdc0840 function=link_timeout_disable_link expires=4297247363 [timeout=225] cpu=0 idx=34 flags=
> > <idle>-0 [000] ..s1 9421.045631: timer_expire_exit: timer=ffff80177fdc0840
> > <idle>-0 [000] d..2 9421.045644: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9420284000000 softexpires=9420284000000
> > <idle>-0 [045] d.h2 9421.102893: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9421.102893: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419421273420
> > <idle>-0 [045] d.h3 9421.102897: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419522275040 softexpires=9419521275040
> > <idle>-0 [045] d.h1 9421.102897: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [055] d.h2 9421.165621: hrtimer_cancel: hrtimer=ffff8017db968808
> > <idle>-0 [055] d.h1 9421.165622: hrtimer_expire_entry: hrtimer=ffff8017db968808 function=tick_sched_timer now=9419484002280
> > <idle>-0 [055] d.h1 9421.165624: hrtimer_expire_exit: hrtimer=ffff8017db968808
> > <idle>-0 [055] d.s2 9421.165624: timer_cancel: timer=ffff80177db6cc08
> > <idle>-0 [055] d.s1 9421.165625: timer_expire_entry: timer=ffff80177db6cc08 function=delayed_work_timer_fn now=4297247168
> > <idle>-0 [055] dns1 9421.165626: timer_expire_exit: timer=ffff80177db6cc08
> > <idle>-0 [055] dn.2 9421.165629: hrtimer_start: hrtimer=ffff8017db968808 function=tick_sched_timer expires=9419488000000 softexpires=9419488000000
> > kworker/55:1-1246 [055] d..1 9421.165632: timer_start: timer=ffff80177db6cc08 function=delayed_work_timer_fn expires=4297247418 [timeout=250] cpu=55 idx=120 flags=I
> > <idle>-0 [055] d..1 9421.165634: tick_stop: success=1 dependency=NONE
> > <idle>-0 [055] d..2 9421.165634: hrtimer_cancel: hrtimer=ffff8017db968808
> > <idle>-0 [055] d..2 9421.165635: hrtimer_start: hrtimer=ffff8017db968808 function=tick_sched_timer expires=9420508000000 softexpires=9420508000000
> > <idle>-0 [045] d.h2 9421.203896: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9421.203896: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419522276980
> > <idle>-0 [045] d.h3 9421.203900: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419623278460 softexpires=9419622278460
> > <idle>-0 [045] d.h1 9421.203901: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9421.304899: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9421.304899: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9419623279580
> > <idle>-0 [045] d.h3 9421.304903: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9419724281060 softexpires=9419723281060
> > <idle>-0 [045] d.h1 9421.304903: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [000] dn.2 9421.381179: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] dn.2 9421.381179: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9419700000000 softexpires=9419700000000
> > <idle>-0 [002] dn.2 9421.381185: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] dn.2 9421.381185: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419700000000 softexpires=9419700000000
> > <idle>-0 [000] d..1 9421.381185: tick_stop: success=1 dependency=NONE
> > <idle>-0 [000] d..2 9421.381186: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d..2 9421.381186: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9420284000000 softexpires=9420284000000
> > sh-2256 [002] .... 9421.381193: timer_init: timer=ffff80176c26fb40
> > sh-2256 [002] d..1 9421.381194: timer_start: timer=ffff80176c26fb40 function=process_timeout expires=4297247223 [timeout=2] cpu=2 idx=0 flags=
> > <idle>-0 [002] d..1 9421.381196: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9421.381197: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9421.381197: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419708000000 softexpires=9419708000000
> > <idle>-0 [002] d.h2 9421.389621: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d.h1 9421.389622: hrtimer_expire_entry: hrtimer=ffff8017fbe76808 function=tick_sched_timer now=9419708002000
> > <idle>-0 [002] d.h1 9421.389623: hrtimer_expire_exit: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d.s2 9421.389624: timer_cancel: timer=ffff80176c26fb40
> > <idle>-0 [002] ..s1 9421.389624: timer_expire_entry: timer=ffff80176c26fb40 function=process_timeout now=4297247224
> > <idle>-0 [002] .ns1 9421.389626: timer_expire_exit: timer=ffff80176c26fb40
> > <idle>-0 [002] dn.2 9421.389629: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419712000000 softexpires=9419712000000
> > sh-2256 [002] ...1 9421.389682: hrtimer_init: hrtimer=ffff8017d4dde8a0 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
> > sh-2256 [002] ...1 9421.389682: hrtimer_init: hrtimer=ffff8017d4dde8e0 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
> > sh-2256 [002] .... 9421.389690: hrtimer_init: hrtimer=ffff80176cbb0088 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
> > <idle>-0 [039] dn.2 9421.389814: hrtimer_start: hrtimer=ffff8017dbb18808 function=tick_sched_timer expires=9419712000000 softexpires=9419712000000
> > <idle>-0 [002] d..1 9421.389896: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9421.389897: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9421.389898: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9419724000000 softexpires=9419724000000
>
> This being the gap?
>
> Interesting in that I am not seeing any timeouts at all associated with
> the rcu_sched kthread...
This only happened when saving out the trace. It's didn't happen at all
on an overnight run with no interference. Which perhaps suggests the
tracing itself is changing the timing enough to hid the issue.
Oh goody.
I'm not familiar enough with the internals of event tracing to know,
but is there a reason that either clearing the buffer or outputting
it could result in this gap?
Jonathan
>
> Thanx, Paul
>
> > <idle>-0 [002] dn.2 9444.510766: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] dn.2 9444.510767: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9442832000000 softexpires=9442832000000
> > <idle>-0 [036] d..1 9444.510812: tick_stop: success=1 dependency=NONE
> > <idle>-0 [036] d..2 9444.510814: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.510815: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442844000000 softexpires=9442844000000
> > sh-2256 [002] .... 9444.510857: timer_init: timer=ffff80176c26fb40
> > sh-2256 [002] d..1 9444.510857: timer_start: timer=ffff80176c26fb40 function=process_timeout expires=4297253006 [timeout=2] cpu=2 idx=0 flags=
> > <idle>-0 [002] d..1 9444.510864: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9444.510865: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9444.510866: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9442844000000 softexpires=9442844000000
> > <idle>-0 [000] d.h2 9444.525625: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [002] d.h2 9444.525625: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [036] d.h2 9444.525625: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [002] d.h1 9444.525625: hrtimer_expire_entry: hrtimer=ffff8017fbe76808 function=tick_sched_timer now=9442844005600
> > <idle>-0 [036] d.h1 9444.525625: hrtimer_expire_entry: hrtimer=ffff8017dbac7808 function=tick_sched_timer now=9442844005460
> > <idle>-0 [000] d.h1 9444.525627: hrtimer_expire_entry: hrtimer=ffff8017fbe40808 function=tick_sched_timer now=9442844005300
> > <idle>-0 [002] d.h1 9444.525627: hrtimer_expire_exit: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d.s2 9444.525629: timer_cancel: timer=ffff8017fbe78558
> > <idle>-0 [036] d.h1 9444.525629: hrtimer_expire_exit: hrtimer=ffff8017dbac7808
> > <idle>-0 [002] d.s1 9444.525629: timer_expire_entry: timer=ffff8017fbe78558 function=delayed_work_timer_fn now=4297253008
> > <idle>-0 [000] d.h1 9444.525629: hrtimer_expire_exit: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.s2 9444.525631: timer_cancel: timer=ffff80177fdc0840
> > <idle>-0 [000] ..s1 9444.525631: timer_expire_entry: timer=ffff80177fdc0840 function=link_timeout_disable_link now=4297253008
> > <idle>-0 [002] dns1 9444.525631: timer_expire_exit: timer=ffff8017fbe78558
> > <idle>-0 [000] d.s2 9444.525632: timer_start: timer=ffff80177fdc0840 function=link_timeout_enable_link expires=4297253033 [timeout=25] cpu=0 idx=82 flags=
> > <idle>-0 [000] ..s1 9444.525633: timer_expire_exit: timer=ffff80177fdc0840
> > <idle>-0 [000] d.s2 9444.525634: timer_cancel: timer=ffff00000910a628
> > <idle>-0 [000] d.s1 9444.525634: timer_expire_entry: timer=ffff00000910a628 function=delayed_work_timer_fn now=4297253008
> > <idle>-0 [000] dns1 9444.525636: timer_expire_exit: timer=ffff00000910a628
> > <idle>-0 [036] dn.2 9444.525639: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442848000000 softexpires=9442848000000
> > <idle>-0 [000] dn.2 9444.525640: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9442848000000 softexpires=9442848000000
> > <idle>-0 [002] dn.2 9444.525640: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9442848000000 softexpires=9442848000000
> > rcu_preempt-9 [036] .... 9444.525648: timer_init: timer=ffff8017d5fcfda0
> > <idle>-0 [002] d..1 9444.525648: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9444.525648: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9444.525649: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9442860000000 softexpires=9442860000000
> > rcu_preempt-9 [036] d..1 9444.525649: timer_start: timer=ffff8017d5fcfda0 function=process_timeout expires=4297253009 [timeout=1] cpu=36 idx=0 flags=
> > kworker/0:0-3 [000] d..1 9444.525650: timer_start: timer=ffff00000910a628 function=delayed_work_timer_fn expires=4297253250 [timeout=242] cpu=0 idx=82 flags=D|I
> > <idle>-0 [000] d..1 9444.525652: tick_stop: success=1 dependency=NONE
> > <idle>-0 [000] d..2 9444.525652: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d..2 9444.525653: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9442948000000 softexpires=9442948000000
> > <idle>-0 [036] d..1 9444.525653: tick_stop: success=1 dependency=NONE
> > <idle>-0 [036] d..2 9444.525654: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.525654: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442852000000 softexpires=9442852000000
> > <idle>-0 [036] d.h2 9444.533624: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d.h1 9444.533625: hrtimer_expire_entry: hrtimer=ffff8017dbac7808 function=tick_sched_timer now=9442852004760
> > <idle>-0 [036] d.h1 9444.533626: hrtimer_expire_exit: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d.s2 9444.533627: timer_cancel: timer=ffff8017d5fcfda0
> > <idle>-0 [036] ..s1 9444.533628: timer_expire_entry: timer=ffff8017d5fcfda0 function=process_timeout now=4297253010
> > <idle>-0 [036] .ns1 9444.533629: timer_expire_exit: timer=ffff8017d5fcfda0
> > <idle>-0 [036] dn.2 9444.533634: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442856000000 softexpires=9442856000000
> > <idle>-0 [036] d..1 9444.533668: tick_stop: success=1 dependency=NONE
> > <idle>-0 [036] d..2 9444.533668: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.533669: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442876000000 softexpires=9442876000000
> > <idle>-0 [002] dnh2 9444.541626: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] dnh1 9444.541627: hrtimer_expire_entry: hrtimer=ffff8017fbe76808 function=tick_sched_timer now=9442860007120
> > <idle>-0 [002] dnh1 9444.541629: hrtimer_expire_exit: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] dn.2 9444.541630: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9442864000000 softexpires=9442864000000
> > <idle>-0 [002] d..1 9444.541640: tick_stop: success=1 dependency=NONE
> > <idle>-0 [002] d..2 9444.541640: hrtimer_cancel: hrtimer=ffff8017fbe76808
> > <idle>-0 [002] d..2 9444.541640: hrtimer_start: hrtimer=ffff8017fbe76808 function=tick_sched_timer expires=9444316000000 softexpires=9444316000000
> > <idle>-0 [036] dnh2 9444.557627: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] dnh1 9444.557628: hrtimer_expire_entry: hrtimer=ffff8017dbac7808 function=tick_sched_timer now=9442876008220
> > <idle>-0 [036] dnh1 9444.557630: hrtimer_expire_exit: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] dn.2 9444.557631: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442880000000 softexpires=9442880000000
> > <idle>-0 [036] d..1 9444.557644: tick_stop: success=1 dependency=NONE
> > <idle>-0 [036] d..2 9444.557645: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.557645: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442892000000 softexpires=9442892000000
> > <idle>-0 [036] d.h2 9444.573621: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d.h1 9444.573621: hrtimer_expire_entry: hrtimer=ffff8017dbac7808 function=tick_sched_timer now=9442892001340
> > <idle>-0 [036] d.h1 9444.573622: hrtimer_expire_exit: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] dn.2 9444.573628: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442896000000 softexpires=9442896000000
> > rcu_preempt-9 [036] .... 9444.573631: timer_init: timer=ffff8017d5fcfda0
> > rcu_preempt-9 [036] d..1 9444.573632: timer_start: timer=ffff8017d5fcfda0 function=process_timeout expires=4297253021 [timeout=1] cpu=36 idx=0 flags=
> > <idle>-0 [036] d..1 9444.573634: tick_stop: success=1 dependency=NONE
> > <idle>-0 [036] d..2 9444.573635: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.573635: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442900000000 softexpires=9442900000000
> > <idle>-0 [036] d.h2 9444.581621: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d.h1 9444.581621: hrtimer_expire_entry: hrtimer=ffff8017dbac7808 function=tick_sched_timer now=9442900001400
> > <idle>-0 [036] d.h1 9444.581622: hrtimer_expire_exit: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d.s2 9444.581623: timer_cancel: timer=ffff8017d5fcfda0
> > <idle>-0 [036] ..s1 9444.581623: timer_expire_entry: timer=ffff8017d5fcfda0 function=process_timeout now=4297253022
> > <idle>-0 [036] .ns1 9444.581625: timer_expire_exit: timer=ffff8017d5fcfda0
> > <idle>-0 [036] dn.2 9444.581628: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442904000000 softexpires=9442904000000
> > <idle>-0 [036] d..1 9444.581636: tick_stop: success=1 dependency=NONE
> > <idle>-0 [036] d..2 9444.581636: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.581637: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9442924000000 softexpires=9442924000000
> > <idle>-0 [045] d.h2 9444.581718: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9444.581719: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9442900098200
> > <idle>-0 [045] d.h3 9444.581724: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9443001101380 softexpires=9443000101380
> > <idle>-0 [045] d.h1 9444.581725: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [036] d.h2 9444.605621: hrtimer_cancel: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d.h1 9444.605621: hrtimer_expire_entry: hrtimer=ffff8017dbac7808 function=tick_sched_timer now=9442924001600
> > <idle>-0 [036] d.h1 9444.605622: hrtimer_expire_exit: hrtimer=ffff8017dbac7808
> > <idle>-0 [036] d..2 9444.605629: hrtimer_start: hrtimer=ffff8017dbac7808 function=tick_sched_timer expires=9883719202655 softexpires=9883719202655
> > <idle>-0 [000] d.h2 9444.629625: hrtimer_cancel: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.h1 9444.629625: hrtimer_expire_entry: hrtimer=ffff8017fbe40808 function=tick_sched_timer now=9442948005580
> > <idle>-0 [000] d.h1 9444.629627: hrtimer_expire_exit: hrtimer=ffff8017fbe40808
> > <idle>-0 [000] d.s2 9444.629628: timer_cancel: timer=ffff80177fdc0840
> > <idle>-0 [000] ..s1 9444.629628: timer_expire_entry: timer=ffff80177fdc0840 function=link_timeout_enable_link now=4297253034
> > <idle>-0 [000] d.s2 9444.629629: timer_start: timer=ffff80177fdc0840 function=link_timeout_disable_link expires=4297253259 [timeout=225] cpu=0 idx=42 flags=
> > <idle>-0 [000] ..s1 9444.629638: timer_expire_exit: timer=ffff80177fdc0840
> > <idle>-0 [000] d..2 9444.629661: hrtimer_start: hrtimer=ffff8017fbe40808 function=tick_sched_timer expires=9443868000000 softexpires=9443868000000
> > <idle>-0 [045] d.h2 9444.682725: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9444.682725: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9443001105940
> > <idle>-0 [045] d.h3 9444.682730: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9443102107440 softexpires=9443101107440
> > <idle>-0 [045] d.h1 9444.682730: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [055] d.h2 9444.717626: hrtimer_cancel: hrtimer=ffff8017db968808
> > <idle>-0 [055] d.h1 9444.717627: hrtimer_expire_entry: hrtimer=ffff8017db968808 function=tick_sched_timer now=9443036006240
> > <idle>-0 [055] d.h1 9444.717629: hrtimer_expire_exit: hrtimer=ffff8017db968808
> > <idle>-0 [055] d.s2 9444.717630: timer_cancel: timer=ffff80177db6cc08
> > <idle>-0 [055] d.s1 9444.717630: timer_expire_entry: timer=ffff80177db6cc08 function=delayed_work_timer_fn now=4297253056
> > <idle>-0 [055] dns1 9444.717633: timer_expire_exit: timer=ffff80177db6cc08
> > <idle>-0 [055] dn.2 9444.717637: hrtimer_start: hrtimer=ffff8017db968808 function=tick_sched_timer expires=9443040000000 softexpires=9443040000000
> > kworker/55:1-1246 [055] d..1 9444.717640: timer_start: timer=ffff80177db6cc08 function=delayed_work_timer_fn expires=4297253306 [timeout=250] cpu=55 idx=88 flags=I
> > <idle>-0 [055] d..1 9444.717643: tick_stop: success=1 dependency=NONE
> > <idle>-0 [055] d..2 9444.717643: hrtimer_cancel: hrtimer=ffff8017db968808
> > <idle>-0 [055] d..2 9444.717644: hrtimer_start: hrtimer=ffff8017db968808 function=tick_sched_timer expires=9444060000000 softexpires=9444060000000
> > <idle>-0 [045] d.h2 9444.783729: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9444.783729: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9443102109380
> > <idle>-0 [045] d.h3 9444.783733: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9443203110880 softexpires=9443202110880
> > <idle>-0 [045] d.h1 9444.783733: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9444.884731: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9444.884731: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9443203112000
> > <idle>-0 [045] d.h3 9444.884735: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9443304113380 softexpires=9443303113380
> > <idle>-0 [045] d.h1 9444.884736: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h2 9444.985734: hrtimer_cancel: hrtimer=ffff80176cb7ca90
> > <idle>-0 [045] d.h1 9444.985735: hrtimer_expire_entry: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func now=9443304114500
> > <idle>-0 [045] d.h3 9444.985738: hrtimer_start: hrtimer=ffff80176cb7ca90 function=ehci_hrtimer_func expires=9443405116440 softexpires=9443404116440
> > <idle>-0 [045] d.h1 9444.985739: hrtimer_expire_exit: hrtimer=ffff80176cb7ca90
> > <idle>-0 [042] d.h2 9445.037622: hrtimer_cancel: hrtimer=ffff8017dbb69808
> > >
> > > Thanks,
> > >
> > > Jonathan
> > > >
> > > > Thanx, Paul
> > > >
> > > > > [ 1984.628602] rcu_preempt kthread starved for 5663 jiffies! g1566 c1565 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
> > > > > [ 1984.638153] rcu_preempt S 0 9 2 0x00000000
> > > > > [ 1984.643626] Call trace:
> > > > > [ 1984.646059] [<ffff000008084fb0>] __switch_to+0x90/0xa8
> > > > > [ 1984.651189] [<ffff000008962274>] __schedule+0x19c/0x5d8
> > > > > [ 1984.656400] [<ffff0000089626e8>] schedule+0x38/0xa0
> > > > > [ 1984.661266] [<ffff000008965844>] schedule_timeout+0x124/0x218
> > > > > [ 1984.667002] [<ffff000008121424>] rcu_gp_kthread+0x4fc/0x748
> > > > > [ 1984.672564] [<ffff0000080df0b4>] kthread+0xfc/0x128
> > > > > [ 1984.677429] [<ffff000008082ec0>] ret_from_fork+0x10/0x50
> > > > >
> > > >
> > >
> > > _______________________________________________
> > > linuxarm mailing list
> > > linuxarm at huawei.com
> > > http://rnd-openeuler.huawei.com/mailman/listinfo/linuxarm
> >
>
More information about the linux-arm-kernel
mailing list