From: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
To: fupan li <lifupan@gmail.com>
Cc: linux-rt-users@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: Re: RCU stall and the system boot hang
Date: Fri, 27 Nov 2015 08:28:09 -0800 [thread overview]
Message-ID: <20151127162809.GM26643@linux.vnet.ibm.com> (raw)
In-Reply-To: <CADUONQMsaiTyFPRxm8TfB4ec__XjXUCAhjxZHG8Mz=cExvz5Sw@mail.gmail.com>
On Fri, Nov 27, 2015 at 08:23:24PM +0800, fupan li wrote:
> Hi, Paul
>
> On my Wildcat_Pass (Haswell) board, the system boot will hang as below.
> The kernel is preempt-rt kernel.
> But it was not reproduced every time, about 1 time per 5-10 boots.
CCing LMKL and linux-rt-users in case anyone else is seeing this.
OK, let's take a look at the stall warning...
[ . . . ]
> Btrfs loaded
> console [netcon0] enabled
> netconsole: network logging started
> rtc_cmos 00:00: setting system clock to 2015-11-11 18:18:03 UTC (1447265883)
> usb 1-9: new full-speed USB device number 3 using xhci_hcd
> IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
> IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
> usb 1-9: ep 0x81 - rounding interval to 64 microframes, ep desc says 80
> microframes
> input: American Megatrends Inc. Virtual Keyboard and Mouse as
> /devices/pci0000:00/0000:00:14.0/usb1/1-9/1-9:1.0/0003:046B:FF10.0002/input/input3
> hid-generic 0003:046B:FF10.0002: input: USB HID v1.10 Keyboard [American
> Megatrends Inc. Virtual Keyboard and Mouse] on usb-0000:00:14.0-9/input0
> input: American Megatrends Inc. Virtual Keyboard and Mouse as
> /devices/pci0000:00/0000:00:14.0/usb1/1-9/1-9:1.1/0003:046B:FF10.0003/input/input4
> hid-generic 0003:046B:FF10.0003: input: USB HID v1.10 Mouse [American
> Megatrends Inc. Virtual Keyboard and Mouse] on usb-0000:00:14.0-9/input1
> ixgbe 0000:02:00.0: registered PHC device on eth2
> IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
> ixgbe 0000:02:00.1: registered PHC device on eth3
> IPv6: ADDRCONF(NETDEV_UP): eth3: link is not ready
> igb 0000:04:00.0 eth0: igb: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow
> Control: RX/TX
> IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> cfg80211: Calling CRDA to update world regulatory domain
> Sending DHCP requests ., OK
> random: nonblocking pool is initialized
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Calling CRDA to update world regulatory domain
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 12: (0 ticks this GP) idle=f48/0/0 softirq=0/0 fqs=0
> 17: (59 GPs behind) idle=55a/0/0 softirq=0/0 fqs=0
So CPUs 12 and 17 are stalling the grace period.
> (detected by 5, t=21002 jiffies, g=-237, c=-238, q=136)
> Task dump for CPU 12:
> swapper/12 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859037eb8 ffffffff810b7ff5 ffff880859037ea8
> ffffffff810759ef ffffffff82140220 000000000000000c ffffffff82140220
> ffff880859034000 ffff880859037ea8 ffffffff8140f1f7 ffff880859037ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
But CPU 12 seems to be idle (as is in fact indicated by the "idle=55a/0/0"
above), so the grace-period kthread should have reported a quiescent
state on its behalf.
> Task dump for CPU 17:
> swapper/17 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859063eb8 ffffffff810b7ff5 ffff880859063ea8
> ffffffff810759ef ffffffff82140220 0000000000000011 ffffffff82140220
> ffff880859060000 ffff880859063ea8 ffffffff8140f1f7 ffff880859063ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
And the same for CPU 17.
> rcu_preempt kthread starved for 21002 jiffies!
But the grace-period kthread hasn't had a chance to run for more
than 21 seconds, which explains why the grace period is not ending.
Are you starting up a heavy real-time workload at boot time?
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Calling CRDA to update world regulatory domain
> cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 12: (0 ticks this GP) idle=04c/0/0 softirq=0/0 fqs=1
At this point, CPU 17's quiescent state has been recorded.
> (detected by 24, t=84007 jiffies, g=-237, c=-238, q=147)
> Task dump for CPU 12:
> swapper/12 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859037eb8 ffffffff810b7ff5 ffff880859037ea8
> ffffffff810759ef ffffffff82140220 000000000000000c ffffffff82140220
> ffff880859034000 ffff880859037ea8 ffffffff8140f1f7 ffff880859037ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
CPU 12 still looks idle. Though it does appear to have transitioned
between idle and non-idle several times.
> rcu_preempt kthread starved for 63005 jiffies!
And the last time the grace-period kthread ran was about the time of
the first stall-warning message. Strange...
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 12: (0 ticks this GP) idle=0a8/0/0 softirq=0/0 fqs=0
> 17: (60 GPs behind) idle=6b4/0/0 softirq=0/0 fqs=0
> (detected by 11, t=21002 jiffies, g=-236, c=-237, q=151)
And the old grace period (g=-237, c=-238) finished and a new one has
been stalled for 21 seconds. Again, CPUs 12 and 17 are idle and
stalling the grace period.
> Task dump for CPU 12:
> swapper/12 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859037eb8 ffffffff810b7ff5 ffff880859037ea8
> ffffffff810759ef ffffffff82140220 000000000000000c ffffffff82140220
> ffff880859034000 ffff880859037ea8 ffffffff8140f1f7 ffff880859037ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
> Task dump for CPU 17:
> swapper/17 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859063eb8 ffffffff810b7ff5 ffff880859063ea8
> ffffffff810759ef ffffffff82140220 0000000000000011 ffffffff82140220
> ffff880859060000 ffff880859063ea8 ffffffff8140f1f7 ffff880859063ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
The stack traces are consistent with idle CPUs.
> rcu_preempt kthread starved for 21002 jiffies!
And the grace-period kthread apparently hasn't gotten a chance to run
at all during the grace period. Strange... It should get awakened by
a timeout every three jiffies or so.
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 12: (0 ticks this GP) idle=1aa/0/0 softirq=0/0 fqs=1
> (detected by 0, t=84007 jiffies, g=-236, c=-237, q=159)
The same grace period is still stalled after a total of 84 seconds,
and again CPU 17's quiescent state has been reported.
> Task dump for CPU 12:
> swapper/12 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859037eb8 ffffffff810b7ff5 ffff880859037ea8
> ffffffff810759ef ffffffff82140220 000000000000000c ffffffff82140220
> ffff880859034000 ffff880859037ea8 ffffffff8140f1f7 ffff880859037ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
And again, the stack is consistent with the CPU being idle.
> rcu_preempt kthread starved for 63005 jiffies!
And again the grace-period kthread seems to have gotten a chance to
run during the first RCU CPU stall warning, but not since then.
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 12: (0 ticks this GP) idle=20c/0/0 softirq=0/0 fqs=0
> 17: (61 GPs behind) idle=810/0/0 softirq=0/0 fqs=0
> (detected by 40, t=21002 jiffies, g=-235, c=-236, q=162)
And again, it looks like the stall warning gave the grace-period kthread
another chance to run, thus completing the earlier grace period. We
now have another grace period stalled for 21 seconds, again by CPUs 12
and 17.
> Task dump for CPU 12:
> swapper/12 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859037eb8 ffffffff810b7ff5 ffff880859037ea8
> ffffffff810759ef ffffffff82140220 000000000000000c ffffffff82140220
> ffff880859034000 ffff880859037ea8 ffffffff8140f1f7 ffff880859037ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
> Task dump for CPU 17:
> swapper/17 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859063eb8 ffffffff810b7ff5 ffff880859063ea8
> ffffffff810759ef ffffffff82140220 0000000000000011 ffffffff82140220
> ffff880859060000 ffff880859063ea8 ffffffff8140f1f7 ffff880859063ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
> rcu_preempt kthread starved for 21002 jiffies!
And again idle stacks, and again the RCU grace-period kthread has not
been allowed to run at all since the grace period stared.
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 12: (0 ticks this GP) idle=30e/0/0 softirq=0/0 fqs=1
> (detected by 5, t=84007 jiffies, g=-235, c=-236, q=170)
> Task dump for CPU 12:
> swapper/12 R running task 0 0 1 0x00200000
> ffffffff8140f1f7 ffff880859037eb8 ffffffff810b7ff5 ffff880859037ea8
> ffffffff810759ef ffffffff82140220 000000000000000c ffffffff82140220
> ffff880859034000 ffff880859037ea8 ffffffff8140f1f7 ffff880859037ec8
> Call Trace:
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff810b7ff5>] ? rcu_eqs_enter_common+0x85/0x240
> [<ffffffff810759ef>] ? __atomic_notifier_call_chain+0x4f/0x70
> [<ffffffff8140f1f7>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff8100dd52>] ? mwait_idle+0x42/0x1d0
> [<ffffffff8100ea8f>] ? arch_cpu_idle+0xf/0x20
> [<ffffffff8109688e>] ? cpu_startup_entry+0xae/0x300
> [<ffffffff8103aabc>] ? start_secondary+0x12c/0x140
> rcu_preempt kthread starved for 63005 jiffies!
And again, CPU 17's grace period has been recorded, and the grace-period
kthread hasn't been allowed to run since the last RCU CPU stall warning.
When a stall warning is printed, there is also a resched_cpu() on the
holdout CPU. Perhaps that is also giving the grace-period kthread a
chance to run? Alternatively, perhaps the overhead of all the printing
is letting the grace-period kthread run?
I do sometimes see similar stalls, but under heavy rcutorture load and
when running qemu/kvm. I am considering this to be a bug (somewhere!) and
am tracking it down, but I suspect that your boot-time stalls are from
something different. Yours is the only report of this that I have seen
thus far.
So what are you starting up at boot time?
Thanx, Paul
next parent reply other threads:[~2015-11-27 16:28 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
[not found] <CADUONQMsaiTyFPRxm8TfB4ec__XjXUCAhjxZHG8Mz=cExvz5Sw@mail.gmail.com>
2015-11-27 16:28 ` Paul E. McKenney [this message]
[not found] ` <CADUONQN3yFyFQ8pfkS9u7UAYNjQym8f1JAGapeR9YV4E=7_xXg@mail.gmail.com>
2015-11-28 14:53 ` RCU stall and the system boot hang Paul E. McKenney
[not found] ` <CADUONQOYtHvwzoWNW33=WXy5r-UBTqs_vKdeRUgg=YEqq1meWg@mail.gmail.com>
2015-11-29 6:05 ` Paul E. McKenney
[not found] ` <CADUONQOc1x_gboKOmigwUX9GrZhukH4KkN1SXRGyjwvXfoGqTg@mail.gmail.com>
2015-11-30 17:19 ` Paul E. McKenney
2015-12-01 19:55 ` Paul E. McKenney
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20151127162809.GM26643@linux.vnet.ibm.com \
--to=paulmck@linux.vnet.ibm.com \
--cc=lifupan@gmail.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-rt-users@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).