From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755185Ab0CXISE (ORCPT ); Wed, 24 Mar 2010 04:18:04 -0400 Received: from mail.gmx.net ([213.165.64.20]:36047 "HELO mail.gmx.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1755122Ab0CXIR6 (ORCPT ); Wed, 24 Mar 2010 04:17:58 -0400 X-Authenticated: #14349625 X-Provags-ID: V01U2FsdGVkX1/VT5QruS/Vzz/dh3wiNm2tSGZtnnP6llHUGC23eh yVYeTn9udEUw6a Subject: Re: [BUG] perf: hard lockup when using perf-sched From: Mike Galbraith To: Li Zefan Cc: LKML , Ingo Molnar , Peter Zijlstra , Frederic Weisbecker , Arnaldo Carvalho de Melo , Paul Mackerras In-Reply-To: <1269415964.6530.25.camel@marge.simson.net> References: <4BA082EC.8030101@cn.fujitsu.com> <4BA9A885.9050105@cn.fujitsu.com> <1269415964.6530.25.camel@marge.simson.net> Content-Type: text/plain Date: Wed, 24 Mar 2010 09:17:51 +0100 Message-Id: <1269418671.6465.6.camel@marge.simson.net> Mime-Version: 1.0 X-Mailer: Evolution 2.24.1.1 Content-Transfer-Encoding: 7bit X-Y-GMX-Trusted: 0 X-FuHaFi: 0.5 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Wed, 2010-03-24 at 08:32 +0100, Mike Galbraith wrote: > I just saw this, hunted down your testcase and tried it here. Looks > like perf_output_lock() wedged box. (turns on frame pointers, and adds noinline) [ 90.276644] BUG: NMI Watchdog detected LOCKUP on CPU2, ip ffffffff812b54a8, registers: [ 90.276644] CPU 2 [ 90.276644] Modules linked in: cpufreq_conservative cpufreq_ondemand cpufreq_userspace cpufreq_powersave acpi_cpufreq snd_pcm_oss snd_mixer_oss microcode snd_seq snd_seq_device fuse loop dm_mod snd_hda_codec_realtek snd_hda_intel firewire_ohci firewire_core snd_hda_codec usbmouse crc_itu_t snd_hwdep snd_pcm usb_storage snd_timer sr_mod usbhid ohci1394 snd rtc_cmos soundcore rtc_core ieee1394 usb_libusual thermal i2c_i801 processor button e1000e snd_page_alloc cdrom rtc_lib hid sg uhci_hcd ehci_hcd sd_mod usbcore edd fan ext3 ext2 mbcache jbd ahci libata scsi_mod [ 90.276644] [ 90.276644] Pid: 20237, comm: forkbomb Not tainted 2.6.34-smpx #1477 MS-7502/MS-7502 [ 90.276644] RIP: 0010:[] [] _raw_spin_lock+0x12/0x1a [ 90.276644] RSP: 0018:ffff880001703ee8 EFLAGS: 00000097 [ 90.276644] RAX: 000000000000c3c2 RBX: ffff880001712e40 RCX: 0000001504ab3a62 [ 90.276644] RDX: 0000001504ab3b83 RSI: 0000000000000026 RDI: ffff880001712e40 [ 90.276644] RBP: ffff880001703ee8 R08: 000000001ba05e30 R09: ffff880001703f88 [ 90.276644] R10: 0000000000000038 R11: 0000000000000038 R12: 0000000000000002 [ 90.276644] R13: ffff8800b48de2d0 R14: 0000000000000038 R15: 00000000ffffffe4 [ 90.276644] FS: 0000000000000000(0000) GS:ffff880001700000(0000) knlGS:0000000000000000 [ 90.276644] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 90.276644] CR2: 00007ff05702a4a8 CR3: 0000000001430000 CR4: 00000000000006e0 [ 90.276644] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 90.276644] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 90.276644] Process forkbomb (pid: 20237, threadinfo ffff8800bd3f8000, task ffff8800b48de2d0) [ 90.276644] Stack: [ 90.276644] ffff880001703f18 ffffffff8102ecc4 ffff8800b48de2d0 ffff8800b48de2d0 [ 90.276644] <0> 0000000000000000 0000000000000002 ffff880001703f48 ffffffff8103f082 [ 90.276644] <0> ffffea00029f9ee0 ffff88000170d170 ffff88000170d170 0000000000000002 [ 90.276644] Call Trace: [ 90.276644] [ 90.276644] [] scheduler_tick+0x3c/0x1e6 [ 90.276644] [] update_process_times+0x4b/0x5b [ 90.276644] [] tick_periodic+0x5d/0x5f [ 90.276644] [] tick_handle_periodic+0x21/0x6e [ 90.276644] [] smp_apic_timer_interrupt+0x83/0x96 [ 90.276644] [] apic_timer_interrupt+0x13/0x20 [ 90.276644] [ 90.276644] [] ? perf_output_unlock+0x27/0x122 [ 90.276644] [] ? perf_swevent_overflow+0x58/0x76 [ 90.276644] [] perf_output_begin+0x16e/0x180 [ 90.276644] [] ? perf_swevent_ctx_event+0xdd/0xee [ 90.276644] [] perf_event_task_ctx+0xf8/0x110 [ 90.276644] [] ? sched_clock_cpu+0xc0/0xce [ 90.276644] [] perf_event_task+0x92/0xc3 [ 90.276644] [] perf_event_exit_task+0x27/0x112 [ 90.276644] [] ? free_fs_struct+0x2d/0x31 [ 90.276644] [] do_exit+0x264/0x67a [ 90.276644] [] ? do_page_fault+0x222/0x253 [ 90.276644] [] do_group_exit+0x6f/0x98 [ 90.276644] [] sys_exit_group+0x12/0x16 [ 90.276644] [] system_call_fastpath+0x16/0x1b [ 90.276644] Code: 00 00 75 05 f0 66 0f b1 17 0f 94 c2 0f b6 c2 85 c0 c9 0f 95 c0 0f b6 c0 c3 55 b8 00 01 00 00 48 89 e5 f0 66 0f c1 07 38 e0 74 06 90 8a 07 eb f6 c9 c3 55 48 89 e5 9c 58 fa ba 00 01 00 00 f0 [ 90.276639] BUG: NMI Watchdog detected LOCKUP [ 90.276644] ---[ end trace ef30915e055ad1b9 ]--- [ 90.276639] on CPU1, ip ffffffff81079014, registers: [ 90.276639] CPU 1 [ 90.276639] Modules linked in: cpufreq_conservative cpufreq_ondemand cpufreq_userspace cpufreq_powersave acpi_cpufreq snd_pcm_oss snd_mixer_oss microcode snd_seq snd_seq_device fuse loop dm_mod snd_hda_codec_realtek snd_hda_intel firewire_ohci firewire_core snd_hda_codec usbmouse crc_itu_t snd_hwdep snd_pcm usb_storage snd_timer sr_mod usbhid ohci1394 snd rtc_cmos soundcore rtc_core ieee1394 usb_libusual thermal i2c_i801 processor button e1000e snd_page_alloc cdrom rtc_lib hid sg uhci_hcd ehci_hcd sd_mod usbcore edd fan ext3 ext2 mbcache jbd ahci libata scsi_mod [ 90.276639] [ 90.276639] Pid: 0, comm: swapper Tainted: G D 2.6.34-smpx #1477 MS-7502/MS-7502 [ 90.276639] RIP: 0010:[] [] perf_output_lock+0x30/0x4e [ 90.276639] RSP: 0018:ffff880001683a00 EFLAGS: 00000082 [ 90.276639] RAX: 0000000000000002 RBX: ffff880001683ab0 RCX: ffff8800bc454000 [ 90.276639] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff880001683ab0 [ 90.276639] RBP: ffff880001683a10 R08: 0000000000000001 R09: ffff880001683ae0 [ 90.276639] R10: 0000000000000200 R11: 0000000000000000 R12: ffff8800bc454000 [ 90.276639] R13: ffff880037788000 R14: 0000000000000070 R15: 00000000ffffffe4 [ 90.276639] FS: 0000000000000000(0000) GS:ffff880001680000(0000) knlGS:0000000000000000 [ 90.276639] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 90.276639] CR2: 00007ff05702a4a8 CR3: 0000000001430000 CR4: 00000000000006e0 [ 90.276639] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 90.276639] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 90.276639] Process swapper (pid: 0, threadinfo ffff8800bf888000, task ffff8800bf8422e0) [ 90.276639] Stack: [ 90.276639] 00000001374fb210 00000002ffffffff ffff880001683a90 ffffffff8107c5cf [ 90.276639] <0> ffff880001683a40 000000000002b3c6 ffff880001683a40 ffff880001683ae0 [ 90.276639] <0> ffff880001683a90 ffffffff8107d13c ffffffff8104eb6b ffff8800bf8422e0 [ 90.276639] Call Trace: [ 90.276639] [ 90.276639] [] perf_output_begin+0x77/0x180 [ 90.276639] [] ? perf_prepare_sample+0xb5/0x1d3 [ 90.276639] [] ? sched_clock_local+0x12/0x75 [ 90.276639] [] __perf_event_overflow+0x16b/0x1ad [ 90.276639] [] ? perf_prepare_sample+0xb5/0x1d3 [ 90.276639] [] perf_swevent_overflow+0x58/0x76 [ 90.276639] [] perf_swevent_add+0x46/0x48 [ 90.276639] [] perf_swevent_ctx_event+0xdd/0xee [ 90.276639] [] do_perf_sw_event+0x4e/0x8c [ 90.276639] [] perf_tp_event+0x31/0x33 [ 90.276639] [] ? try_to_wake_up+0x165/0x226 [ 90.276639] [] ? perf_trace_buf_prepare+0x8e/0xb5 [ 90.276639] [] perf_trace_templ_sched_wakeup_template+0xca/0xe0 [ 90.276639] [] perf_trace_sched_wakeup+0xf/0x11 [ 90.276639] [] try_to_wake_up+0x165/0x226 [ 90.276639] [] wake_up_process+0x10/0x12 [ 90.276639] [] load_balance+0x3d3/0x47f [ 90.276639] [] ? perf_event_task_tick+0x6e/0x124 [ 90.276639] [] rebalance_domains+0xda/0x14a [ 90.276639] [] run_rebalance_domains+0x44/0xd4 [ 90.276639] [] __do_softirq+0xd7/0x193 [ 90.276639] [] ? timer_interrupt+0x19/0x20 [ 90.276639] [] call_softirq+0x1c/0x28 [ 90.276639] [] do_softirq+0x33/0x69 [ 90.276639] [] irq_exit+0x36/0x78 [ 90.276639] [] do_IRQ+0xa7/0xbe [ 90.276639] [] ret_from_intr+0x0/0xa [ 90.276639] [ 90.276639] [] ? mwait_idle+0xa2/0xa9 [ 90.276639] [] ? atomic_notifier_call_chain+0x13/0x15 [ 90.276639] [] cpu_idle+0x52/0x6f [ 90.276639] [] start_secondary+0x1ae/0x1b2 [ 90.276639] Code: 83 ec 10 c7 47 28 00 00 00 00 48 8b 4f 08 65 8b 14 25 58 d1 00 00 c7 45 f8 ff ff ff ff 89 55 f4 8b 75 f4 8b 45 f8 f0 0f b1 71 38 <89> 45 fc 8b 45 fc 83 f8 ff 75 09 c7 47 28 01 00 00 00 eb 08 39 [ 90.276639] ---[ end trace ef30915e055ad1ba ]--- [ 90.276644] BUG: NMI Watchdog detected LOCKUP on CPU3, ip ffffffff81079014, registers: [ 90.276644] CPU 3 [ 90.276644] Modules linked in: cpufreq_conservative cpufreq_ondemand cpufreq_userspace cpufreq_powersave acpi_cpufreq snd_pcm_oss snd_mixer_oss microcode snd_seq snd_seq_device fuse loop dm_mod snd_hda_codec_realtek snd_hda_intel firewire_ohci firewire_core snd_hda_codec usbmouse crc_itu_t snd_hwdep snd_pcm usb_storage snd_timer sr_mod usbhid ohci1394 snd rtc_cmos soundcore rtc_core ieee1394 usb_libusual thermal i2c_i801 processor button e1000e snd_page_alloc cdrom rtc_lib hid sg uhci_hcd ehci_hcd sd_mod usbcore edd fan ext3 ext2 mbcache jbd ahci libata scsi_mod [ 90.276644] [ 90.276644] Pid: 5146, comm: forkbomb Tainted: G D 2.6.34-smpx #1477 MS-7502/MS-7502 [ 90.276644] RIP: 0010:[] [] perf_output_lock+0x30/0x4e [ 90.276644] RSP: 0018:ffff880001783b88 EFLAGS: 00000082 [ 90.276644] RAX: 0000000000000002 RBX: ffff880001783c38 RCX: ffff8800bc454000 [ 90.276644] RDX: 0000000000000003 RSI: 0000000000000003 RDI: ffff880001783c38 [ 90.276644] RBP: ffff880001783b98 R08: 0000000000000001 R09: ffff880001783c68 [ 90.276644] R10: 0000000000000003 R11: 0000000000000246 R12: ffff8800bc454000 [ 90.276644] R13: ffff880037788000 R14: 0000000000000078 R15: 00000000ffffffe4 [ 90.276644] FS: 00007ff057202700(0000) GS:ffff880001780000(0000) knlGS:0000000000000000 [ 90.276644] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 90.276644] CR2: 00007ff05702be04 CR3: 00000000bf8c4000 CR4: 00000000000006e0 [ 90.276644] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 90.276644] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 90.276644] Process forkbomb (pid: 5146, threadinfo ffff8800bbebc000, task ffff8800bc128000) [ 90.276644] Stack: [ 90.276644] 000000030178f9e0 00000002ffffffff ffff880001783c18 ffffffff8107c5cf [ 90.276644] <0> ffff880001783bc8 000000000002b3c6 ffff880001783bc8 ffff880001783c68 [ 90.276644] <0> ffff880001783c18 ffffffff8107d13c ffff880001783be8 ffff8800bc128000 [ 90.276644] Call Trace: [ 90.276644] [ 90.276644] [] perf_output_begin+0x77/0x180 [ 90.276644] [] ? perf_prepare_sample+0xb5/0x1d3 [ 90.276644] [] __perf_event_overflow+0x16b/0x1ad [ 90.276644] [] perf_swevent_overflow+0x58/0x76 [ 90.276644] [] perf_swevent_add+0x46/0x48 [ 90.276644] [] perf_swevent_ctx_event+0xdd/0xee [ 90.276644] [] do_perf_sw_event+0x4e/0x8c [ 90.276644] [] perf_tp_event+0x31/0x33 [ 90.276644] [] ? task_tick_fair+0x47/0x103 [ 90.276644] [] ? perf_trace_buf_prepare+0x8e/0xb5 [ 90.276644] [] perf_trace_sched_stat_runtime+0xc4/0xdc [ 90.276644] [] update_curr+0x87/0xc8 [ 90.276644] [] task_tick_fair+0x47/0x103 [ 90.276644] [] scheduler_tick+0xd9/0x1e6 [ 90.276644] [] update_process_times+0x4b/0x5b [ 90.276644] [] tick_periodic+0x5d/0x5f [ 90.276644] [] tick_handle_periodic+0x21/0x6e [ 90.276644] [] smp_apic_timer_interrupt+0x83/0x96 [ 90.276644] [] apic_timer_interrupt+0x13/0x20 [ 90.276644] [ 90.276644] [] ? kmem_cache_alloc+0x6a/0xdc [ 90.276644] [] anon_vma_fork+0x40/0xca [ 90.276644] [] dup_mm+0x206/0x43f [ 90.276644] [] copy_process+0x7b2/0xea9 [ 90.276644] [] do_fork+0x15e/0x2b4 [ 90.276644] [] ? do_page_fault+0x222/0x253 [ 90.276644] [] sys_clone+0x23/0x25 [ 90.276644] [] stub_clone+0x13/0x20 [ 90.276644] [] ? system_call_fastpath+0x16/0x1b [ 90.276644] Code: 83 ec 10 c7 47 28 00 00 00 00 48 8b 4f 08 65 8b 14 25 58 d1 00 00 c7 45 f8 ff ff ff ff 89 55 f4 8b 75 f4 8b 45 f8 f0 0f b1 71 38 <89> 45 fc 8b 45 fc 83 f8 ff 75 09 c7 47 28 01 00 00 00 eb 08 39 [ 90.276644] ---[ end trace ef30915e055ad1bb ]--- [ 90.276643] BUG: NMI Watchdog detected LOCKUP on CPU0, ip ffffffff81079014, registers: [ 90.276643] CPU 0 [ 90.276643] Modules linked in: cpufreq_conservative cpufreq_ondemand cpufreq_userspace cpufreq_powersave [ 90.276644] Kernel panic - not syncing: Aiee, killing interrupt handler! [ 90.276643] acpi_cpufreqPid: 5146, comm: forkbomb Tainted: G D 2.6.34-smpx #1477 [ 90.276643] snd_pcm_ossCall Trace: [ 90.276643] snd_mixer_oss microcode snd_seq [] panic+0x73/0xe1 [ 90.276643] snd_seq_device fuse [] ? irq_exit+0x48/0x78 [ 90.276643] loop dm_mod [] do_exit+0x6d/0x67a [ 90.276643] snd_hda_codec_realtek snd_hda_intel [] ? notifier_call_chain+0x32/0x5e [ 90.276643] firewire_ohci firewire_core [] die_nmi+0xd2/0xde [ 90.276643] snd_hda_codec usbmouse [] nmi_watchdog_tick+0x41/0x19d [ 90.276643] crc_itu_t snd_hwdep [] do_nmi+0x222/0x24c [ 90.276643] snd_pcm usb_storage [] nmi+0x1a/0x20 [ 90.276643] snd_timer sr_mod [] ? die_nmi+0xcd/0xde [ 90.276643] usbhid <> ohci1394 snd rtc_cmos soundcore rtc_core ieee1394 usb_libusual thermal i2c_i801 processor button e1000e snd_page_alloc cdrom rtc_lib hid sg uhci_hcd ehci_hcd sd_mod usbcore edd fan ext3 ext2 mbcache jbd ahci libata scsi_mod [ 90.276643] [ 90.276643] Pid: 20238, comm: forkbomb Tainted: G D 2.6.34-smpx #1477 MS-7502/MS-7502 [ 90.276643] RIP: 0010:[] [] perf_output_lock+0x30/0x4e [ 90.276643] RSP: 0000:ffff880001603b88 EFLAGS: 00000082 [ 90.276643] RAX: 0000000000000002 RBX: ffff880001603c38 RCX: ffff8800bc454000 [ 90.276643] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff880001603c38 [ 90.276643] RBP: ffff880001603b98 R08: 0000000000000001 R09: ffff880001603c68 [ 90.276643] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8800bc454000 [ 90.276643] R13: ffff880037788000 R14: 0000000000000078 R15: 00000000ffffffe4 [ 90.276643] FS: 00007ff057202700(0000) GS:ffff880001600000(0000) knlGS:0000000000000000 [ 90.276643] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 90.276643] CR2: 00007ff056d05510 CR3: 00000000bd9f7000 CR4: 00000000000006f0 [ 90.276643] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 90.276643] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 90.276643] Process forkbomb (pid: 20238, threadinfo ffff8800bd3fa000, task ffff8800b48de8a0) [ 90.276643] Stack: [ 90.276643] 00000000071cf224 00000002ffffffff ffff880001603c18 ffffffff8107c5cf [ 90.276643] <0> ffff880001603bc8 000000000002b3c6 ffff880001603bc8 ffff880001603c68 [ 90.276643] <0> ffff880001603c18 ffffffff8107d13c ffff8800bc690888 ffff8800b48de8a0 [ 90.276643] Call Trace: [ 90.276643] [ 90.276643] [] perf_output_begin+0x77/0x180 [ 90.276643] [] ? perf_prepare_sample+0xb5/0x1d3 [ 90.276643] [] __perf_event_overflow+0x16b/0x1ad [ 90.276643] [] perf_swevent_overflow+0x58/0x76 [ 90.276643] [] perf_swevent_add+0x46/0x48 [ 90.276643] [] perf_swevent_ctx_event+0xdd/0xee [ 90.276643] [] do_perf_sw_event+0x4e/0x8c [ 90.276643] [] ? put_device+0x12/0x14 [ 90.276643] [] perf_tp_event+0x31/0x33 [ 90.276643] [] ? task_tick_fair+0x47/0x103 [ 90.276643] [] ? perf_trace_buf_prepare+0x8e/0xb5 [ 90.276643] [] perf_trace_sched_stat_runtime+0xc4/0xdc [ 90.276643] [] ? scsi_finish_command+0xec/0xf5 [scsi_mod] [ 90.276643] [] update_curr+0x87/0xc8 [ 90.276643] [] task_tick_fair+0x47/0x103 [ 90.276643] [] scheduler_tick+0xd9/0x1e6 [ 90.276643] [] update_process_times+0x4b/0x5b [ 90.276643] [] tick_periodic+0x5d/0x5f [ 90.276643] [] tick_handle_periodic+0x21/0x6e [ 90.276643] [] smp_apic_timer_interrupt+0x83/0x96 [ 90.276643] [] apic_timer_interrupt+0x13/0x20 [ 90.276643] [ 90.276643] [] ? do_page_fault+0x84/0x253 [ 90.276643] [] ? do_page_fault+0x222/0x253 [ 90.276643] [] page_fault+0x1f/0x30 [ 90.276643] Code: 83 ec 10 c7 47 28 00 00 00 00 48 8b 4f 08 65 8b 14 25 58 d1 00 00 c7 45 f8 ff ff ff ff 89 55 f4 8b 75 f4 8b 45 f8 f0 0f b1 71 38 <89> 45 fc 8b 45 fc 83 f8 ff 75 09 c7 47 28 01 00 00 00 eb 08 39 [ 90.276643] ---[ end trace ef30915e055ad1bc ]---