Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1298923 > unrolled thread
| Started by | Aaron Ma <mapengyu@gmail.com> |
|---|---|
| First post | 2015-12-29 10:40 +0100 |
| Last post | 2016-01-05 20:20 +0100 |
| Articles | 9 — 2 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
Re: RCU stall and the system boot hang with nfsroot Aaron Ma <mapengyu@gmail.com> - 2015-12-29 10:40 +0100
Re: RCU stall and the system boot hang with nfsroot "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2015-12-30 00:50 +0100
Re: RCU stall and the system boot hang with nfsroot Aaron Ma <mapengyu@gmail.com> - 2015-12-30 08:10 +0100
Re: RCU stall and the system boot hang with nfsroot "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2015-12-30 18:50 +0100
Re: RCU stall and the system boot hang with nfsroot "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2015-12-31 21:00 +0100
Re: RCU stall and the system boot hang with nfsroot Aaron Ma <mapengyu@gmail.com> - 2016-01-04 11:10 +0100
Re: RCU stall and the system boot hang with nfsroot "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-01-04 22:20 +0100
Re: RCU stall and the system boot hang with nfsroot Aaron Ma <mapengyu@gmail.com> - 2016-01-05 09:00 +0100
Re: RCU stall and the system boot hang with nfsroot "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-01-05 20:20 +0100
| From | Aaron Ma <mapengyu@gmail.com> |
|---|---|
| Date | 2015-12-29 10:40 +0100 |
| Subject | Re: RCU stall and the system boot hang with nfsroot |
| Message-ID | <qKYV4-71t-23@gated-at.bofh.it> |
Add paulmck@linux.vnet.ibm.com On Tue, Dec 29, 2015 at 5:32 PM, Aaron Ma <mapengyu@gmail.com> wrote: > Hi, Paul: > I found the linux-stable-4.1.15 with rt15 patches boot hang sometimes. > Hardware is Grantley-EP and WildcatPass. > No response by sysrq. > > Did you found any issue about this? Or how can I address this issue? > > Attached kernel config. > > Thanks, > Pengyu > > xhci_hcd 0000:00:14.0: cache line size of 32 is not supported > hub 1-0:1.0: USB hub found > hub 1-0:1.0: 15 ports detected > xhci_hcd 0000:00:14.0: xHCI Host Controller > xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2 > hub 2-0:1.0: USB hub found > hub 2-0:1.0: 6 ports detected > initcall xhci_pci_init+0x0/0x44 returned 0 after 306571 usecs > calling ehci_hcd_init+0x0/0x5d @ 1 > ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver > initcall ehci_hcd_init+0x0/0x5d returned 0 after 5695 usecs > calling ehci_pci_init+0x0/0x69 @ 1 > ehci-pci: EHCI PCI platform driver > ehci-pci 0000:00:1a.0: enabling bus mastering > ehci-pci 0000:00:1a.0: EHCI Host Controller > ehci-pci 0000:00:1a.0: new USB bus registered, assigned bus number 3 > ehci-pci 0000:00:1a.0: debug port 2 > ehci-pci 0000:00:1a.0: cache line size of 32 is not supported > ehci-pci 0000:00:1a.0: irq 18, io mem 0x91d02000 > 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 > cfg80211: Exceeded CRDA call max attempts. Not calling CRDA > INFO: rcu_preempt detected stalls on CPUs/tasks: > 18: (0 ticks this GP) idle=284/0/0 softirq=0/0 fqs=0 > (detected by 12, t=26002 jiffies, g=5351, c=5350, q=451332) > Task dump for CPU 18: > swapper/18 R running task 0 0 1 0x00200000 > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004 > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8 > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046 > Call Trace: > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20 > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140 > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0 > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20 > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630 > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140 > rcu_preempt kthread starved for 26002 jiffies! > INFO: rcu_preempt detected stalls on CPUs/tasks: > 18: (0 ticks this GP) idle=326/0/0 softirq=0/0 fqs=1 > (detected by 67, t=104007 jiffies, g=5351, c=5350, q=451332) > Task dump for CPU 18: > swapper/18 R running task 0 0 1 0x00200000 > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004 > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8 > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046 > Call Trace: > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20 > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140 > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0 > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20 > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630 > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140 > rcu_preempt kthread starved for 78005 jiffies! > INFO: rcu_preempt detected stalls on CPUs/tasks: > 18: (0 ticks this GP) idle=35c/0/0 softirq=0/0 fqs=0 > (detected by 62, t=26002 jiffies, g=5352, c=5351, q=451332) > Task dump for CPU 18: > swapper/18 R running task 0 0 1 0x00200000 > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004 > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8 > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046 > Call Trace: > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20 > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140 > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0 > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20 > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630 > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140 > rcu_preempt kthread starved for 26002 jiffies! > perf interrupt took too long (2575 > 2500), lowering > kernel.perf_event_max_sample_rate to 50000 > INFO: task swapper/0:1 blocked for more than 120 seconds. > Not tainted 4.1.15-rt13-WR8.0.0.0_preempt-rt+ #25 > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > swapper/0 D ffff880453547a18 0 1 0 0x00000000 > ffff880453547a18 ffff880851aa8000 000000000000d7a0 ffff88045f604ba0 > ffff880851aa8000 ffff8804535479e8 ffffffff814946a7 ffff880453547a08 > ffff880453548000 ffff880851aa8000 ffff880453547a68 ffff8804663ce500 > Call Trace: > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20 > [<ffffffff81b60bff>] schedule+0x3f/0xd0 > [<ffffffff81b62c89>] schedule_timeout+0x189/0x3f0 > [<ffffffff810e8f10>] ? timer_cpu_notify+0x190/0x190 > [<ffffffff810eaac2>] msleep+0x42/0x50 > [<ffffffff81759bd6>] ehci_run+0xf6/0x1d0 > [<ffffffff8174329d>] usb_add_hcd+0x2dd/0x810 > [<ffffffff817551de>] usb_hcd_pci_probe+0x33e/0x490 > [<ffffffff81761626>] ehci_pci_probe+0x36/0x40 > [<ffffffff814bfe52>] local_pci_probe+0x42/0xa0 > [<ffffffff814bfda2>] ? pci_match_device+0xf2/0x120 > [<ffffffff814c1199>] pci_device_probe+0xe9/0x150 > [<ffffffff815cf861>] driver_probe_device+0x181/0x310 > [<ffffffff815cfacb>] __driver_attach+0x9b/0xa0 > [<ffffffff815cfa30>] ? __device_attach+0x40/0x40 > [<ffffffff815cd683>] bus_for_each_dev+0x73/0xb0 > [<ffffffff815cf24e>] driver_attach+0x1e/0x20 > [<ffffffff815cee78>] bus_add_driver+0x188/0x240 > [<ffffffff8239ec18>] ? ehci_hcd_init+0x5d/0x5d > [<ffffffff815d09e4>] driver_register+0x64/0xf0 > [<ffffffff814bf66a>] __pci_register_driver+0x8a/0x90 > [<ffffffff8239ec7f>] ehci_pci_init+0x67/0x69 > [<ffffffff8100045b>] do_one_initcall+0x12b/0x1c0 > [<ffffffff8235615e>] kernel_init_freeable+0x1f9/0x2c0 > [<ffffffff810b26c7>] ? trace_hardirqs_on_caller+0xe7/0x240 > [<ffffffff810b282d>] ? trace_hardirqs_on+0xd/0x10 > [<ffffffff81b641fb>] ? _raw_spin_unlock_irq+0x3b/0x80 > [<ffffffff81087f5c>] ? finish_task_switch+0x9c/0x150 > [<ffffffff81087f1d>] ? finish_task_switch+0x5d/0x150 > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20 > [<ffffffff81b547a0>] ? rest_init+0x140/0x140 > [<ffffffff81b547ae>] kernel_init+0xe/0xf0 > [<ffffffff81b652a2>] ret_from_fork+0x42/0x70 > [<ffffffff81b547a0>] ? rest_init+0x140/0x140 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
[toc] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2015-12-30 00:50 +0100 |
| Message-ID | <qLcbF-7bP-29@gated-at.bofh.it> |
| In reply to | #1298923 |
On Tue, Dec 29, 2015 at 05:34:38PM +0800, Aaron Ma wrote:
> Add paulmck@linux.vnet.ibm.com
>
> On Tue, Dec 29, 2015 at 5:32 PM, Aaron Ma <mapengyu@gmail.com> wrote:
> > Hi, Paul:
> > I found the linux-stable-4.1.15 with rt15 patches boot hang sometimes.
> > Hardware is Grantley-EP and WildcatPass.
I must confess that I am unfamiliar with this hardware, for whatever
that might be worth.
> > No response by sysrq.
> >
> > Did you found any issue about this? Or how can I address this issue?
I see something similar in post-4.1 mainline, but only when CPU hotplug
is enabled and only under extreme stress. Which is probably not the
case during your boot-up. But please see below.
> > Attached kernel config.
> >
> > Thanks,
> > Pengyu
> >
> > xhci_hcd 0000:00:14.0: cache line size of 32 is not supported
> > hub 1-0:1.0: USB hub found
> > hub 1-0:1.0: 15 ports detected
> > xhci_hcd 0000:00:14.0: xHCI Host Controller
> > xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
> > hub 2-0:1.0: USB hub found
> > hub 2-0:1.0: 6 ports detected
> > initcall xhci_pci_init+0x0/0x44 returned 0 after 306571 usecs
> > calling ehci_hcd_init+0x0/0x5d @ 1
> > ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> > initcall ehci_hcd_init+0x0/0x5d returned 0 after 5695 usecs
> > calling ehci_pci_init+0x0/0x69 @ 1
> > ehci-pci: EHCI PCI platform driver
> > ehci-pci 0000:00:1a.0: enabling bus mastering
> > ehci-pci 0000:00:1a.0: EHCI Host Controller
> > ehci-pci 0000:00:1a.0: new USB bus registered, assigned bus number 3
> > ehci-pci 0000:00:1a.0: debug port 2
> > ehci-pci 0000:00:1a.0: cache line size of 32 is not supported
> > ehci-pci 0000:00:1a.0: irq 18, io mem 0x91d02000
> > 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
> > cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
> > INFO: rcu_preempt detected stalls on CPUs/tasks:
> > 18: (0 ticks this GP) idle=284/0/0 softirq=0/0 fqs=0
The "stalling" CPU is idle, which is a quiescent state and therefore
should not stall grace periods. But please see below...
> > (detected by 12, t=26002 jiffies, g=5351, c=5350, q=451332)
> > Task dump for CPU 18:
> > swapper/18 R running task 0 0 1 0x00200000
> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
> > Call Trace:
> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
> > rcu_preempt kthread starved for 26002 jiffies!
The reason that the idle CPU is not being recognized as a legitimate
quiescent state is that the rcu_preempt grace-period kthread is not
being allowed to run. In fact, it has not been permitted to run for more
than 26 seconds. Despite the fact that in this situation, it would have
invoked wait_event_interruptible_timeout() with a three-jiffy timeout.
One thing to do is to modify the rcu_check_gp_kthread_starvation()
function to print the value of rsp->gp_kthread, then to also print
fields from the resulting pointer to task_struct to see what the thread
is up to. (It is tempting to suspect that this kthread might never have
been spawned, but in that case the grace period would not have started.)
For example, add the following in the "if (j - gpa > 2 * HZ)"
body:
if (rsp->gp_kthread)
sched_show_task(rsp->gp_kthread);
Don't forget to add the "{" "}" to accommodate the additional statement
within the "if" statement.
If the additional output shows that the rcu_preempt kthread is runnable,
the next question is "why is it not running?". If the output instead
shows that the task is blocked, the next question is "why didn't the
wait_event_interruptible_timeout() awaken it?
Thanx, Paul
> > INFO: rcu_preempt detected stalls on CPUs/tasks:
> > 18: (0 ticks this GP) idle=326/0/0 softirq=0/0 fqs=1
> > (detected by 67, t=104007 jiffies, g=5351, c=5350, q=451332)
> > Task dump for CPU 18:
> > swapper/18 R running task 0 0 1 0x00200000
> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
> > Call Trace:
> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
> > rcu_preempt kthread starved for 78005 jiffies!
> > INFO: rcu_preempt detected stalls on CPUs/tasks:
> > 18: (0 ticks this GP) idle=35c/0/0 softirq=0/0 fqs=0
> > (detected by 62, t=26002 jiffies, g=5352, c=5351, q=451332)
> > Task dump for CPU 18:
> > swapper/18 R running task 0 0 1 0x00200000
> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
> > Call Trace:
> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
> > rcu_preempt kthread starved for 26002 jiffies!
> > perf interrupt took too long (2575 > 2500), lowering
> > kernel.perf_event_max_sample_rate to 50000
> > INFO: task swapper/0:1 blocked for more than 120 seconds.
> > Not tainted 4.1.15-rt13-WR8.0.0.0_preempt-rt+ #25
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > swapper/0 D ffff880453547a18 0 1 0 0x00000000
> > ffff880453547a18 ffff880851aa8000 000000000000d7a0 ffff88045f604ba0
> > ffff880851aa8000 ffff8804535479e8 ffffffff814946a7 ffff880453547a08
> > ffff880453548000 ffff880851aa8000 ffff880453547a68 ffff8804663ce500
> > Call Trace:
> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff81b60bff>] schedule+0x3f/0xd0
> > [<ffffffff81b62c89>] schedule_timeout+0x189/0x3f0
> > [<ffffffff810e8f10>] ? timer_cpu_notify+0x190/0x190
> > [<ffffffff810eaac2>] msleep+0x42/0x50
> > [<ffffffff81759bd6>] ehci_run+0xf6/0x1d0
> > [<ffffffff8174329d>] usb_add_hcd+0x2dd/0x810
> > [<ffffffff817551de>] usb_hcd_pci_probe+0x33e/0x490
> > [<ffffffff81761626>] ehci_pci_probe+0x36/0x40
> > [<ffffffff814bfe52>] local_pci_probe+0x42/0xa0
> > [<ffffffff814bfda2>] ? pci_match_device+0xf2/0x120
> > [<ffffffff814c1199>] pci_device_probe+0xe9/0x150
> > [<ffffffff815cf861>] driver_probe_device+0x181/0x310
> > [<ffffffff815cfacb>] __driver_attach+0x9b/0xa0
> > [<ffffffff815cfa30>] ? __device_attach+0x40/0x40
> > [<ffffffff815cd683>] bus_for_each_dev+0x73/0xb0
> > [<ffffffff815cf24e>] driver_attach+0x1e/0x20
> > [<ffffffff815cee78>] bus_add_driver+0x188/0x240
> > [<ffffffff8239ec18>] ? ehci_hcd_init+0x5d/0x5d
> > [<ffffffff815d09e4>] driver_register+0x64/0xf0
> > [<ffffffff814bf66a>] __pci_register_driver+0x8a/0x90
> > [<ffffffff8239ec7f>] ehci_pci_init+0x67/0x69
> > [<ffffffff8100045b>] do_one_initcall+0x12b/0x1c0
> > [<ffffffff8235615e>] kernel_init_freeable+0x1f9/0x2c0
> > [<ffffffff810b26c7>] ? trace_hardirqs_on_caller+0xe7/0x240
> > [<ffffffff810b282d>] ? trace_hardirqs_on+0xd/0x10
> > [<ffffffff81b641fb>] ? _raw_spin_unlock_irq+0x3b/0x80
> > [<ffffffff81087f5c>] ? finish_task_switch+0x9c/0x150
> > [<ffffffff81087f1d>] ? finish_task_switch+0x5d/0x150
> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff81b547a0>] ? rest_init+0x140/0x140
> > [<ffffffff81b547ae>] kernel_init+0xe/0xf0
> > [<ffffffff81b652a2>] ret_from_fork+0x42/0x70
> > [<ffffffff81b547a0>] ? rest_init+0x140/0x140
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Aaron Ma <mapengyu@gmail.com> |
|---|---|
| Date | 2015-12-30 08:10 +0100 |
| Message-ID | <qLj3r-3pd-1@gated-at.bofh.it> |
| In reply to | #1299169 |
On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> On Tue, Dec 29, 2015 at 05:34:38PM +0800, Aaron Ma wrote:
>> Add paulmck@linux.vnet.ibm.com
>>
>> On Tue, Dec 29, 2015 at 5:32 PM, Aaron Ma <mapengyu@gmail.com> wrote:
>> > Hi, Paul:
>> > I found the linux-stable-4.1.15 with rt15 patches boot hang sometimes.
>> > Hardware is Grantley-EP and WildcatPass.
>
> I must confess that I am unfamiliar with this hardware, for whatever
> that might be worth.
>
>> > No response by sysrq.
>> >
>> > Did you found any issue about this? Or how can I address this issue?
>
> I see something similar in post-4.1 mainline, but only when CPU hotplug
> is enabled and only under extreme stress. Which is probably not the
> case during your boot-up. But please see below.
>
>> > Attached kernel config.
>> >
>> > Thanks,
>> > Pengyu
>> >
>> > xhci_hcd 0000:00:14.0: cache line size of 32 is not supported
>> > hub 1-0:1.0: USB hub found
>> > hub 1-0:1.0: 15 ports detected
>> > xhci_hcd 0000:00:14.0: xHCI Host Controller
>> > xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
>> > hub 2-0:1.0: USB hub found
>> > hub 2-0:1.0: 6 ports detected
>> > initcall xhci_pci_init+0x0/0x44 returned 0 after 306571 usecs
>> > calling ehci_hcd_init+0x0/0x5d @ 1
>> > ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
>> > initcall ehci_hcd_init+0x0/0x5d returned 0 after 5695 usecs
>> > calling ehci_pci_init+0x0/0x69 @ 1
>> > ehci-pci: EHCI PCI platform driver
>> > ehci-pci 0000:00:1a.0: enabling bus mastering
>> > ehci-pci 0000:00:1a.0: EHCI Host Controller
>> > ehci-pci 0000:00:1a.0: new USB bus registered, assigned bus number 3
>> > ehci-pci 0000:00:1a.0: debug port 2
>> > ehci-pci 0000:00:1a.0: cache line size of 32 is not supported
>> > ehci-pci 0000:00:1a.0: irq 18, io mem 0x91d02000
>> > 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
>> > cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
>> > INFO: rcu_preempt detected stalls on CPUs/tasks:
>> > 18: (0 ticks this GP) idle=284/0/0 softirq=0/0 fqs=0
>
> The "stalling" CPU is idle, which is a quiescent state and therefore
> should not stall grace periods. But please see below...
>
>> > (detected by 12, t=26002 jiffies, g=5351, c=5350, q=451332)
>> > Task dump for CPU 18:
>> > swapper/18 R running task 0 0 1 0x00200000
>> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
>> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
>> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
>> > Call Trace:
>> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
>> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
>> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
>> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
>> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
>> > rcu_preempt kthread starved for 26002 jiffies!
>
> The reason that the idle CPU is not being recognized as a legitimate
> quiescent state is that the rcu_preempt grace-period kthread is not
> being allowed to run. In fact, it has not been permitted to run for more
> than 26 seconds. Despite the fact that in this situation, it would have
> invoked wait_event_interruptible_timeout() with a three-jiffy timeout.
>
> One thing to do is to modify the rcu_check_gp_kthread_starvation()
> function to print the value of rsp->gp_kthread, then to also print
> fields from the resulting pointer to task_struct to see what the thread
> is up to. (It is tempting to suspect that this kthread might never have
> been spawned, but in that case the grace period would not have started.)
>
> For example, add the following in the "if (j - gpa > 2 * HZ)"
> body:
>
> if (rsp->gp_kthread)
> sched_show_task(rsp->gp_kthread);
>
> Don't forget to add the "{" "}" to accommodate the additional statement
> within the "if" statement.
>
> If the additional output shows that the rcu_preempt kthread is runnable,
> the next question is "why is it not running?". If the output instead
> shows that the task is blocked, the next question is "why didn't the
> wait_event_interruptible_timeout() awaken it?
>
> Thanx, Paul
Add sched_show_task to show the current task on stalled CPU:
calling efi_load_efivars+0x0/0x40 @ 1
initcall efi_load_efivars+0x0/0x40 returned 0 after 0 usecs
calling esrt_sysfs_init+0x0/0x2d6 @ 1
initcall esrt_sysfs_init+0x0/0x2d6 returned -38 after 1 usecs
calling hid_init+0x0/0x4c @ 1
initcall hid_init+0x0/0x4c returned 0 after 373 usecs
calling hid_generic_init+0x0/0x1b @ 1
initcall hid_generic_init+0x0/0x1b returned 0 after 108 usecs
calling sensor_hub_driver_init+0x0/0x1b @ 1
initcall sensor_hub_driver_init+0x0/0x1b returned 0 after 101 usecs
calling hid_init+0x0/0x54 @ 1
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.0001/input/input2
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
cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
INFO: rcu_preempt detected stalls on CPUs/tasks:
71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
(detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
Task dump for CPU 71:
swapper/71 R running task 0 0 1 0x00200000
ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
Call Trace:
[<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
[<ffffffff814f21d7>] ? intel_idle+0x137/0x140
[<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
[<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
[<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
[<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
rcu_preempt kthread starved for 26002 jiffies!
rcu_check_gp_kthread_starvation --->show task:
rcu_preempt S ffff880456413c68 0 8 2 0x00000000
ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
Call Trace:
[<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
[<ffffffff81b5ce9f>] schedule+0x3f/0xd0
[<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
[<ffffffff810a7904>] ? swait_prepare+0x24/0x90
[<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
[<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
[<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
[<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
[<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
[<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
[<ffffffff8107f844>] kthread+0xe4/0x100
[<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
[<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
[<ffffffff81b61562>] ret_from_fork+0x42/0x70
[<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
rcu_check_gp_kthread_starvation --->end
It seems wait in rcu_gp_kthread. it should be no task blocked right?
If so, why the swait_event_interruptible_timeout is not awaken? the
timeout is CONFIG_HZ=1000.
Thanks for your answer during holiday.
Pengyu
>
>> > INFO: rcu_preempt detected stalls on CPUs/tasks:
>> > 18: (0 ticks this GP) idle=326/0/0 softirq=0/0 fqs=1
>> > (detected by 67, t=104007 jiffies, g=5351, c=5350, q=451332)
>> > Task dump for CPU 18:
>> > swapper/18 R running task 0 0 1 0x00200000
>> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
>> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
>> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
>> > Call Trace:
>> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
>> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
>> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
>> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
>> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
>> > rcu_preempt kthread starved for 78005 jiffies!
>> > INFO: rcu_preempt detected stalls on CPUs/tasks:
>> > 18: (0 ticks this GP) idle=35c/0/0 softirq=0/0 fqs=0
>> > (detected by 62, t=26002 jiffies, g=5352, c=5351, q=451332)
>> > Task dump for CPU 18:
>> > swapper/18 R running task 0 0 1 0x00200000
>> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
>> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
>> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
>> > Call Trace:
>> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
>> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
>> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
>> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
>> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
>> > rcu_preempt kthread starved for 26002 jiffies!
>> > perf interrupt took too long (2575 > 2500), lowering
>> > kernel.perf_event_max_sample_rate to 50000
>> > INFO: task swapper/0:1 blocked for more than 120 seconds.
>> > Not tainted 4.1.15-rt13-WR8.0.0.0_preempt-rt+ #25
>> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> > swapper/0 D ffff880453547a18 0 1 0 0x00000000
>> > ffff880453547a18 ffff880851aa8000 000000000000d7a0 ffff88045f604ba0
>> > ffff880851aa8000 ffff8804535479e8 ffffffff814946a7 ffff880453547a08
>> > ffff880453548000 ffff880851aa8000 ffff880453547a68 ffff8804663ce500
>> > Call Trace:
>> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff81b60bff>] schedule+0x3f/0xd0
>> > [<ffffffff81b62c89>] schedule_timeout+0x189/0x3f0
>> > [<ffffffff810e8f10>] ? timer_cpu_notify+0x190/0x190
>> > [<ffffffff810eaac2>] msleep+0x42/0x50
>> > [<ffffffff81759bd6>] ehci_run+0xf6/0x1d0
>> > [<ffffffff8174329d>] usb_add_hcd+0x2dd/0x810
>> > [<ffffffff817551de>] usb_hcd_pci_probe+0x33e/0x490
>> > [<ffffffff81761626>] ehci_pci_probe+0x36/0x40
>> > [<ffffffff814bfe52>] local_pci_probe+0x42/0xa0
>> > [<ffffffff814bfda2>] ? pci_match_device+0xf2/0x120
>> > [<ffffffff814c1199>] pci_device_probe+0xe9/0x150
>> > [<ffffffff815cf861>] driver_probe_device+0x181/0x310
>> > [<ffffffff815cfacb>] __driver_attach+0x9b/0xa0
>> > [<ffffffff815cfa30>] ? __device_attach+0x40/0x40
>> > [<ffffffff815cd683>] bus_for_each_dev+0x73/0xb0
>> > [<ffffffff815cf24e>] driver_attach+0x1e/0x20
>> > [<ffffffff815cee78>] bus_add_driver+0x188/0x240
>> > [<ffffffff8239ec18>] ? ehci_hcd_init+0x5d/0x5d
>> > [<ffffffff815d09e4>] driver_register+0x64/0xf0
>> > [<ffffffff814bf66a>] __pci_register_driver+0x8a/0x90
>> > [<ffffffff8239ec7f>] ehci_pci_init+0x67/0x69
>> > [<ffffffff8100045b>] do_one_initcall+0x12b/0x1c0
>> > [<ffffffff8235615e>] kernel_init_freeable+0x1f9/0x2c0
>> > [<ffffffff810b26c7>] ? trace_hardirqs_on_caller+0xe7/0x240
>> > [<ffffffff810b282d>] ? trace_hardirqs_on+0xd/0x10
>> > [<ffffffff81b641fb>] ? _raw_spin_unlock_irq+0x3b/0x80
>> > [<ffffffff81087f5c>] ? finish_task_switch+0x9c/0x150
>> > [<ffffffff81087f1d>] ? finish_task_switch+0x5d/0x150
>> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff81b547a0>] ? rest_init+0x140/0x140
>> > [<ffffffff81b547ae>] kernel_init+0xe/0xf0
>> > [<ffffffff81b652a2>] ret_from_fork+0x42/0x70
>> > [<ffffffff81b547a0>] ? rest_init+0x140/0x140
>>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2015-12-30 18:50 +0100 |
| Message-ID | <qLt2N-1dJ-7@gated-at.bofh.it> |
| In reply to | #1299261 |
On Wed, Dec 30, 2015 at 03:03:33PM +0800, Aaron Ma wrote:
> On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> > On Tue, Dec 29, 2015 at 05:34:38PM +0800, Aaron Ma wrote:
> >> Add paulmck@linux.vnet.ibm.com
> >>
> >> On Tue, Dec 29, 2015 at 5:32 PM, Aaron Ma <mapengyu@gmail.com> wrote:
> >> > Hi, Paul:
> >> > I found the linux-stable-4.1.15 with rt15 patches boot hang sometimes.
> >> > Hardware is Grantley-EP and WildcatPass.
> >
> > I must confess that I am unfamiliar with this hardware, for whatever
> > that might be worth.
> >
> >> > No response by sysrq.
> >> >
> >> > Did you found any issue about this? Or how can I address this issue?
> >
> > I see something similar in post-4.1 mainline, but only when CPU hotplug
> > is enabled and only under extreme stress. Which is probably not the
> > case during your boot-up. But please see below.
> >
> >> > Attached kernel config.
> >> >
> >> > Thanks,
> >> > Pengyu
> >> >
> >> > xhci_hcd 0000:00:14.0: cache line size of 32 is not supported
> >> > hub 1-0:1.0: USB hub found
> >> > hub 1-0:1.0: 15 ports detected
> >> > xhci_hcd 0000:00:14.0: xHCI Host Controller
> >> > xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
> >> > hub 2-0:1.0: USB hub found
> >> > hub 2-0:1.0: 6 ports detected
> >> > initcall xhci_pci_init+0x0/0x44 returned 0 after 306571 usecs
> >> > calling ehci_hcd_init+0x0/0x5d @ 1
> >> > ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> >> > initcall ehci_hcd_init+0x0/0x5d returned 0 after 5695 usecs
> >> > calling ehci_pci_init+0x0/0x69 @ 1
> >> > ehci-pci: EHCI PCI platform driver
> >> > ehci-pci 0000:00:1a.0: enabling bus mastering
> >> > ehci-pci 0000:00:1a.0: EHCI Host Controller
> >> > ehci-pci 0000:00:1a.0: new USB bus registered, assigned bus number 3
> >> > ehci-pci 0000:00:1a.0: debug port 2
> >> > ehci-pci 0000:00:1a.0: cache line size of 32 is not supported
> >> > ehci-pci 0000:00:1a.0: irq 18, io mem 0x91d02000
> >> > 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
> >> > cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
> >> > INFO: rcu_preempt detected stalls on CPUs/tasks:
> >> > 18: (0 ticks this GP) idle=284/0/0 softirq=0/0 fqs=0
> >
> > The "stalling" CPU is idle, which is a quiescent state and therefore
> > should not stall grace periods. But please see below...
> >
> >> > (detected by 12, t=26002 jiffies, g=5351, c=5350, q=451332)
> >> > Task dump for CPU 18:
> >> > swapper/18 R running task 0 0 1 0x00200000
> >> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
> >> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
> >> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
> >> > Call Trace:
> >> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
> >> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
> >> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
> >> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
> >> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
> >> > rcu_preempt kthread starved for 26002 jiffies!
> >
> > The reason that the idle CPU is not being recognized as a legitimate
> > quiescent state is that the rcu_preempt grace-period kthread is not
> > being allowed to run. In fact, it has not been permitted to run for more
> > than 26 seconds. Despite the fact that in this situation, it would have
> > invoked wait_event_interruptible_timeout() with a three-jiffy timeout.
> >
> > One thing to do is to modify the rcu_check_gp_kthread_starvation()
> > function to print the value of rsp->gp_kthread, then to also print
> > fields from the resulting pointer to task_struct to see what the thread
> > is up to. (It is tempting to suspect that this kthread might never have
> > been spawned, but in that case the grace period would not have started.)
> >
> > For example, add the following in the "if (j - gpa > 2 * HZ)"
> > body:
> >
> > if (rsp->gp_kthread)
> > sched_show_task(rsp->gp_kthread);
> >
> > Don't forget to add the "{" "}" to accommodate the additional statement
> > within the "if" statement.
> >
> > If the additional output shows that the rcu_preempt kthread is runnable,
> > the next question is "why is it not running?". If the output instead
> > shows that the task is blocked, the next question is "why didn't the
> > wait_event_interruptible_timeout() awaken it?
> >
> > Thanx, Paul
>
> Add sched_show_task to show the current task on stalled CPU:
>
> calling efi_load_efivars+0x0/0x40 @ 1
> initcall efi_load_efivars+0x0/0x40 returned 0 after 0 usecs
> calling esrt_sysfs_init+0x0/0x2d6 @ 1
> initcall esrt_sysfs_init+0x0/0x2d6 returned -38 after 1 usecs
> calling hid_init+0x0/0x4c @ 1
> initcall hid_init+0x0/0x4c returned 0 after 373 usecs
> calling hid_generic_init+0x0/0x1b @ 1
> initcall hid_generic_init+0x0/0x1b returned 0 after 108 usecs
> calling sensor_hub_driver_init+0x0/0x1b @ 1
> initcall sensor_hub_driver_init+0x0/0x1b returned 0 after 101 usecs
> calling hid_init+0x0/0x54 @ 1
> 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.0001/input/input2
> 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
> cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
> INFO: rcu_preempt detected stalls on CPUs/tasks:
> 71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
> (detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
> Task dump for CPU 71:
> swapper/71 R running task 0 0 1 0x00200000
> ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
> 0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
> ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
> Call Trace:
> [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff814f21d7>] ? intel_idle+0x137/0x140
> [<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
> [<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
> [<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
> [<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
> rcu_preempt kthread starved for 26002 jiffies!
> rcu_check_gp_kthread_starvation --->show task:
> rcu_preempt S ffff880456413c68 0 8 2 0x00000000
> ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
> ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
> ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
> Call Trace:
> [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> [<ffffffff81b5ce9f>] schedule+0x3f/0xd0
> [<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
> [<ffffffff810a7904>] ? swait_prepare+0x24/0x90
> [<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
> [<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
> [<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
> [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> [<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
> [<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
> [<ffffffff8107f844>] kthread+0xe4/0x100
> [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> [<ffffffff81b61562>] ret_from_fork+0x42/0x70
> [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> rcu_check_gp_kthread_starvation --->end
>
> It seems wait in rcu_gp_kthread. it should be no task blocked right?
> If so, why the swait_event_interruptible_timeout is not awaken? the
> timeout is CONFIG_HZ=1000.
Given that this happens at boot, perhaps ftrace is a good next step.
The thought would be to enable ftrace via the kernel boot parameters
for the timers.
And how often does this problem occur?
Thanx, Paul
> Thanks for your answer during holiday.
> Pengyu
>
> >
> >> > INFO: rcu_preempt detected stalls on CPUs/tasks:
> >> > 18: (0 ticks this GP) idle=326/0/0 softirq=0/0 fqs=1
> >> > (detected by 67, t=104007 jiffies, g=5351, c=5350, q=451332)
> >> > Task dump for CPU 18:
> >> > swapper/18 R running task 0 0 1 0x00200000
> >> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
> >> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
> >> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
> >> > Call Trace:
> >> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
> >> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
> >> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
> >> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
> >> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
> >> > rcu_preempt kthread starved for 78005 jiffies!
> >> > INFO: rcu_preempt detected stalls on CPUs/tasks:
> >> > 18: (0 ticks this GP) idle=35c/0/0 softirq=0/0 fqs=0
> >> > (detected by 62, t=26002 jiffies, g=5352, c=5351, q=451332)
> >> > Task dump for CPU 18:
> >> > swapper/18 R running task 0 0 1 0x00200000
> >> > ffffffff814946a7 ffff88045fbc7e58 ffffffff814f42f7 0000000000000004
> >> > 0000000000000004 ffff8804663e0f60 ffffffff820dc5c0 ffff88045fbc7ea8
> >> > ffffffff8181fca5 0000000000000000 0000000000000000 0000000000000046
> >> > Call Trace:
> >> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff814f42f7>] ? intel_idle+0x137/0x140
> >> > [<ffffffff8181fca5>] ? cpuidle_enter_state+0x65/0x3e0
> >> > [<ffffffff81820057>] ? cpuidle_enter+0x17/0x20
> >> > [<ffffffff810a856d>] ? cpu_startup_entry+0x33d/0x630
> >> > [<ffffffff8103cf6e>] ? start_secondary+0x12e/0x140
> >> > rcu_preempt kthread starved for 26002 jiffies!
> >> > perf interrupt took too long (2575 > 2500), lowering
> >> > kernel.perf_event_max_sample_rate to 50000
> >> > INFO: task swapper/0:1 blocked for more than 120 seconds.
> >> > Not tainted 4.1.15-rt13-WR8.0.0.0_preempt-rt+ #25
> >> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> > swapper/0 D ffff880453547a18 0 1 0 0x00000000
> >> > ffff880453547a18 ffff880851aa8000 000000000000d7a0 ffff88045f604ba0
> >> > ffff880851aa8000 ffff8804535479e8 ffffffff814946a7 ffff880453547a08
> >> > ffff880453548000 ffff880851aa8000 ffff880453547a68 ffff8804663ce500
> >> > Call Trace:
> >> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff81b60bff>] schedule+0x3f/0xd0
> >> > [<ffffffff81b62c89>] schedule_timeout+0x189/0x3f0
> >> > [<ffffffff810e8f10>] ? timer_cpu_notify+0x190/0x190
> >> > [<ffffffff810eaac2>] msleep+0x42/0x50
> >> > [<ffffffff81759bd6>] ehci_run+0xf6/0x1d0
> >> > [<ffffffff8174329d>] usb_add_hcd+0x2dd/0x810
> >> > [<ffffffff817551de>] usb_hcd_pci_probe+0x33e/0x490
> >> > [<ffffffff81761626>] ehci_pci_probe+0x36/0x40
> >> > [<ffffffff814bfe52>] local_pci_probe+0x42/0xa0
> >> > [<ffffffff814bfda2>] ? pci_match_device+0xf2/0x120
> >> > [<ffffffff814c1199>] pci_device_probe+0xe9/0x150
> >> > [<ffffffff815cf861>] driver_probe_device+0x181/0x310
> >> > [<ffffffff815cfacb>] __driver_attach+0x9b/0xa0
> >> > [<ffffffff815cfa30>] ? __device_attach+0x40/0x40
> >> > [<ffffffff815cd683>] bus_for_each_dev+0x73/0xb0
> >> > [<ffffffff815cf24e>] driver_attach+0x1e/0x20
> >> > [<ffffffff815cee78>] bus_add_driver+0x188/0x240
> >> > [<ffffffff8239ec18>] ? ehci_hcd_init+0x5d/0x5d
> >> > [<ffffffff815d09e4>] driver_register+0x64/0xf0
> >> > [<ffffffff814bf66a>] __pci_register_driver+0x8a/0x90
> >> > [<ffffffff8239ec7f>] ehci_pci_init+0x67/0x69
> >> > [<ffffffff8100045b>] do_one_initcall+0x12b/0x1c0
> >> > [<ffffffff8235615e>] kernel_init_freeable+0x1f9/0x2c0
> >> > [<ffffffff810b26c7>] ? trace_hardirqs_on_caller+0xe7/0x240
> >> > [<ffffffff810b282d>] ? trace_hardirqs_on+0xd/0x10
> >> > [<ffffffff81b641fb>] ? _raw_spin_unlock_irq+0x3b/0x80
> >> > [<ffffffff81087f5c>] ? finish_task_switch+0x9c/0x150
> >> > [<ffffffff81087f1d>] ? finish_task_switch+0x5d/0x150
> >> > [<ffffffff814946a7>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff81b547a0>] ? rest_init+0x140/0x140
> >> > [<ffffffff81b547ae>] kernel_init+0xe/0xf0
> >> > [<ffffffff81b652a2>] ret_from_fork+0x42/0x70
> >> > [<ffffffff81b547a0>] ? rest_init+0x140/0x140
> >>
> >
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2015-12-31 21:00 +0100 |
| Message-ID | <qLRyb-g0-9@gated-at.bofh.it> |
| In reply to | #1299438 |
On Wed, Dec 30, 2015 at 09:41:45AM -0800, Paul E. McKenney wrote:
> On Wed, Dec 30, 2015 at 03:03:33PM +0800, Aaron Ma wrote:
> > On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
> > <paulmck@linux.vnet.ibm.com> wrote:
[ . . . ]
> > 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:
> > 71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
> > (detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
> > Task dump for CPU 71:
> > swapper/71 R running task 0 0 1 0x00200000
> > ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
> > 0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
> > ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
> > Call Trace:
> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff814f21d7>] ? intel_idle+0x137/0x140
> > [<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
> > [<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
> > [<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
> > [<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
> > rcu_preempt kthread starved for 26002 jiffies!
> > rcu_check_gp_kthread_starvation --->show task:
> > rcu_preempt S ffff880456413c68 0 8 2 0x00000000
> > ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
> > ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
> > ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
> > Call Trace:
> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> > [<ffffffff81b5ce9f>] schedule+0x3f/0xd0
> > [<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
> > [<ffffffff810a7904>] ? swait_prepare+0x24/0x90
> > [<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
> > [<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
> > [<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> > [<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
> > [<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
> > [<ffffffff8107f844>] kthread+0xe4/0x100
> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> > [<ffffffff81b61562>] ret_from_fork+0x42/0x70
> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> > rcu_check_gp_kthread_starvation --->end
> >
> > It seems wait in rcu_gp_kthread. it should be no task blocked right?
> > If so, why the swait_event_interruptible_timeout is not awaken? the
> > timeout is CONFIG_HZ=1000.
>
> Given that this happens at boot, perhaps ftrace is a good next step.
> The thought would be to enable ftrace via the kernel boot parameters
> for the timers.
>
> And how often does this problem occur?
And does the following diagnostic patch help? Its expected behavior
would be to turn a hard hang into something that recovered in a few
minutes, while giving a few stall-warning splats.
Thanx, Paul
------------------------------------------------------------------------
commit 7798a5efb2acabfa3ca788dd9b5b118eb1bff443
Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Date: Thu Dec 31 08:48:36 2015 -0800
rcu: Awaken grace-period kthread when stalled
Recent kernels can fail to awaken the grace-period kthread for
quiescent-state forcing. This commit is a crude hack that does
a wakeup any time a stall is detected.
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index 4b3de6718f7c..51da7ef3561f 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -1225,8 +1225,10 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
rsp->gp_flags,
gp_state_getname(rsp->gp_state), rsp->gp_state,
rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
- if (rsp->gp_kthread)
+ if (rsp->gp_kthread) {
sched_show_task(rsp->gp_kthread);
+ wake_up_process(rsp->gp_kthread);
+ }
}
}
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Aaron Ma <mapengyu@gmail.com> |
|---|---|
| Date | 2016-01-04 11:10 +0100 |
| Message-ID | <qNafo-23H-13@gated-at.bofh.it> |
| In reply to | #1299771 |
On Fri, Jan 1, 2016 at 3:49 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> On Wed, Dec 30, 2015 at 09:41:45AM -0800, Paul E. McKenney wrote:
>> On Wed, Dec 30, 2015 at 03:03:33PM +0800, Aaron Ma wrote:
>> > On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
>> > <paulmck@linux.vnet.ibm.com> wrote:
>
> [ . . . ]
>
>> > 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:
>> > 71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
>> > (detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
>> > Task dump for CPU 71:
>> > swapper/71 R running task 0 0 1 0x00200000
>> > ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
>> > 0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
>> > ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
>> > Call Trace:
>> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff814f21d7>] ? intel_idle+0x137/0x140
>> > [<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
>> > [<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
>> > [<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
>> > [<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
>> > rcu_preempt kthread starved for 26002 jiffies!
>> > rcu_check_gp_kthread_starvation --->show task:
>> > rcu_preempt S ffff880456413c68 0 8 2 0x00000000
>> > ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
>> > ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
>> > ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
>> > Call Trace:
>> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
>> > [<ffffffff81b5ce9f>] schedule+0x3f/0xd0
>> > [<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
>> > [<ffffffff810a7904>] ? swait_prepare+0x24/0x90
>> > [<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
>> > [<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
>> > [<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
>> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
>> > [<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
>> > [<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
>> > [<ffffffff8107f844>] kthread+0xe4/0x100
>> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
>> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
>> > [<ffffffff81b61562>] ret_from_fork+0x42/0x70
>> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
>> > rcu_check_gp_kthread_starvation --->end
>> >
>> > It seems wait in rcu_gp_kthread. it should be no task blocked right?
>> > If so, why the swait_event_interruptible_timeout is not awaken? the
>> > timeout is CONFIG_HZ=1000.
>>
>> Given that this happens at boot, perhaps ftrace is a good next step.
>> The thought would be to enable ftrace via the kernel boot parameters
>> for the timers.
>>
>> And how often does this problem occur?
>
> And does the following diagnostic patch help? Its expected behavior
> would be to turn a hard hang into something that recovered in a few
> minutes, while giving a few stall-warning splats.
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> commit 7798a5efb2acabfa3ca788dd9b5b118eb1bff443
> Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> Date: Thu Dec 31 08:48:36 2015 -0800
>
> rcu: Awaken grace-period kthread when stalled
>
> Recent kernels can fail to awaken the grace-period kthread for
> quiescent-state forcing. This commit is a crude hack that does
> a wakeup any time a stall is detected.
>
> Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index 4b3de6718f7c..51da7ef3561f 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -1225,8 +1225,10 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
> rsp->gp_flags,
> gp_state_getname(rsp->gp_state), rsp->gp_state,
> rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
> - if (rsp->gp_kthread)
> + if (rsp->gp_kthread) {
> sched_show_task(rsp->gp_kthread);
> + wake_up_process(rsp->gp_kthread);
> + }
> }
> }
Sorry for late response because of holiday.
During my knowledge, now this issue is splitted to 2 issues.
First, there is a mistake in the kernel I used.
I used kernel is changed by someone else, and it ported a patch:
Author: Thomas Gleixner <tglx@linutronix.de>
Date: Tue Apr 14 21:08:54 2015 +0000
tick: sched: Force tick interrupt and get rid of softirq magic
commit 0ff53d09642204c648424def0caa9117e7a3caaf upstream
static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
ktime_t now, int cpu)
{
@@ -691,22 +705,18 @@ static ktime_t tick_nohz_stop_sched_tick(struct
tick_sched *ts,
if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
hrtimer_cancel(&ts->sched_timer);
goto out;
- }
+ }
- if (ts->nohz_mode == NOHZ_MODE_HIGHRES) {
- hrtimer_start(&ts->sched_timer, expires,
- HRTIMER_MODE_ABS_PINNED);
- goto out;
- } else if (!tick_program_event(expires, 0))
- goto out;
- /*
- * We are past the event already. So we crossed a
- * jiffie boundary. Update jiffies and raise the
- * softirq.
- */
- tick_do_update_jiffies64(ktime_get());
+ if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
+ hrtimer_start(&ts->sched_timer, expires,
+ HRTIMER_MODE_ABS_PINNED);
+ else
+ tick_program_event(expires, 1);
+ } else {
+ /* Tick is stopped, but required now. Enforce it */
+ tick_nohz_restart(ts, now);
}
- raise_softirq_irqoff(TIMER_SOFTIRQ);
+
It remove the "raise_softirq_irqoff" in tick_nohz_stop_sched_tick, so
the kernel will be not waked up in idle status.
Second:
The reason I thought linux-stable-rt has the same issue because of it
has a boot issue during systemd init:
mce: [Hardware Error]: PROCESSOR 0:406f0 TIME 1451543174 SOCKET 1 APIC
40 microcode 10
0000000000000000 ffff880468a0c420 ffff880468a08f58
Call Trace:
mce: [Hardware Error]: Run the above through 'mcelog --ascii'
mce: [Hardware Error]: CPU 22: Machine Check Exception: 0 Bank 20:
c800008000310e0f
mce: [Hardware Error]: TSC 0 MISC df87b008d9eff
mce: [Hardware Error]: PROCESSOR 0:406f0 TIME 1451543174 SOCKET 1 APIC
40 microcode 10
mce: [Hardware Error]: Run the above through 'mcelog --ascii'
<IRQ> [<ffffffff81b56b53>] dump_stack+0x4a/0x61
Kernel panic - not syncing: Timeout: Not all CPUs entered broadcast
exception handler
[<ffffffff81058a6a>] warn_slowpath_common+0x8a/0xe0
[<ffffffff81058b7a>] warn_slowpath_null+0x1a/0x20
[<ffffffff810dafee>] rcu_eqs_exit_common+0x2be/0x550
[<ffffffff810e32fc>] rcu_irq_enter+0xfc/0x330
[<ffffffff8105f25e>] irq_enter+0xe/0x60
[<ffffffff81b63a87>] smp_apic_timer_interrupt+0x37/0x60
[<ffffffff81b62030>] apic_timer_interrupt+0x70/0x80
<EOI> <#MC> [<ffffffff81b53b2b>] ? wait_for_panic+0x1a/0x54
[<ffffffff81b53b31>] ? wait_for_panic+0x20/0x54
[<ffffffff81b53b2b>] ? wait_for_panic+0x1a/0x54
[<ffffffff8102f62e>] mce_timed_out+0x7e/0x80
[<ffffffff81030887>] do_machine_check+0x737/0xa50
[<ffffffff814f2191>] ? intel_idle+0xd1/0x140
[<ffffffff81b62e1b>] machine_check+0x2b/0x50
[<ffffffff814f2191>] ? intel_idle+0xd1/0x140
<<EOE>> [<ffffffff8181dba5>] cpuidle_enter_state+0x65/0x3e0
[<ffffffff8181df57>] cpuidle_enter+0x17/0x20
[<ffffffff810a849d>] cpu_startup_entry+0x33d/0x630
[<ffffffff8103ceae>] start_secondary+0x12e/0x140
---[ end trace 0000000000000002 ]---
I didn't know what's the problem here, so I thought it is caused by
the same issue.
Now with 1st issue resolved, I am digging the "mce hardware error".
Do you think this is a hardware issue?
Thank you very much for your help.
Pengyu
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-01-04 22:20 +0100 |
| Message-ID | <qNkHL-sc-1@gated-at.bofh.it> |
| In reply to | #1300597 |
On Mon, Jan 04, 2016 at 06:01:37PM +0800, Aaron Ma wrote:
> On Fri, Jan 1, 2016 at 3:49 AM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> > On Wed, Dec 30, 2015 at 09:41:45AM -0800, Paul E. McKenney wrote:
> >> On Wed, Dec 30, 2015 at 03:03:33PM +0800, Aaron Ma wrote:
> >> > On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
> >> > <paulmck@linux.vnet.ibm.com> wrote:
> >
> > [ . . . ]
> >
> >> > 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:
> >> > 71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
> >> > (detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
> >> > Task dump for CPU 71:
> >> > swapper/71 R running task 0 0 1 0x00200000
> >> > ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
> >> > 0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
> >> > ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
> >> > Call Trace:
> >> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff814f21d7>] ? intel_idle+0x137/0x140
> >> > [<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
> >> > [<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
> >> > [<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
> >> > [<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
> >> > rcu_preempt kthread starved for 26002 jiffies!
> >> > rcu_check_gp_kthread_starvation --->show task:
> >> > rcu_preempt S ffff880456413c68 0 8 2 0x00000000
> >> > ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
> >> > ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
> >> > ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
> >> > Call Trace:
> >> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> >> > [<ffffffff81b5ce9f>] schedule+0x3f/0xd0
> >> > [<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
> >> > [<ffffffff810a7904>] ? swait_prepare+0x24/0x90
> >> > [<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
> >> > [<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
> >> > [<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
> >> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> >> > [<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
> >> > [<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
> >> > [<ffffffff8107f844>] kthread+0xe4/0x100
> >> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> >> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> >> > [<ffffffff81b61562>] ret_from_fork+0x42/0x70
> >> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> >> > rcu_check_gp_kthread_starvation --->end
> >> >
> >> > It seems wait in rcu_gp_kthread. it should be no task blocked right?
> >> > If so, why the swait_event_interruptible_timeout is not awaken? the
> >> > timeout is CONFIG_HZ=1000.
> >>
> >> Given that this happens at boot, perhaps ftrace is a good next step.
> >> The thought would be to enable ftrace via the kernel boot parameters
> >> for the timers.
> >>
> >> And how often does this problem occur?
> >
> > And does the following diagnostic patch help? Its expected behavior
> > would be to turn a hard hang into something that recovered in a few
> > minutes, while giving a few stall-warning splats.
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > commit 7798a5efb2acabfa3ca788dd9b5b118eb1bff443
> > Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> > Date: Thu Dec 31 08:48:36 2015 -0800
> >
> > rcu: Awaken grace-period kthread when stalled
> >
> > Recent kernels can fail to awaken the grace-period kthread for
> > quiescent-state forcing. This commit is a crude hack that does
> > a wakeup any time a stall is detected.
> >
> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> >
> > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > index 4b3de6718f7c..51da7ef3561f 100644
> > --- a/kernel/rcu/tree.c
> > +++ b/kernel/rcu/tree.c
> > @@ -1225,8 +1225,10 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
> > rsp->gp_flags,
> > gp_state_getname(rsp->gp_state), rsp->gp_state,
> > rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
> > - if (rsp->gp_kthread)
> > + if (rsp->gp_kthread) {
> > sched_show_task(rsp->gp_kthread);
> > + wake_up_process(rsp->gp_kthread);
> > + }
> > }
> > }
>
> Sorry for late response because of holiday.
>
> During my knowledge, now this issue is splitted to 2 issues.
>
> First, there is a mistake in the kernel I used.
> I used kernel is changed by someone else, and it ported a patch:
> Author: Thomas Gleixner <tglx@linutronix.de>
> Date: Tue Apr 14 21:08:54 2015 +0000
>
> tick: sched: Force tick interrupt and get rid of softirq magic
>
> commit 0ff53d09642204c648424def0caa9117e7a3caaf upstream
>
> static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> ktime_t now, int cpu)
> {
> @@ -691,22 +705,18 @@ static ktime_t tick_nohz_stop_sched_tick(struct
> tick_sched *ts,
> if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
> hrtimer_cancel(&ts->sched_timer);
> goto out;
> - }
> + }
>
> - if (ts->nohz_mode == NOHZ_MODE_HIGHRES) {
> - hrtimer_start(&ts->sched_timer, expires,
> - HRTIMER_MODE_ABS_PINNED);
> - goto out;
> - } else if (!tick_program_event(expires, 0))
> - goto out;
> - /*
> - * We are past the event already. So we crossed a
> - * jiffie boundary. Update jiffies and raise the
> - * softirq.
> - */
> - tick_do_update_jiffies64(ktime_get());
> + if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
> + hrtimer_start(&ts->sched_timer, expires,
> + HRTIMER_MODE_ABS_PINNED);
> + else
> + tick_program_event(expires, 1);
> + } else {
> + /* Tick is stopped, but required now. Enforce it */
> + tick_nohz_restart(ts, now);
> }
> - raise_softirq_irqoff(TIMER_SOFTIRQ);
> +
>
> It remove the "raise_softirq_irqoff" in tick_nohz_stop_sched_tick, so
> the kernel will be not waked up in idle status.
>
> Second:
> The reason I thought linux-stable-rt has the same issue because of it
> has a boot issue during systemd init:
> mce: [Hardware Error]: PROCESSOR 0:406f0 TIME 1451543174 SOCKET 1 APIC
> 40 microcode 10
> 0000000000000000 ffff880468a0c420 ffff880468a08f58
> Call Trace:
> mce: [Hardware Error]: Run the above through 'mcelog --ascii'
> mce: [Hardware Error]: CPU 22: Machine Check Exception: 0 Bank 20:
> c800008000310e0f
> mce: [Hardware Error]: TSC 0 MISC df87b008d9eff
> mce: [Hardware Error]: PROCESSOR 0:406f0 TIME 1451543174 SOCKET 1 APIC
> 40 microcode 10
> mce: [Hardware Error]: Run the above through 'mcelog --ascii'
> <IRQ> [<ffffffff81b56b53>] dump_stack+0x4a/0x61
> Kernel panic - not syncing: Timeout: Not all CPUs entered broadcast
> exception handler
> [<ffffffff81058a6a>] warn_slowpath_common+0x8a/0xe0
> [<ffffffff81058b7a>] warn_slowpath_null+0x1a/0x20
> [<ffffffff810dafee>] rcu_eqs_exit_common+0x2be/0x550
> [<ffffffff810e32fc>] rcu_irq_enter+0xfc/0x330
> [<ffffffff8105f25e>] irq_enter+0xe/0x60
> [<ffffffff81b63a87>] smp_apic_timer_interrupt+0x37/0x60
> [<ffffffff81b62030>] apic_timer_interrupt+0x70/0x80
> <EOI> <#MC> [<ffffffff81b53b2b>] ? wait_for_panic+0x1a/0x54
> [<ffffffff81b53b31>] ? wait_for_panic+0x20/0x54
> [<ffffffff81b53b2b>] ? wait_for_panic+0x1a/0x54
> [<ffffffff8102f62e>] mce_timed_out+0x7e/0x80
> [<ffffffff81030887>] do_machine_check+0x737/0xa50
> [<ffffffff814f2191>] ? intel_idle+0xd1/0x140
> [<ffffffff81b62e1b>] machine_check+0x2b/0x50
> [<ffffffff814f2191>] ? intel_idle+0xd1/0x140
> <<EOE>> [<ffffffff8181dba5>] cpuidle_enter_state+0x65/0x3e0
> [<ffffffff8181df57>] cpuidle_enter+0x17/0x20
> [<ffffffff810a849d>] cpu_startup_entry+0x33d/0x630
> [<ffffffff8103ceae>] start_secondary+0x12e/0x140
> ---[ end trace 0000000000000002 ]---
>
> I didn't know what's the problem here, so I thought it is caused by
> the same issue.
>
> Now with 1st issue resolved, I am digging the "mce hardware error".
> Do you think this is a hardware issue?
I cannot claim to be an MCE expert. But I am curious. What do you get
when you run the lines through "mcelog --ascii" like it suggests?
Thanx, Paul
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Aaron Ma <mapengyu@gmail.com> |
|---|---|
| Date | 2016-01-05 09:00 +0100 |
| Message-ID | <qNuH8-7ob-3@gated-at.bofh.it> |
| In reply to | #1301100 |
On Tue, Jan 5, 2016 at 5:18 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> On Mon, Jan 04, 2016 at 06:01:37PM +0800, Aaron Ma wrote:
>> On Fri, Jan 1, 2016 at 3:49 AM, Paul E. McKenney
>> <paulmck@linux.vnet.ibm.com> wrote:
>> > On Wed, Dec 30, 2015 at 09:41:45AM -0800, Paul E. McKenney wrote:
>> >> On Wed, Dec 30, 2015 at 03:03:33PM +0800, Aaron Ma wrote:
>> >> > On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
>> >> > <paulmck@linux.vnet.ibm.com> wrote:
>> >
>> > [ . . . ]
>> >
>> >> > 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:
>> >> > 71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
>> >> > (detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
>> >> > Task dump for CPU 71:
>> >> > swapper/71 R running task 0 0 1 0x00200000
>> >> > ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
>> >> > 0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
>> >> > ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
>> >> > Call Trace:
>> >> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
>> >> > [<ffffffff814f21d7>] ? intel_idle+0x137/0x140
>> >> > [<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
>> >> > [<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
>> >> > [<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
>> >> > [<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
>> >> > rcu_preempt kthread starved for 26002 jiffies!
>> >> > rcu_check_gp_kthread_starvation --->show task:
>> >> > rcu_preempt S ffff880456413c68 0 8 2 0x00000000
>> >> > ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
>> >> > ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
>> >> > ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
>> >> > Call Trace:
>> >> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
>> >> > [<ffffffff81b5ce9f>] schedule+0x3f/0xd0
>> >> > [<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
>> >> > [<ffffffff810a7904>] ? swait_prepare+0x24/0x90
>> >> > [<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
>> >> > [<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
>> >> > [<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
>> >> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
>> >> > [<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
>> >> > [<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
>> >> > [<ffffffff8107f844>] kthread+0xe4/0x100
>> >> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
>> >> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
>> >> > [<ffffffff81b61562>] ret_from_fork+0x42/0x70
>> >> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
>> >> > rcu_check_gp_kthread_starvation --->end
>> >> >
>> >> > It seems wait in rcu_gp_kthread. it should be no task blocked right?
>> >> > If so, why the swait_event_interruptible_timeout is not awaken? the
>> >> > timeout is CONFIG_HZ=1000.
>> >>
>> >> Given that this happens at boot, perhaps ftrace is a good next step.
>> >> The thought would be to enable ftrace via the kernel boot parameters
>> >> for the timers.
>> >>
>> >> And how often does this problem occur?
>> >
>> > And does the following diagnostic patch help? Its expected behavior
>> > would be to turn a hard hang into something that recovered in a few
>> > minutes, while giving a few stall-warning splats.
>> >
>> > Thanx, Paul
>> >
>> > ------------------------------------------------------------------------
>> >
>> > commit 7798a5efb2acabfa3ca788dd9b5b118eb1bff443
>> > Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>> > Date: Thu Dec 31 08:48:36 2015 -0800
>> >
>> > rcu: Awaken grace-period kthread when stalled
>> >
>> > Recent kernels can fail to awaken the grace-period kthread for
>> > quiescent-state forcing. This commit is a crude hack that does
>> > a wakeup any time a stall is detected.
>> >
>> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>> >
>> > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
>> > index 4b3de6718f7c..51da7ef3561f 100644
>> > --- a/kernel/rcu/tree.c
>> > +++ b/kernel/rcu/tree.c
>> > @@ -1225,8 +1225,10 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
>> > rsp->gp_flags,
>> > gp_state_getname(rsp->gp_state), rsp->gp_state,
>> > rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
>> > - if (rsp->gp_kthread)
>> > + if (rsp->gp_kthread) {
>> > sched_show_task(rsp->gp_kthread);
>> > + wake_up_process(rsp->gp_kthread);
>> > + }
>> > }
>> > }
>>
>> Sorry for late response because of holiday.
>>
>> During my knowledge, now this issue is splitted to 2 issues.
>>
>> First, there is a mistake in the kernel I used.
>> I used kernel is changed by someone else, and it ported a patch:
>> Author: Thomas Gleixner <tglx@linutronix.de>
>> Date: Tue Apr 14 21:08:54 2015 +0000
>>
>> tick: sched: Force tick interrupt and get rid of softirq magic
>>
>> commit 0ff53d09642204c648424def0caa9117e7a3caaf upstream
>>
>> static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
>> ktime_t now, int cpu)
>> {
>> @@ -691,22 +705,18 @@ static ktime_t tick_nohz_stop_sched_tick(struct
>> tick_sched *ts,
>> if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
>> hrtimer_cancel(&ts->sched_timer);
>> goto out;
>> - }
>> + }
>>
>> - if (ts->nohz_mode == NOHZ_MODE_HIGHRES) {
>> - hrtimer_start(&ts->sched_timer, expires,
>> - HRTIMER_MODE_ABS_PINNED);
>> - goto out;
>> - } else if (!tick_program_event(expires, 0))
>> - goto out;
>> - /*
>> - * We are past the event already. So we crossed a
>> - * jiffie boundary. Update jiffies and raise the
>> - * softirq.
>> - */
>> - tick_do_update_jiffies64(ktime_get());
>> + if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
>> + hrtimer_start(&ts->sched_timer, expires,
>> + HRTIMER_MODE_ABS_PINNED);
>> + else
>> + tick_program_event(expires, 1);
>> + } else {
>> + /* Tick is stopped, but required now. Enforce it */
>> + tick_nohz_restart(ts, now);
>> }
>> - raise_softirq_irqoff(TIMER_SOFTIRQ);
>> +
>>
>> It remove the "raise_softirq_irqoff" in tick_nohz_stop_sched_tick, so
>> the kernel will be not waked up in idle status.
>>
>> Second:
>> The reason I thought linux-stable-rt has the same issue because of it
>> has a boot issue during systemd init:
>> mce: [Hardware Error]: PROCESSOR 0:406f0 TIME 1451543174 SOCKET 1 APIC
>> 40 microcode 10
>> 0000000000000000 ffff880468a0c420 ffff880468a08f58
>> Call Trace:
>> mce: [Hardware Error]: Run the above through 'mcelog --ascii'
>> mce: [Hardware Error]: CPU 22: Machine Check Exception: 0 Bank 20:
>> c800008000310e0f
>> mce: [Hardware Error]: TSC 0 MISC df87b008d9eff
>> mce: [Hardware Error]: PROCESSOR 0:406f0 TIME 1451543174 SOCKET 1 APIC
>> 40 microcode 10
>> mce: [Hardware Error]: Run the above through 'mcelog --ascii'
>> <IRQ> [<ffffffff81b56b53>] dump_stack+0x4a/0x61
>> Kernel panic - not syncing: Timeout: Not all CPUs entered broadcast
>> exception handler
>> [<ffffffff81058a6a>] warn_slowpath_common+0x8a/0xe0
>> [<ffffffff81058b7a>] warn_slowpath_null+0x1a/0x20
>> [<ffffffff810dafee>] rcu_eqs_exit_common+0x2be/0x550
>> [<ffffffff810e32fc>] rcu_irq_enter+0xfc/0x330
>> [<ffffffff8105f25e>] irq_enter+0xe/0x60
>> [<ffffffff81b63a87>] smp_apic_timer_interrupt+0x37/0x60
>> [<ffffffff81b62030>] apic_timer_interrupt+0x70/0x80
>> <EOI> <#MC> [<ffffffff81b53b2b>] ? wait_for_panic+0x1a/0x54
>> [<ffffffff81b53b31>] ? wait_for_panic+0x20/0x54
>> [<ffffffff81b53b2b>] ? wait_for_panic+0x1a/0x54
>> [<ffffffff8102f62e>] mce_timed_out+0x7e/0x80
>> [<ffffffff81030887>] do_machine_check+0x737/0xa50
>> [<ffffffff814f2191>] ? intel_idle+0xd1/0x140
>> [<ffffffff81b62e1b>] machine_check+0x2b/0x50
>> [<ffffffff814f2191>] ? intel_idle+0xd1/0x140
>> <<EOE>> [<ffffffff8181dba5>] cpuidle_enter_state+0x65/0x3e0
>> [<ffffffff8181df57>] cpuidle_enter+0x17/0x20
>> [<ffffffff810a849d>] cpu_startup_entry+0x33d/0x630
>> [<ffffffff8103ceae>] start_secondary+0x12e/0x140
>> ---[ end trace 0000000000000002 ]---
>>
>> I didn't know what's the problem here, so I thought it is caused by
>> the same issue.
>>
>> Now with 1st issue resolved, I am digging the "mce hardware error".
>> Do you think this is a hardware issue?
>
> I cannot claim to be an MCE expert. But I am curious. What do you get
> when you run the lines through "mcelog --ascii" like it suggests?
Yes, understood.
There is no chance to do "mcelog" because of the system hang.
Pengyu
>
> Thanx, Paul
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-01-05 20:20 +0100 |
| Message-ID | <qNFjd-7by-27@gated-at.bofh.it> |
| In reply to | #1301315 |
On Tue, Jan 05, 2016 at 03:57:54PM +0800, Aaron Ma wrote:
> On Tue, Jan 5, 2016 at 5:18 AM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> > On Mon, Jan 04, 2016 at 06:01:37PM +0800, Aaron Ma wrote:
> >> On Fri, Jan 1, 2016 at 3:49 AM, Paul E. McKenney
> >> <paulmck@linux.vnet.ibm.com> wrote:
> >> > On Wed, Dec 30, 2015 at 09:41:45AM -0800, Paul E. McKenney wrote:
> >> >> On Wed, Dec 30, 2015 at 03:03:33PM +0800, Aaron Ma wrote:
> >> >> > On Wed, Dec 30, 2015 at 7:42 AM, Paul E. McKenney
> >> >> > <paulmck@linux.vnet.ibm.com> wrote:
> >> >
> >> > [ . . . ]
> >> >
> >> >> > 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:
> >> >> > 71: (0 ticks this GP) idle=1ac/0/0 softirq=0/0 fqs=0
> >> >> > (detected by 62, t=26002 jiffies, g=3735, c=3734, q=366014)
> >> >> > Task dump for CPU 71:
> >> >> > swapper/71 R running task 0 0 1 0x00200000
> >> >> > ffffffff81492587 ffff8804633cbe58 ffffffff814f21d7 0000000000000004
> >> >> > 0000000000000004 ffffe8fffb405310 ffffffff820dc5c0 ffff8804633cbea8
> >> >> > ffffffff8181db85 0000000000000000 0000000000000000 0000000000000046
> >> >> > Call Trace:
> >> >> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> >> >> > [<ffffffff814f21d7>] ? intel_idle+0x137/0x140
> >> >> > [<ffffffff8181db85>] ? cpuidle_enter_state+0x65/0x3e0
> >> >> > [<ffffffff8181df37>] ? cpuidle_enter+0x17/0x20
> >> >> > [<ffffffff810a849d>] ? cpu_startup_entry+0x33d/0x630
> >> >> > [<ffffffff8103ceae>] ? start_secondary+0x12e/0x140
> >> >> > rcu_preempt kthread starved for 26002 jiffies!
> >> >> > rcu_check_gp_kthread_starvation --->show task:
> >> >> > rcu_preempt S ffff880456413c68 0 8 2 0x00000000
> >> >> > ffff880456413c68 ffff8804564025d0 000000000000d7a0 ffff880456b18000
> >> >> > ffff8804564025d0 ffff880456413c38 ffffffff81492587 ffff880456413c58
> >> >> > ffff880456414000 ffff8804564025d0 ffff880456413cb8 ffff880869dce500
> >> >> > Call Trace:
> >> >> > [<ffffffff81492587>] ? debug_smp_processor_id+0x17/0x20
> >> >> > [<ffffffff81b5ce9f>] schedule+0x3f/0xd0
> >> >> > [<ffffffff81b5ef19>] schedule_timeout+0x189/0x3f0
> >> >> > [<ffffffff810a7904>] ? swait_prepare+0x24/0x90
> >> >> > [<ffffffff810e8e60>] ? timer_cpu_notify+0x190/0x190
> >> >> > [<ffffffff810a793b>] ? swait_prepare+0x5b/0x90
> >> >> > [<ffffffff810de3f8>] rcu_gp_kthread+0x8a8/0x2190
> >> >> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> >> >> > [<ffffffff81b5c18f>] ? __schedule+0x4af/0x1180
> >> >> > [<ffffffff810ddb50>] ? call_rcu_sched+0x20/0x20
> >> >> > [<ffffffff8107f844>] kthread+0xe4/0x100
> >> >> > [<ffffffff810b275d>] ? trace_hardirqs_on+0xd/0x10
> >> >> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> >> >> > [<ffffffff81b61562>] ret_from_fork+0x42/0x70
> >> >> > [<ffffffff8107f760>] ? kthread_create_on_node+0x240/0x240
> >> >> > rcu_check_gp_kthread_starvation --->end
> >> >> >
> >> >> > It seems wait in rcu_gp_kthread. it should be no task blocked right?
> >> >> > If so, why the swait_event_interruptible_timeout is not awaken? the
> >> >> > timeout is CONFIG_HZ=1000.
> >> >>
> >> >> Given that this happens at boot, perhaps ftrace is a good next step.
> >> >> The thought would be to enable ftrace via the kernel boot parameters
> >> >> for the timers.
> >> >>
> >> >> And how often does this problem occur?
> >> >
> >> > And does the following diagnostic patch help? Its expected behavior
> >> > would be to turn a hard hang into something that recovered in a few
> >> > minutes, while giving a few stall-warning splats.
> >> >
> >> > Thanx, Paul
> >> >
> >> > ------------------------------------------------------------------------
> >> >
> >> > commit 7798a5efb2acabfa3ca788dd9b5b118eb1bff443
> >> > Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> >> > Date: Thu Dec 31 08:48:36 2015 -0800
> >> >
> >> > rcu: Awaken grace-period kthread when stalled
> >> >
> >> > Recent kernels can fail to awaken the grace-period kthread for
> >> > quiescent-state forcing. This commit is a crude hack that does
> >> > a wakeup any time a stall is detected.
> >> >
> >> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> >> >
> >> > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> >> > index 4b3de6718f7c..51da7ef3561f 100644
> >> > --- a/kernel/rcu/tree.c
> >> > +++ b/kernel/rcu/tree.c
> >> > @@ -1225,8 +1225,10 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
> >> > rsp->gp_flags,
> >> > gp_state_getname(rsp->gp_state), rsp->gp_state,
> >> > rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
> >> > - if (rsp->gp_kthread)
> >> > + if (rsp->gp_kthread) {
> >> > sched_show_task(rsp->gp_kthread);
> >> > + wake_up_process(rsp->gp_kthread);
> >> > + }
> >> > }
> >> > }
> >>
> >> Sorry for late response because of holiday.
> >>
> >> During my knowledge, now this issue is splitted to 2 issues.
> >>
> >> First, there is a mistake in the kernel I used.
> >> I used kernel is changed by someone else, and it ported a patch:
> >> Author: Thomas Gleixner <tglx@linutronix.de>
> >> Date: Tue Apr 14 21:08:54 2015 +0000
> >>
> >> tick: sched: Force tick interrupt and get rid of softirq magic
> >>
> >> commit 0ff53d09642204c648424def0caa9117e7a3caaf upstream
> >>
> >> static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> >> ktime_t now, int cpu)
> >> {
> >> @@ -691,22 +705,18 @@ static ktime_t tick_nohz_stop_sched_tick(struct
> >> tick_sched *ts,
> >> if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
> >> hrtimer_cancel(&ts->sched_timer);
> >> goto out;
> >> - }
> >> + }
> >>
> >> - if (ts->nohz_mode == NOHZ_MODE_HIGHRES) {
> >> - hrtimer_start(&ts->sched_timer, expires,
> >> - HRTIMER_MODE_ABS_PINNED);
> >> - goto out;
> >> - } else if (!tick_program_event(expires, 0))
> >> - goto out;
> >> - /*
> >> - * We are past the event already. So we crossed a
> >> - * jiffie boundary. Update jiffies and raise the
> >> - * softirq.
> >> - */
> >> - tick_do_update_jiffies64(ktime_get());
> >> + if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
> >> + hrtimer_start(&ts->sched_timer, expires,
> >> + HRTIMER_MODE_ABS_PINNED);
> >> + else
> >> + tick_program_event(expires, 1);
> >> + } else {
> >> + /* Tick is stopped, but required now. Enforce it */
> >> + tick_nohz_restart(ts, now);
> >> }
> >> - raise_softirq_irqoff(TIMER_SOFTIRQ);
> >> +
> >>
> >> It remove the "raise_softirq_irqoff" in tick_nohz_stop_sched_tick, so
> >> the kernel will be not waked up in idle status.
By the way, this was a nice hint, but unfortunately did not pan out.
I don't see the problem on all NO_HZ_FULL scenarios, and do see it on
some non-NO_HZ_FULL scenarios. :-/
Thanx, Paul
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web