From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752493Ab2GTLPg (ORCPT ); Fri, 20 Jul 2012 07:15:36 -0400 Received: from mail-bk0-f46.google.com ([209.85.214.46]:56661 "EHLO mail-bk0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751189Ab2GTLPd (ORCPT ); Fri, 20 Jul 2012 07:15:33 -0400 Message-ID: <50093DED.7090706@gmail.com> Date: Fri, 20 Jul 2012 13:15:57 +0200 From: Sasha Levin User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:13.0) Gecko/20120713 Thunderbird/13.0 MIME-Version: 1.0 To: tglx@linutronix.de CC: "linux-kernel@vger.kernel.org" Subject: hrtimer: Lockups with latest -next kernel Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi all, While fuzzing with trinity inside a KVM tools guest on the latest -next kernel, I've started seeing hangs straight away after the guest has started fuzzing. I've annotated the hang spots with [HANG]. When those happen everything is pretty much locked up. [ 39.030023] hrtimer: interrupt took 3064 ns [ 39.030025] hrtimer: interrupt took 2769 ns [HANG] [ 78.052011] ------------[ cut here ]------------ [ 78.052012] ------------[ cut here ]------------ [ 78.052038] WARNING: at kernel/time/clockevents.c:209 clockevents_program_event+0x48/0xf0() [ 78.052041] Pid: 0, comm: swapper/2 Tainted: G W 3.5.0-rc7-next-20120720-sasha-00001-g0bb3f48-dirty #227 [ 78.052041] Call Trace: [ 78.052058] [] ? clockevents_program_event+0x48/0xf0 [ 78.052082] [] warn_slowpath_common+0x87/0xb0 [ 78.052086] [] warn_slowpath_null+0x15/0x20 [ 78.052086] [] clockevents_program_event+0x48/0xf0 [ 78.052103] [] tick_program_event+0x1f/0x30 [ 78.052121] [] hrtimer_interrupt+0x1ea/0x220 [ 78.052132] [] smp_apic_timer_interrupt+0x85/0xa0 [ 78.052132] [] apic_timer_interrupt+0x6f/0x80 [ 78.052150] [] ? retint_restore_args+0x13/0x13 [ 78.052169] [] ? native_safe_halt+0x6/0x10 [ 78.052179] [] ? trace_hardirqs_on+0xd/0x10 [ 78.052179] [] default_idle+0x235/0x5c0 [ 78.052196] [] cpu_idle+0x118/0x160 [ 78.052212] [] start_secondary+0xd0/0xd7 [ 78.052218] ---[ end trace 2b1961b84676e158 ]--- [ 78.061989] WARNING: at kernel/time/clockevents.c:209 clockevents_program_event+0x48/0xf0() [ 78.061989] Pid: 0, comm: swapper/3 Tainted: G W 3.5.0-rc7-next-20120720-sasha-00001-g0bb3f48-dirty #227 [ 78.061989] Call Trace: [ 78.061989] [] ? clockevents_program_event+0x48/0xf0 [ 78.061989] [] warn_slowpath_common+0x87/0xb0 [ 78.061989] [] warn_slowpath_null+0x15/0x20 [ 78.061989] [] clockevents_program_event+0x48/0xf0 [ 78.061989] [] tick_program_event+0x1f/0x30 [ 78.061989] [] hrtimer_interrupt+0x1ea/0x220 [ 78.061989] [] smp_apic_timer_interrupt+0x85/0xa0 [ 78.061989] [] apic_timer_interrupt+0x6f/0x80 [ 78.061989] [] ? retint_restore_args+0x13/0x13 [ 78.061989] [] ? native_safe_halt+0x6/0x10 [ 78.061989] [] ? trace_hardirqs_on+0xd/0x10 [ 78.061989] [] default_idle+0x235/0x5c0 [ 78.061989] [] cpu_idle+0x118/0x160 [ 78.061989] [] start_secondary+0xd0/0xd7 [ 78.061989] ---[ end trace 2b1961b84676e159 ]--- [HANG] [ 234.121718] BUG: soft lockup - CPU#0 stuck for 34s! [trinity-child41:6057] [ 234.121718] irq event stamp: 31065397 [ 234.121718] hardirqs last enabled at (31065396): [] restore_args+0x0/0x30 [ 234.121718] hardirqs last disabled at (31065397): [] apic_timer_interrupt+0x6a/0x80 [ 234.121718] softirqs last enabled at (344302): [] release_sock+0x94/0xa0 [ 234.121718] softirqs last disabled at (7204061): [] call_softirq+0x1c/0x30 [ 234.121718] CPU 0 [ 234.121718] Pid: 6057, comm: trinity-child41 Tainted: G W 3.5.0-rc7-next-20120720-sasha-00001-g0bb3f48-dirty #227 [ 234.121718] RIP: 0010:[] [] __do_softirq+0x94/0x450 [ 234.121718] RSP: 0018:ffff88000d803ec0 EFLAGS: 00000282 [ 234.121718] RAX: 0000000000000086 RBX: ffffffff8378b234 RCX: 0000000000000000 [ 234.121718] RDX: ffff88000bad0000 RSI: 0000000000000000 RDI: ffff88000bad0000 [ 234.121718] RBP: ffff88000d803f30 R08: 0000000000000000 R09: 0000000000000000 [ 234.121718] R10: 0000000000000001 R11: 0000000000000000 R12: ffff88000d803e38 [ 234.121718] R13: ffffffff8378c82f R14: ffff88000d803f30 R15: 0000000000000282 [ 234.121718] FS: 00007f8ca2ccb700(0000) GS:ffff88000d800000(0000) knlGS:0000000000000000 [ 234.121718] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 234.121718] CR2: 0000000000000000 CR3: 000000000bab3000 CR4: 00000000000406f0 [ 234.121718] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 234.121718] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 234.121718] Process trinity-child41 (pid: 6057, threadinfo ffff88000baca000, task ffff88000bad0000) [ 234.121718] Stack: [ 234.121718] ffff88000d9d7640 ffff88000bacbfd8 ffff88000bacbfd8 ffff88000000000a [ 234.121718] ffff88000bacbfd8 000000000d803f18 ffff88000bacbfd8 0000000000005678 [ 234.121718] 0000000000000000 0000000000000086 ffff88000bacbfd8 0000000000000001 [ 234.121718] Call Trace: [ 234.121718] [ 234.121718] [] call_softirq+0x1c/0x30 [ 234.121718] [] do_softirq+0x7d/0x100 [ 234.121718] [] irq_exit+0x5c/0xd0 [ 234.121718] [] smp_apic_timer_interrupt+0x8a/0xa0 [ 234.121718] [] apic_timer_interrupt+0x6f/0x80 [ 234.121718] [ 234.121718] [] ? retint_restore_args+0x13/0x13 [ 234.121718] [] ? _raw_spin_unlock_irqrestore+0x6d/0xa0 [ 234.121718] [] hrtimer_try_to_cancel+0x182/0x1f0 [ 234.121718] [] hrtimer_cancel+0x18/0x30 [ 234.121718] [] do_nanosleep+0x84/0xd0 [ 234.121718] [] hrtimer_nanosleep+0xd7/0x180 [ 234.121718] [] ? update_rmtp+0x70/0x70 [ 234.121718] [] common_nsleep+0x1e/0x20 [ 234.121718] [] sys_clock_nanosleep+0xcc/0x110 [ 234.121718] [] system_call_fastpath+0x1a/0x1f [ 234.121718] Code: 1f 84 00 00 00 00 00 65 c7 04 25 c0 46 1d 00 00 00 00 00 e8 8f a1 06 00 48 83 3d df 70 75 03 00 75 05 0f 0b 0f 1f 00 fb 66 66 90 <66> 66 90 48 c7 c3 00 60 80 84 66 90 41 f6 c4 01 0f 84 76 02 00 [ 234.121718] Kernel panic - not syncing: softlockup: hung tasks [ 234.121718] Pid: 6057, comm: trinity-child41 Tainted: G W 3.5.0-rc7-next-20120720-sasha-00001-g0bb3f48-dirty #227 [ 234.121718] Call Trace: [ 234.121718] [] panic+0xcd/0x1f4 [ 234.121718] [] ? __do_softirq+0xa8/0x450 [ 234.121718] [] watchdog_timer_fn+0x15e/0x190 [ 234.121718] [] __run_hrtimer+0x27e/0x4d0 [ 234.121718] [] ? kvm_clock_get_cycles+0x9/0x10 [ 234.121718] [] ? __touch_watchdog+0x20/0x20 [ 234.121718] [] ? ktime_get_update_offsets+0x4c/0xd0 [ 234.121718] [] hrtimer_interrupt+0x119/0x220 [ 234.121718] [] smp_apic_timer_interrupt+0x85/0xa0 [ 234.121718] [] apic_timer_interrupt+0x6f/0x80 [ 234.121718] [] ? retint_restore_args+0x13/0x13 [ 234.121718] [] ? __do_softirq+0x94/0x450 [ 234.121718] [] call_softirq+0x1c/0x30 [ 234.121718] [] do_softirq+0x7d/0x100 [ 234.121718] [] irq_exit+0x5c/0xd0 [ 234.121718] [] smp_apic_timer_interrupt+0x8a/0xa0 [ 234.121718] [] apic_timer_interrupt+0x6f/0x80 [ 234.121718] [] ? retint_restore_args+0x13/0x13 [ 234.121718] [] ? _raw_spin_unlock_irqrestore+0x6d/0xa0 [ 234.121718] [] hrtimer_try_to_cancel+0x182/0x1f0 [ 234.121718] [] hrtimer_cancel+0x18/0x30 [ 234.121718] [] do_nanosleep+0x84/0xd0 [ 234.121718] [] hrtimer_nanosleep+0xd7/0x180 [ 234.121718] [] ? update_rmtp+0x70/0x70 [ 234.121718] [] common_nsleep+0x1e/0x20 [ 234.121718] [] sys_clock_nanosleep+0xcc/0x110 [ 234.121718] [] system_call_fastpath+0x1a/0x1f