RCU lockup issues when CONFIG_SOFTLOCKUP_DETECTOR=n - any one else seeing this?
Jonathan Cameron
Jonathan.Cameron at huawei.com
Tue Jul 25 04:32:10 PDT 2017
Hi All,
We observed a regression on our d05 boards (but curiously not
the fairly similar but single socket / smaller core count
d03), initially seen with linux-next prior to the merge window
and still present in v4.13-rc2.
The symptom is:
[ 1982.959365] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 1982.965021] 2-...: (10 GPs behind) idle=1d4/0/0 softirq=306/306 fqs=0
[ 1982.971624] 3-...: (2 GPs behind) idle=700/0/0 softirq=307/307 fqs=0
[ 1982.978139] 4-...: (20 GPs behind) idle=9f4/0/0 softirq=651/652 fqs=0
[ 1982.984740] 5-...: (18 GPs behind) idle=a78/0/0 softirq=369/371 fqs=0
[ 1982.991342] 6-...: (26 GPs behind) idle=e5c/0/0 softirq=217/219 fqs=0
[ 1982.997944] 7-...: (1438 GPs behind) idle=eb4/0/0 softirq=260/260 fqs=0
[ 1983.004719] 8-...: (18 GPs behind) idle=830/0/0 softirq=1609/1609 fqs=0
[ 1983.011494] 9-...: (18 GPs behind) idle=e9c/0/0 softirq=242/242 fqs=0
[ 1983.018095] 10-...: (1434 GPs behind) idle=ca0/0/0 softirq=210/212 fqs=0
[ 1983.024957] 11-...: (1106 GPs behind) idle=ee0/0/0 softirq=188/191 fqs=0
[ 1983.031819] 12-...: (1636 GPs behind) idle=c58/0/0 softirq=215/216 fqs=0
[ 1983.038680] 13-...: (1114 GPs behind) idle=c20/0/0 softirq=170/170 fqs=0
[ 1983.045542] 14-...: (1106 GPs behind) idle=d90/0/0 softirq=176/178 fqs=0
[ 1983.052403] 15-...: (1858 GPs behind) idle=900/0/0 softirq=184/185 fqs=0
[ 1983.059266] 16-...: (1621 GPs behind) idle=f04/0/0 softirq=204/206 fqs=0
[ 1983.066127] 17-...: (1433 GPs behind) idle=d30/0/0 softirq=202/202 fqs=0
[ 1983.072988] 18-...: (18 GPs behind) idle=2d4/0/0 softirq=218/220 fqs=0
[ 1983.079676] 19-...: (19 GPs behind) idle=bbc/0/0 softirq=178/180 fqs=0
[ 1983.086364] 20-...: (0 ticks this GP) idle=ee0/0/0 softirq=231/231 fqs=0
[ 1983.093226] 21-...: (4 GPs behind) idle=140/0/0 softirq=208/208 fqs=0
[ 1983.099827] 22-...: (5 GPs behind) idle=100/0/0 softirq=186/188 fqs=0
[ 1983.106428] 23-...: (1635 GPs behind) idle=fd4/0/0 softirq=1220/1221 fqs=0
[ 1983.113463] 24-...: (1112 GPs behind) idle=ca8/0/0 softirq=231/233 fqs=0
[ 1983.120325] 25-...: (1637 GPs behind) idle=9c4/0/0 softirq=164/166 fqs=0
[ 1983.127187] 27-...: (0 ticks this GP) idle=b08/0/0 softirq=182/182 fqs=0
[ 1983.134048] 28-...: (1110 GPs behind) idle=d28/0/0 softirq=179/181 fqs=0
[ 1983.140909] 29-...: (8 GPs behind) idle=1dc/0/0 softirq=196/198 fqs=0
[ 1983.147511] 31-...: (1434 GPs behind) idle=74c/0/0 softirq=160/161 fqs=0
[ 1983.154373] 32-...: (1432 GPs behind) idle=7d4/0/0 softirq=164/164 fqs=0
[ 1983.161234] 33-...: (1632 GPs behind) idle=4dc/0/0 softirq=130/132 fqs=0
[ 1983.168096] 34-...: (57 GPs behind) idle=3b0/0/0 softirq=411/411 fqs=0
[ 1983.174784] 35-...: (1599 GPs behind) idle=8a0/0/0 softirq=177/179 fqs=0
[ 1983.181646] 36-...: (1603 GPs behind) idle=520/0/0 softirq=132/134 fqs=0
[ 1983.188507] 37-...: (8 GPs behind) idle=02c/0/0 softirq=176/178 fqs=0
[ 1983.195108] 38-...: (1442 GPs behind) idle=d8c/0/0 softirq=3189/3190 fqs=0
[ 1983.202144] 39-...: (1431 GPs behind) idle=444/0/0 softirq=117/117 fqs=0
[ 1983.209005] 40-...: (4 GPs behind) idle=688/0/0 softirq=134/136 fqs=0
[ 1983.215606] 41-...: (1599 GPs behind) idle=554/0/0 softirq=2707/2711 fqs=0
[ 1983.222642] 42-...: (1430 GPs behind) idle=15c/0/0 softirq=110/111 fqs=0
[ 1983.229503] 43-...: (4 GPs behind) idle=054/0/0 softirq=101/103 fqs=0
[ 1983.236104] 46-...: (1117 GPs behind) idle=558/0/0 softirq=251/253 fqs=0
[ 1983.242966] 47-...: (1118 GPs behind) idle=5f0/0/0 softirq=110/112 fqs=0
[ 1983.249827] 48-...: (1621 GPs behind) idle=ef4/0/0 softirq=241/242 fqs=0
[ 1983.256689] 49-...: (1648 GPs behind) idle=92c/0/0 softirq=207/208 fqs=0
[ 1983.263550] 52-...: (1439 GPs behind) idle=e40/0/0 softirq=261/263 fqs=0
[ 1983.270412] 54-...: (1434 GPs behind) idle=650/0/0 softirq=258/260 fqs=0
[ 1983.277273] 55-...: (1646 GPs behind) idle=5e0/0/0 softirq=178/178 fqs=0
[ 1983.284135] 56-...: (1646 GPs behind) idle=800/0/0 softirq=249/249 fqs=0
[ 1983.290996] 57-...: (1599 GPs behind) idle=c48/0/0 softirq=222/224 fqs=0
[ 1983.297858] 58-...: (1648 GPs behind) idle=3e8/0/0 softirq=235/235 fqs=0
[ 1983.304719] 59-...: (1434 GPs behind) idle=720/0/0 softirq=201/203 fqs=0
[ 1983.311581] 60-...: (1647 GPs behind) idle=c80/0/0 softirq=250/250 fqs=0
[ 1983.318443] 61-...: (1598 GPs behind) idle=b18/0/0 softirq=208/208 fqs=0
[ 1983.325304] 62-...: (1112 GPs behind) idle=0a4/0/0 softirq=620/620 fqs=0
[ 1983.332166] 63-...: (1109 GPs behind) idle=4b0/0/0 softirq=187/188 fqs=0
[ 1983.339026] (detected by 44, t=5335 jiffies, g=1566, c=1565, q=220)
[ 1983.345371] Task dump for CPU 2:
[ 1983.348587] swapper/2 R running task 0 0 1 0x00000000
[ 1983.355626] Call trace:
[ 1983.358072] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1983.363199] [<7fffffffffffffff>] 0x7fffffffffffffff
[ 1983.368062] Task dump for CPU 3:
[ 1983.371278] swapper/3 R running task 0 0 1 0x00000000
[ 1983.378315] Call trace:
[ 1983.380750] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1983.385881] [<ffff000008ea9000>] page_wait_table+0x1280/0x1800
[ 1983.391699] Task dump for CPU 4:
[ 1983.394915] swapper/4 R running task 0 0 1 0x00000000
[ 1983.401951] Call trace:
[ 1983.404386] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1983.409510] [<7fffffffffffffff>] 0x7fffffffffffffff
[ 1983.414374] Task dump for CPU 5:
[ 1983.417590] swapper/5 R running task 0 0 1 0x00000000
[ 1983.424626] Call trace:
[ 1983.427060] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1983.432185] [<7fffffffffffffff>] 0x7fffffffffffffff
[ 1983.437049] Task dump for CPU 6:
[ 1983.440265] swapper/6 R running task 0 0 1 0x00000000
<snip> Mixture of the two forms above for all the cpus
[ 1984.568746] Call trace:
[ 1984.571180] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1984.576305] [<ffff000008ea9000>] page_wait_table+0x1280/0x1800
[ 1984.582124] Task dump for CPU 62:
[ 1984.585426] swapper/62 R running task 0 0 1 0x00000000
[ 1984.592461] Call trace:
[ 1984.594895] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1984.600020] [<ffff000008ea9000>] page_wait_table+0x1280/0x1800
[ 1984.605839] Task dump for CPU 63:
[ 1984.609141] swapper/63 R running task 0 0 1 0x00000000
[ 1984.616176] Call trace:
[ 1984.618611] [<ffff000008084fb0>] __switch_to+0x90/0xa8
[ 1984.623735] [<7fffffffffffffff>] 0x7fffffffffffffff
[ 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
Reducing the RCU CPU stall timeout makes it happen more often,
but we are seeing even with the default value of 24 seconds.
Tends to occur after a period or relatively low usage, but has
also been seen mid way through performance tests.
This was not seen with v4.12 so a bisection run later lead to
commit 05a4a9527 (kernel/watchdog: split up config options).
Which was odd until we discovered that a side effect of this patch
was to change whether the softlockup detector was enabled or not in
the arm64 defconfig.
On 4.13-rc2 enabling the softlockup detector indeed stopped us
seeing the rcu issue. Disabling the equivalent on 4.12 made the
issue occur there as well.
Clearly the softlockup detector results in a thread on every cpu,
which might be related but beyond that we are still looking into
the issue.
So the obvious question is whether anyone else is seeing this as
it might help us to focus in on where to look!
In the meantime we'll carry on digging.
Thanks,
Jonathan
p.s. As a more general question, do we want to have the
soft lockup detector enabledon arm64 by default?
More information about the linux-arm-kernel
mailing list