Messages in this thread | | | From | Vince Weaver <> | Date | Thu, 19 Feb 2015 11:54:40 -0500 (EST) | Subject | perf: fuzzer gets CPU stuck in perf_callchain() |
| |
Another bug found by the perf_fuzzer(). I think this one is different than the one I sent the other day, it looks like something is going very wrong in perf_callchain().
This one is reasonably reproducible, if there's any extra debugging that I can add. This is on a Haswell machine with git as of a few days ago.
There are two traces below; they were generated by the same random seed across different reboots and the trigger is slightly different (although both look like they hit the same bug in the callchain code).
[ 7938.495396] ------------[ cut here ]------------ [ 7938.500373] WARNING: CPU: 2 PID: 5692 at kernel/watchdog.c:290 watchdog_overflow_callback+0x92/0xc0() [ 7938.510337] Watchdog detected hard LOCKUP on cpu 2 [ 7938.515301] Modules linked in: fuse x86_pkg_temp_thermal intel_powerclamp intel_rapl iosf_mbi coretemp kvm crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi snd_hda_intel snd_hda_controller snd_hda_codec i915 aes_x86_64 lrw gf128mul ppdev iTCO_wdt xhci_pci snd_hwdep snd_pcm tpm_tis evdev glue_helper iTCO_vendor_support xhci_hcd snd_timer mei_me drm_kms_helper ablk_helper snd tpm mei drm psmouse serio_raw pcspkr parport_pc cryptd soundcore lpc_ich parport wmi mfd_core battery i2c_i801 i2c_algo_bit button processor video sg sr_mod sd_mod cdrom ahci libahci ehci_pci libata ehci_hcd e1000e ptp crc32c_intel scsi_mod usbcore usb_common pps_core fan thermal thermal_sys [ 7938.586970] CPU: 2 PID: 5692 Comm: perf_fuzzer Not tainted 3.19.0+ #127 [ 7938.594053] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014 [ 7938.601990] ffffffff81a41afe ffff88011ea85aa0 ffffffff816bfed5 0000000000000000 [ 7938.610056] ffff88011ea85af0 ffff88011ea85ae0 ffffffff8106ddfa 0000000000000000 [ 7938.618102] ffff8801195a1800 0000000000000000 ffff88011ea85c40 ffff88011ea85ef8 [ 7938.626105] Call Trace: [ 7938.628735] <NMI> [<ffffffff816bfed5>] dump_stack+0x45/0x57 [ 7938.634940] [<ffffffff8106ddfa>] warn_slowpath_common+0x8a/0xc0 [ 7938.641394] [<ffffffff8106de76>] warn_slowpath_fmt+0x46/0x50 [ 7938.647566] [<ffffffff8111cde2>] watchdog_overflow_callback+0x92/0xc0 [ 7938.654617] [<ffffffff8115dbe1>] __perf_event_overflow+0x91/0x270 [ 7938.661233] [<ffffffff8102b56a>] ? x86_perf_event_set_period+0xca/0x170 [ 7938.668419] [<ffffffff8115e6c9>] perf_event_overflow+0x19/0x20 [ 7938.674764] [<ffffffff81032a7a>] intel_pmu_handle_irq+0x1ba/0x3a0 [ 7938.681432] [<ffffffff8102a45b>] perf_event_nmi_handler+0x2b/0x50 [ 7938.688055] [<ffffffff81018760>] nmi_handle+0xa0/0x150 [ 7938.693681] [<ffffffff810186c5>] ? nmi_handle+0x5/0x150 [ 7938.699405] [<ffffffff81018a0a>] default_do_nmi+0x4a/0x140 [ 7938.705429] [<ffffffff81018b98>] do_nmi+0x98/0xe0 [ 7938.710573] [<ffffffff816ca3d1>] end_repeat_nmi+0x1e/0x2e [ 7938.716470] [<ffffffff8140b300>] ? copy_from_user_nmi+0x20/0x70 [ 7938.722929] [<ffffffff8140b300>] ? copy_from_user_nmi+0x20/0x70 [ 7938.729386] [<ffffffff8140b300>] ? copy_from_user_nmi+0x20/0x70 [ 7938.735862] <<EOE>> <IRQ> [<ffffffff8102c210>] ? perf_callchain_user+0xd0/0x240 [ 7938.744067] [<ffffffff81161508>] perf_callchain+0x1f8/0x220 [ 7938.750152] [<ffffffff8115da21>] perf_prepare_sample+0x291/0x3c0 [ 7938.756700] [<ffffffff8115dc5e>] __perf_event_overflow+0x10e/0x270 [ 7938.763412] [<ffffffff8115dc29>] ? __perf_event_overflow+0xd9/0x270 [ 7938.770254] [<ffffffff8115e114>] ? perf_tp_event+0xc4/0x210 [ 7938.776302] [<ffffffff8115da7c>] ? perf_prepare_sample+0x2ec/0x3c0 [ 7938.783021] [<ffffffff816ca018>] ? trace_page_fault+0x28/0x30 [ 7938.789319] [<ffffffff8115df89>] perf_swevent_overflow+0xa9/0xe0 [ 7938.795845] [<ffffffff8115e027>] perf_swevent_event+0x67/0x90 [ 7938.802139] [<ffffffff8115e114>] perf_tp_event+0xc4/0x210 [ 7938.808025] [<ffffffff810b7f10>] ? lock_release+0x130/0x260 [ 7938.814132] [<ffffffff810b643f>] ? __lock_acquire.isra.31+0x3af/0xfe0 [ 7938.821124] [<ffffffff811406d8>] ? perf_trace_buf_prepare+0x98/0xf0 [ 7938.827926] [<ffffffff810b4f8a>] ? perf_trace_lock+0x12a/0x160 [ 7938.834291] [<ffffffff81079c05>] ? __sigqueue_alloc+0x5/0x150 [ 7938.840541] [<ffffffff81079d34>] ? __sigqueue_alloc+0x134/0x150 [ 7938.847009] [<ffffffff811406d8>] ? perf_trace_buf_prepare+0x98/0xf0 [ 7938.853835] [<ffffffff8107ba4e>] ? __lock_task_sighand+0x6e/0x110 [ 7938.861174] [<ffffffff810b4f8a>] perf_trace_lock+0x12a/0x160 [ 7938.867972] [<ffffffff8107ba58>] ? __lock_task_sighand+0x78/0x110 [ 7938.875256] [<ffffffff8107bb4d>] ? do_send_sig_info+0x5d/0x80 [ 7938.882197] [<ffffffff810b7f10>] lock_release+0x130/0x260 [ 7938.888754] [<ffffffff816c7474>] _raw_spin_unlock_irqrestore+0x24/0x40 [ 7938.896510] [<ffffffff8107bb4d>] do_send_sig_info+0x5d/0x80 [ 7938.903240] [<ffffffff811f69df>] send_sigio_to_task+0x12f/0x1a0 [ 7938.910365] [<ffffffff811f68b5>] ? send_sigio_to_task+0x5/0x1a0 [ 7938.917455] [<ffffffff811f7176>] ? send_sigio+0x56/0x100 [ 7938.923894] [<ffffffff811f71ce>] send_sigio+0xae/0x100 [ 7938.930132] [<ffffffff811f72b7>] kill_fasync+0x97/0xf0 [ 7938.936359] [<ffffffff811f722f>] ? kill_fasync+0xf/0xf0 [ 7938.942707] [<ffffffff8115d0b4>] perf_event_wakeup+0xd4/0xf0 [ 7938.949522] [<ffffffff8115cfe5>] ? perf_event_wakeup+0x5/0xf0 [ 7938.956367] [<ffffffff8115d103>] perf_pending_event+0x33/0x60 [ 7938.963199] [<ffffffff8114e3fc>] irq_work_run_list+0x4c/0x80 [ 7938.969932] [<ffffffff8114e448>] irq_work_run+0x18/0x40 [ 7938.976212] [<ffffffff810196af>] smp_trace_irq_work_interrupt+0x3f/0xc0 [ 7938.983957] [<ffffffff816c99bd>] trace_irq_work_interrupt+0x6d/0x80 [ 7938.991362] <EOI> [<ffffffff816c743b>] ? _raw_spin_unlock+0x2b/0x40 [ 7938.998883] [<ffffffff810f0993>] ? generic_exec_single+0x133/0x190 [ 7939.006127] [<ffffffff81156100>] ? task_clock_event_add+0x40/0x40 [ 7939.013297] [<ffffffff810f0a57>] smp_call_function_single+0x67/0xa0 [ 7939.020568] [<ffffffff81154d69>] task_function_call+0x49/0x60 [ 7939.027277] [<ffffffff8115b400>] ? perf_event_sched_in+0xa0/0xa0 [ 7939.034270] [<ffffffff81154e10>] _perf_event_enable+0x90/0xf0 [ 7939.040963] [<ffffffff81154d80>] ? task_function_call+0x60/0x60 [ 7939.047863] [<ffffffff81154baf>] perf_event_for_each_child+0x3f/0xb0 [ 7939.055259] [<ffffffff8115c4ac>] perf_event_task_enable+0x7c/0xd0 [ 7939.062321] [<ffffffff81082d4d>] SyS_prctl+0x26d/0x4d0 [ 7939.068359] [<ffffffff816c7ead>] system_call_fastpath+0x16/0x1b [ 7939.075261] ---[ end trace 8e72f55d0f5cbae4 ]--- [ 7939.080732] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 585.271 msecs [ 7939.090016] perf interrupt took too long (4572449 > 5000), lowering kernel.perf_event_max_sample_rate to 25000 [ 7940.065563] INFO: rcu_sched detected stalls on CPUs/tasks: { 2} (detected by 3, t=5252 jiffies, g=10488, c=10487, q=196) [ 7940.077820] Task dump for CPU 2: [ 7940.081779] perf_fuzzer R running task 0 5692 2549 0x0000000c [ 7940.089901] 00007ffff86e99b8 000000000000002b 0000000000000003 ffff8800a4103cd8 [ 7940.098442] ffffffff810b643f ffff88011897a4d0 0000000000000003 ffff88011897a4d0 [ 7940.106955] ffff8800ced65020 ffff8800a4103c98 ffffffff810b52b8 ffff8800a4103cb8 [ 7940.115473] Call Trace: [ 7940.118593] [<ffffffff810b643f>] ? __lock_acquire.isra.31+0x3af/0xfe0 [ 7940.126120] [<ffffffff810b52b8>] ? __lock_is_held+0x58/0x80 [ 7940.132660] [<ffffffff811406d8>] ? perf_trace_buf_prepare+0x98/0xf0 [ 7940.139989] [<ffffffff810b4f8a>] ? perf_trace_lock+0x12a/0x160 [ 7940.146848] [<ffffffff8115b485>] ? __perf_event_enable+0x85/0x2a0 [ 7940.153971] [<ffffffff816c743b>] ? _raw_spin_unlock+0x2b/0x40 [ 7940.160738] [<ffffffff810f0993>] ? generic_exec_single+0x133/0x190 [ 7940.167964] [<ffffffff81156100>] ? task_clock_event_add+0x40/0x40 [ 7940.175029] [<ffffffff810f0a57>] ? smp_call_function_single+0x67/0xa0 [ 7940.182518] [<ffffffff81154d69>] ? task_function_call+0x49/0x60 [ 7940.189447] [<ffffffff8115b400>] ? perf_event_sched_in+0xa0/0xa0 [ 7940.196485] [<ffffffff81154e10>] ? _perf_event_enable+0x90/0xf0 [ 7940.203430] [<ffffffff81154d80>] ? task_function_call+0x60/0x60 [ 7940.210386] [<ffffffff81154baf>] ? perf_event_for_each_child+0x3f/0xb0 [ 7940.217945] [<ffffffff8115c4ac>] ? perf_event_task_enable+0x7c/0xd0 [ 7940.225255] [<ffffffff81082d4d>] ? SyS_prctl+0x26d/0x4d0 [ 7940.231557] [<ffffffff816c7ead>] ? system_call_fastpath+0x16/0x1b [ 7947.852948] perf interrupt took too long (4536733 > 10000), lowering kernel.perf_event_max_sample_rate to 12500 [ 7956.620503] perf interrupt took too long (4501296 > 20000), lowering kernel.perf_event_max_sample_rate to 6250 [ 7965.387462] perf interrupt took too long (4466134 > 38461), lowering kernel.perf_event_max_sample_rate to 3250
[145965.719358] Call Trace: [145965.722845] <NMI> [<ffffffff816bfed5>] dump_stack+0x45/0x57 [145965.729907] [<ffffffff8106ddfa>] warn_slowpath_common+0x8a/0xc0 [145965.737170] [<ffffffff8106de76>] warn_slowpath_fmt+0x46/0x50 [145965.744103] [<ffffffff8101db0a>] ? native_sched_clock+0x2a/0x90 [145965.751356] [<ffffffff8111cde2>] watchdog_overflow_callback+0x92/0xc0 [145965.759125] [<ffffffff8115dbe1>] __perf_event_overflow+0x91/0x270 [145965.766466] [<ffffffff8102b56a>] ? x86_perf_event_set_period+0xca/0x170 [145965.774393] [<ffffffff8115e6c9>] perf_event_overflow+0x19/0x20 [145965.781478] [<ffffffff81032a7a>] intel_pmu_handle_irq+0x1ba/0x3a0 [145965.788793] [<ffffffff816ca020>] ? trace_page_fault+0x30/0x30 [145965.795777] [<ffffffff8102a45b>] perf_event_nmi_handler+0x2b/0x50 [145965.803049] [<ffffffff81018760>] nmi_handle+0xa0/0x150 [145965.809335] [<ffffffff810186c5>] ? nmi_handle+0x5/0x150 [145965.815730] [<ffffffff81018a95>] default_do_nmi+0xd5/0x140 [145965.822428] [<ffffffff81018b98>] do_nmi+0x98/0xe0 [145965.828254] [<ffffffff816ca3d1>] end_repeat_nmi+0x1e/0x2e [145965.834803] [<ffffffff816c9ff0>] ? general_protection+0x30/0x30 [145965.841912] [<ffffffff816c9ff0>] ? general_protection+0x30/0x30 [145965.849073] [<ffffffff816c9ff0>] ? general_protection+0x30/0x30 [145965.856187] <<EOE>> <IRQ> [<ffffffff8140b46b>] ? copy_user_handle_tail+0x3b/0x80 [145965.865154] [<ffffffff8140b343>] copy_from_user_nmi+0x63/0x70 [145965.872114] [<ffffffff8102c210>] perf_callchain_user+0xd0/0x240 [145965.879227] [<ffffffff81161508>] perf_callchain+0x1f8/0x220 [145965.885923] [<ffffffff8115da21>] perf_prepare_sample+0x291/0x3c0 [145965.893151] [<ffffffff8115dc5e>] __perf_event_overflow+0x10e/0x270 [145965.900562] [<ffffffff8115dc29>] ? __perf_event_overflow+0xd9/0x270 [145965.908078] [<ffffffff810b7f10>] ? lock_release+0x130/0x260 [145965.914842] [<ffffffff8115df89>] perf_swevent_overflow+0xa9/0xe0 [145965.922072] [<ffffffff8115e027>] perf_swevent_event+0x67/0x90 [145965.929025] [<ffffffff8115e114>] perf_tp_event+0xc4/0x210 [145965.935615] [<ffffffff810b7f10>] ? lock_release+0x130/0x260 [145965.942395] [<ffffffff8107ba4e>] ? __lock_task_sighand+0x6e/0x110 [145965.949648] [<ffffffff810b4f8a>] ? perf_trace_lock+0x12a/0x160 [145965.956671] [<ffffffff8107ba58>] ? __lock_task_sighand+0x78/0x110 [145965.963919] [<ffffffff8107bb4d>] ? do_send_sig_info+0x5d/0x80 [145965.970858] [<ffffffff8107bb4d>] ? do_send_sig_info+0x5d/0x80 [145965.977849] [<ffffffff811406d8>] ? perf_trace_buf_prepare+0x98/0xf0 [145965.985330] [<ffffffff810b4f8a>] perf_trace_lock+0x12a/0x160 [145965.992195] [<ffffffff811f7176>] ? send_sigio+0x56/0x100 [145965.998659] [<ffffffff811f71f0>] ? send_sigio+0xd0/0x100 [145966.005169] [<ffffffff810b7f10>] lock_release+0x130/0x260 [145966.011716] [<ffffffff816c76e3>] _raw_read_unlock+0x23/0x40 [145966.018442] [<ffffffff811f71f0>] send_sigio+0xd0/0x100 [145966.024700] [<ffffffff811f72b7>] kill_fasync+0x97/0xf0 [145966.030968] [<ffffffff811f722f>] ? kill_fasync+0xf/0xf0 [145966.037365] [<ffffffff8115d0b4>] perf_event_wakeup+0xd4/0xf0 [145966.044210] [<ffffffff8115cfe5>] ? perf_event_wakeup+0x5/0xf0 [145966.051060] [<ffffffff8115d103>] perf_pending_event+0x33/0x60 [145966.057950] [<ffffffff8114e3fc>] irq_work_run_list+0x4c/0x80 [145966.064798] [<ffffffff8114e448>] irq_work_run+0x18/0x40 [145966.071127] [<ffffffff810196af>] smp_trace_irq_work_interrupt+0x3f/0xc0 [145966.078929] [<ffffffff816c99bd>] trace_irq_work_interrupt+0x6d/0x80 [145966.086359] <EOI> [<ffffffff816c74c2>] ? _raw_spin_unlock_irq+0x32/0x40 [145966.094337] [<ffffffff816c74bb>] ? _raw_spin_unlock_irq+0x2b/0x40 [145966.101634] [<ffffffff81092f7c>] finish_task_switch+0x8c/0x140 [145966.108630] [<ffffffff81092f3d>] ? finish_task_switch+0x4d/0x140 [145966.115793] [<ffffffff816c1c06>] __schedule+0x2d6/0x9f0 [145966.122115] [<ffffffff810b4e89>] ? perf_trace_lock+0x29/0x160 [145966.128909] [<ffffffff816c2357>] schedule+0x37/0x90 [145966.134802] [<ffffffff816c67ac>] schedule_timeout+0x1bc/0x250 [145966.141578] [<ffffffff816c37f8>] ? wait_for_completion+0x28/0x100 [145966.148660] [<ffffffff816c3894>] ? wait_for_completion+0xc4/0x100 [145966.155795] [<ffffffff816c389c>] wait_for_completion+0xcc/0x100 [145966.162731] [<ffffffff8109ae80>] ? wake_up_state+0x20/0x20 [145966.169205] [<ffffffff810d4830>] ? call_rcu_bh+0x20/0x20 [145966.175464] [<ffffffff810d12fd>] wait_rcu_gp+0x5d/0x80 [145966.181586] [<ffffffff810d1240>] ? ftrace_raw_output_rcu_utilization+0x70/0x70 [145966.189890] [<ffffffff810d352a>] synchronize_sched+0x3a/0x50 [145966.196573] [<ffffffff8114083b>] perf_trace_event_unreg.isra.1+0x3b/0x90 [145966.204345] [<ffffffff81140bac>] perf_trace_destroy+0x3c/0x50 [145966.211075] [<ffffffff81155aee>] tp_perf_event_destroy+0xe/0x10 [145966.217976] [<ffffffff8115721c>] __free_event+0x2c/0x80 [145966.224102] [<ffffffff8115f5f9>] SYSC_perf_event_open+0x629/0xc80 [145966.231246] [<ffffffff8116009e>] SyS_perf_event_open+0xe/0x10 [145966.237982] [<ffffffff816c7ead>] system_call_fastpath+0x16/0x1b [145966.244932] ---[ end trace 7088940f25646d60 ]---
| |