Re: frequent lockups in 3.18rc4
From: Dave Jones
Date: Fri Dec 12 2014 - 09:39:47 EST
On Thu, Dec 11, 2014 at 11:45:09PM -0500, Dave Jones wrote:
> I've seen those messages a fair bit on other machines do, and they drive me nuts
> because there's no 'perf' being run. I think it means "NMI watchdog", but is
> worded badly. Still, it's curious that they appeared during what should have
> been idle time.
>
> I'll reboot the box and give it another shot, and see what falls out in the morning.
Same deal again. It happened pretty quick after I'd gone to bed (typical).
[ 2754.509747] Clocksource tsc unstable (delta = -243594587656 ns)
[ 2754.519197] Switched to clocksource hpet
[ 2754.782940] INFO: rcu_preempt self-detected stall on CPU
[ 2754.782972] 0: (1 GPs behind) idle=6ef/140000000000001/0 softirq=247160/247161
[ 2754.782999] (t=24343 jiffies g=104086 c=104085 q=0)
[ 2754.783022] Task dump for CPU 0:
[ 2754.783037] trinity-c387 R running task 14016 13658 12780 0x00000008
[ 2754.783070] ffff880222365bc0 000000005ed04994 ffff880244003d68 ffffffff810a8d46
[ 2754.783104] ffffffff810a8cb2 0000000000000000 0000000000000001 0000000000000000
[ 2754.783138] ffffffff81c51e40 0000000000000092 ffff880244003d88 ffffffff810acf4d
[ 2754.783171] Call Trace:
[ 2754.783184] <IRQ> [<ffffffff810a8d46>] sched_show_task+0x116/0x180
[ 2754.783215] [<ffffffff810a8cb2>] ? sched_show_task+0x82/0x180
[ 2754.783239] [<ffffffff810acf4d>] dump_cpu_task+0x3d/0x50
[ 2754.783261] [<ffffffff810dc0c0>] rcu_dump_cpu_stacks+0x90/0xd0
[ 2754.783286] [<ffffffff810e3db3>] rcu_check_callbacks+0x573/0x850
[ 2754.783311] [<ffffffff8138cb43>] ? __this_cpu_preempt_check+0x13/0x20
[ 2754.783337] [<ffffffff810ec043>] ? hrtimer_run_queues+0x43/0x130
[ 2754.783361] [<ffffffff810ea5eb>] update_process_times+0x4b/0x80
[ 2754.783386] [<ffffffff810fb2cc>] tick_sched_timer+0x4c/0x1b0
[ 2754.783409] [<ffffffff810eb5db>] ? __run_hrtimer+0xbb/0x2e0
[ 2754.783432] [<ffffffff810eb5db>] __run_hrtimer+0xbb/0x2e0
[ 2754.783454] [<ffffffff810eb984>] ? hrtimer_interrupt+0x94/0x260
[ 2754.783478] [<ffffffff810fb280>] ? tick_init_highres+0x20/0x20
[ 2754.783501] [<ffffffff810eb9f7>] hrtimer_interrupt+0x107/0x260
[ 2754.783526] [<ffffffff81033258>] local_apic_timer_interrupt+0x38/0x70
[ 2754.783552] [<ffffffff817e16f5>] smp_apic_timer_interrupt+0x45/0x60
[ 2754.783578] [<ffffffff817dfadf>] apic_timer_interrupt+0x6f/0x80
[ 2754.783600] <EOI> [<ffffffff810c541d>] ? lock_release_holdtime.part.24+0x9d/0x160
[ 2754.783634] [<ffffffff810c50fe>] ? put_lock_stats.isra.23+0xe/0x30
[ 2754.783659] [<ffffffff8118524c>] ? __alloc_pages_nodemask+0x1ac/0xb60
[ 2754.783684] [<ffffffff811cf4be>] ? alloc_pages_vma+0xee/0x1b0
[ 2754.783708] [<ffffffff810ad575>] ? local_clock+0x25/0x30
[ 2754.783731] [<ffffffff810c6e2c>] ? __lock_acquire.isra.31+0x22c/0x9f0
[ 2754.783756] [<ffffffff810a73e1>] ? get_parent_ip+0x11/0x50
[ 2754.783779] [<ffffffff810c541d>] ? lock_release_holdtime.part.24+0x9d/0x160
[ 2754.784613] [<ffffffff811cf4be>] alloc_pages_vma+0xee/0x1b0
[ 2754.785452] [<ffffffff811aa21a>] ? do_wp_page+0xca/0x7d0
[ 2754.786305] [<ffffffff811aa21a>] do_wp_page+0xca/0x7d0
[ 2754.787140] [<ffffffff811acb6b>] handle_mm_fault+0x6cb/0xe90
[ 2754.787948] [<ffffffff81042b20>] ? __do_page_fault+0x140/0x600
[ 2754.788748] [<ffffffff81042b84>] __do_page_fault+0x1a4/0x600
[ 2754.789562] [<ffffffff810c50fe>] ? put_lock_stats.isra.23+0xe/0x30
[ 2754.790340] [<ffffffff810c541d>] ? lock_release_holdtime.part.24+0x9d/0x160
[ 2754.791113] [<ffffffff810a73e1>] ? get_parent_ip+0x11/0x50
[ 2754.791879] [<ffffffff810a755b>] ? preempt_count_sub+0x7b/0x100
[ 2754.792646] [<ffffffff8137fa0d>] ? trace_hardirqs_off_thunk+0x3a/0x3f
[ 2754.793413] [<ffffffff81042fec>] do_page_fault+0xc/0x10
[ 2754.794176] [<ffffffff817e0862>] page_fault+0x22/0x30
[ 2754.794938] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 2754.795736] Tasks blocked on level-0 rcu_node (CPUs 0-7):
[ 2754.796528] 0: (1 GPs behind) idle=6ef/140000000000001/0 softirq=247160/247161
[ 2754.797334] Tasks blocked on level-0 rcu_node (CPUs 0-7):
[ 2754.798153] (detected by 3, t=24343 jiffies, g=104086, c=104085, q=0)
[ 2754.798981] Task dump for CPU 0:
[ 2754.799797] trinity-c387 R running task 14016 13658 12780 0x00000008
[ 2754.800630] ffff880222365bc0 0000000000000246 0000000127e77e08 8000000000000865
[ 2754.801461] ffff8802000000a9 800000008d044865 0000000000000000 ffff8802256d3c70
[ 2754.802288] ffff880227e77e28 00000000000000a9 0000000000d8eff8 ffff880227e77f58
[ 2754.803109] Call Trace:
[ 2754.803929] [<ffffffff81042b84>] ? __do_page_fault+0x1a4/0x600
[ 2754.804765] [<ffffffff810c50fe>] ? put_lock_stats.isra.23+0xe/0x30
[ 2754.805596] [<ffffffff810c541d>] ? lock_release_holdtime.part.24+0x9d/0x160
[ 2754.806444] [<ffffffff810a73e1>] ? get_parent_ip+0x11/0x50
[ 2754.807267] [<ffffffff810a755b>] ? preempt_count_sub+0x7b/0x100
[ 2754.808088] [<ffffffff8137fa0d>] ? trace_hardirqs_off_thunk+0x3a/0x3f
[ 2754.808920] [<ffffffff81042fec>] ? do_page_fault+0xc/0x10
[ 2754.809742] [<ffffffff817e0862>] ? page_fault+0x22/0x30
[ 2771.561356] ------------[ cut here ]------------
[ 2771.562079] WARNING: CPU: 0 PID: 13696 at kernel/watchdog.c:317 watchdog_overflow_callback+0xdd/0x130()
[ 2771.562879] Watchdog detected hard LOCKUP on cpu 0
[ 2771.562895] CPU: 0 PID: 13696 Comm: trinity-c425 Not tainted 3.18.0+ #101
[ 2771.564490] ffffffff81a66315 00000000fce35109 ffff880244005b88 ffffffff817d317e
[ 2771.565315] 0000000000110004 ffff880244005be0 ffff880244005bc8 ffffffff81078a01
[ 2771.566136] 0000000000000000 0000000000000000 0000000000000000 ffff880244005d30
[ 2771.566954] Call Trace:
[ 2771.567759] <NMI> [<ffffffff817d317e>] dump_stack+0x4f/0x7c
[ 2771.568584] [<ffffffff81078a01>] warn_slowpath_common+0x81/0xa0
[ 2771.569405] [<ffffffff81078a75>] warn_slowpath_fmt+0x55/0x70
[ 2771.570253] [<ffffffff8112fea0>] ? restart_watchdog_hrtimer+0x60/0x60
[ 2771.571074] [<ffffffff8112ff7d>] watchdog_overflow_callback+0xdd/0x130
[ 2771.571894] [<ffffffff81173a7c>] __perf_event_overflow+0xac/0x2a0
[ 2771.572721] [<ffffffff81019952>] ? x86_perf_event_set_period+0xe2/0x150
[ 2771.573551] [<ffffffff81174644>] perf_event_overflow+0x14/0x20
[ 2771.574378] [<ffffffff8101f479>] intel_pmu_handle_irq+0x209/0x410
[ 2771.575210] [<ffffffff8101875b>] perf_event_nmi_handler+0x2b/0x50
[ 2771.576040] [<ffffffff81007634>] nmi_handle+0xa4/0x1e0
[ 2771.576868] [<ffffffff81007595>] ? nmi_handle+0x5/0x1e0
[ 2771.577698] [<ffffffff81006de1>] ? print_context_stack+0xe1/0x100
[ 2771.578526] [<ffffffff810079aa>] default_do_nmi+0x7a/0x1d0
[ 2771.579354] [<ffffffff81007bb8>] do_nmi+0xb8/0xf0
[ 2771.580206] [<ffffffff817e0c2a>] end_repeat_nmi+0x1e/0x2e
[ 2771.581023] [<ffffffff817d0f85>] ? free_debug_processing+0x157/0x22a
[ 2771.581836] [<ffffffff817d0f85>] ? free_debug_processing+0x157/0x22a
[ 2771.582644] [<ffffffff81006de1>] ? print_context_stack+0xe1/0x100
[ 2771.583452] [<ffffffff81006de1>] ? print_context_stack+0xe1/0x100
[ 2771.584253] [<ffffffff81006de1>] ? print_context_stack+0xe1/0x100
[ 2771.585042] <<EOE>> [<ffffffff81005710>] dump_trace+0x140/0x370
[ 2771.585841] [<ffffffff812005c6>] ? final_putname+0x26/0x50
[ 2771.586636] [<ffffffff81013ecf>] save_stack_trace+0x2f/0x50
[ 2771.587430] [<ffffffff811d4f20>] set_track+0x70/0x140
[ 2771.588217] [<ffffffff817d0f85>] free_debug_processing+0x157/0x22a
[ 2771.589015] [<ffffffff810c50fe>] ? put_lock_stats.isra.23+0xe/0x30
[ 2771.589815] [<ffffffff817d10ad>] __slab_free+0x55/0x320
[ 2771.590636] [<ffffffff8138e016>] ? debug_check_no_obj_freed+0x156/0x250
[ 2771.591442] [<ffffffff81212294>] ? mntput+0x24/0x40
[ 2771.592242] [<ffffffff811d7fd2>] kmem_cache_free+0x262/0x280
[ 2771.593036] [<ffffffff812005c6>] ? final_putname+0x26/0x50
[ 2771.593831] [<ffffffff812005c6>] final_putname+0x26/0x50
[ 2771.594622] [<ffffffff81200869>] putname+0x29/0x40
[ 2771.595411] [<ffffffff8120166e>] user_path_at_empty+0x6e/0xc0
[ 2771.596199] [<ffffffff81212197>] ? mntput_no_expire+0x67/0x140
[ 2771.596986] [<ffffffff81212135>] ? mntput_no_expire+0x5/0x140
[ 2771.597766] [<ffffffff81207df6>] ? dput+0x56/0x190
[ 2771.598542] [<ffffffff812016d1>] user_path_at+0x11/0x20
[ 2771.599311] [<ffffffff812187ec>] path_setxattr+0x4c/0xe0
[ 2771.600097] [<ffffffff81218a51>] SyS_lsetxattr+0x11/0x20
[ 2771.600848] [<ffffffff817dec12>] system_call_fastpath+0x12/0x17
[ 2771.601598] ---[ end trace 7b78126c55dcb717 ]---
[ 2771.602404] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 40.989 msecs
[ 2771.603175] perf interrupt took too long (322423 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[ 3471.463812] perf interrupt took too long (319933 > 5000), lowering kernel.perf_event_max_sample_rate to 25000
[ 4563.539619] perf interrupt took too long (317460 > 10000), lowering kernel.perf_event_max_sample_rate to 12500
[ 5676.723413] perf interrupt took too long (315015 > 19841), lowering kernel.perf_event_max_sample_rate to 6300
[ 6800.751151] perf interrupt took too long (312583 > 39062), lowering kernel.perf_event_max_sample_rate to 3200
[ 8056.882309] perf interrupt took too long (310176 > 78125), lowering kernel.perf_event_max_sample_rate to 1600
[ 9233.809073] perf interrupt took too long (307790 > 156250), lowering kernel.perf_event_max_sample_rate to 800
again, the box survived. Next run I'll try undoing Chris' idea of no serial,
and see if it wedges after the spew. After that, I'll do a no preempt run.
Dave
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/