Greetings, 0day kernel testing robot got the below dmesg and the first bad commit is git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master commit 939f04bec1a4ef6ba4370b0f34b01decc844b1b1 Author: Jan Kara AuthorDate: Wed Jun 4 16:11:37 2014 -0700 Commit: Linus Torvalds CommitDate: Wed Jun 4 16:54:17 2014 -0700 printk: enable interrupts before calling console_trylock_for_printk() We need interrupts disabled when calling console_trylock_for_printk() only so that cpu id we pass to can_use_console() remains valid (for other things console_sem provides all the exclusion we need and deadlocks on console_sem due to interrupts are impossible because we use down_trylock()). However if we are rescheduled, we are guaranteed to run on an online cpu so we can easily just get the cpu id in can_use_console(). We can lose a bit of performance when we enable interrupts in vprintk_emit() and then disable them again in console_unlock() but OTOH it can somewhat reduce interrupt latency caused by console_unlock() especially since later in the patch series we will want to spin on console_sem in console_trylock_for_printk(). Signed-off-by: Jan Kara Signed-off-by: Andrew Morton Signed-off-by: Linus Torvalds +----------------------------------------------------+------------+------------+------------+ | | bd8d7cf5b8 | 939f04bec1 | fb3ec67942 | +----------------------------------------------------+------------+------------+------------+ | boot_successes | 1159 | 280 | 41 | | boot_failures | 41 | 20 | 5 | | BUG:kernel_boot_hang | 41 | 13 | 3 | | INFO:possible_circular_locking_dependency_detected | 0 | 7 | 2 | | backtrace:do_fork | 0 | 7 | 2 | | backtrace:vfs_write | 0 | 7 | 2 | | backtrace:SyS_write | 0 | 7 | 2 | | backtrace:event_create_dir | 0 | 2 | 1 | | backtrace:event_trace_init | 0 | 2 | 1 | | backtrace:kernel_init_freeable | 0 | 3 | 1 | | backtrace:SYSC_perf_event_open | 0 | 7 | 2 | | backtrace:SyS_perf_event_open | 0 | 7 | 2 | | backtrace:trace_create_cpu_file | 0 | 1 | | | backtrace:init_tracer_debugfs | 0 | 1 | | | backtrace:tracer_init_debugfs | 0 | 1 | | +----------------------------------------------------+------------+------------+------------+ [ 29.644027] CE: hpet increased min_delta_ns to 25312 nsec [ 29.644027] [ 29.644027] ====================================================== [ 29.644027] [ INFO: possible circular locking dependency detected ] [ 29.644027] 3.15.0-rc8-06195-g939f04b #2 Not tainted [ 29.644027] ------------------------------------------------------- [ 29.644027] trinity-main/74 is trying to acquire lock: [ 29.644027] (&port_lock_key){-.....}, at: [<811c60be>] serial8250_console_write+0x8c/0x10c [ 29.644027] [ 29.644027] but task is already holding lock: [ 29.644027] (hrtimer_bases.lock){-.-...}, at: [<8103caeb>] hrtimer_try_to_cancel+0x13/0x66 [ 29.644027] [ 29.644027] which lock already depends on the new lock. [ 29.644027] [ 29.644027] [ 29.644027] the existing dependency chain (in reverse order) is: [ 29.644027] [ 29.644027] -> #5 (hrtimer_bases.lock){-.-...}: [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e [ 29.644027] [<8103c918>] __hrtimer_start_range_ns+0x1c/0x197 [ 29.644027] [<8107ec20>] perf_swevent_start_hrtimer.part.41+0x7a/0x85 [ 29.644027] [<81080792>] task_clock_event_start+0x3a/0x3f [ 29.644027] [<810807a4>] task_clock_event_add+0xd/0x14 [ 29.644027] [<8108259a>] event_sched_in+0xb6/0x17a [ 29.644027] [<810826a2>] group_sched_in+0x44/0x122 [ 29.644027] [<81082885>] ctx_sched_in.isra.67+0x105/0x11f [ 29.644027] [<810828e6>] perf_event_sched_in.isra.70+0x47/0x4b [ 29.644027] [<81082bf6>] __perf_install_in_context+0x8b/0xa3 [ 29.644027] [<8107eb8e>] remote_function+0x12/0x2a [ 29.644027] [<8105f5af>] smp_call_function_single+0x2d/0x53 [ 29.644027] [<8107e17d>] task_function_call+0x30/0x36 [ 29.644027] [<8107fb82>] perf_install_in_context+0x87/0xbb [ 29.644027] [<810852c9>] SYSC_perf_event_open+0x5c6/0x701 [ 29.644027] [<810856f9>] SyS_perf_event_open+0x17/0x19 [ 29.644027] [<8142f8ee>] syscall_call+0x7/0xb [ 29.644027] [ 29.644027] -> #4 (&ctx->lock){......}: [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<8142f04c>] _raw_spin_lock+0x21/0x30 [ 29.644027] [<81081df3>] __perf_event_task_sched_out+0x1dc/0x34f [ 29.644027] [<8142cacc>] __schedule+0x4c6/0x4cb [ 29.644027] [<8142cae0>] schedule+0xf/0x11 [ 29.644027] [<8142f9a6>] work_resched+0x5/0x30 [ 29.644027] [ 29.644027] -> #3 (&rq->lock){-.-.-.}: [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<8142f04c>] _raw_spin_lock+0x21/0x30 [ 29.644027] [<81040873>] __task_rq_lock+0x33/0x3a [ 29.644027] [<8104184c>] wake_up_new_task+0x25/0xc2 [ 29.644027] [<8102474b>] do_fork+0x15c/0x2a0 [ 29.644027] [<810248a9>] kernel_thread+0x1a/0x1f [ 29.644027] [<814232a2>] rest_init+0x1a/0x10e [ 29.644027] [<817af949>] start_kernel+0x303/0x308 [ 29.644027] [<817af2ab>] i386_start_kernel+0x79/0x7d [ 29.644027] [ 29.644027] -> #2 (&p->pi_lock){-.-...}: [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e [ 29.644027] [<810413dd>] try_to_wake_up+0x1d/0xd6 [ 29.644027] [<810414cd>] default_wake_function+0xb/0xd [ 29.644027] [<810461f3>] __wake_up_common+0x39/0x59 [ 29.644027] [<81046346>] __wake_up+0x29/0x3b [ 29.644027] [<811b8733>] tty_wakeup+0x49/0x51 [ 29.644027] [<811c3568>] uart_write_wakeup+0x17/0x19 [ 29.644027] [<811c5dc1>] serial8250_tx_chars+0xbc/0xfb [ 29.644027] [<811c5f28>] serial8250_handle_irq+0x54/0x6a [ 29.644027] [<811c5f57>] serial8250_default_handle_irq+0x19/0x1c [ 29.644027] [<811c56d8>] serial8250_interrupt+0x38/0x9e [ 29.644027] [<810510e7>] handle_irq_event_percpu+0x5f/0x1e2 [ 29.644027] [<81051296>] handle_irq_event+0x2c/0x43 [ 29.644027] [<81052cee>] handle_level_irq+0x57/0x80 [ 29.644027] [<81002a72>] handle_irq+0x46/0x5c [ 29.644027] [<810027df>] do_IRQ+0x32/0x89 [ 29.644027] [<8143036e>] common_interrupt+0x2e/0x33 [ 29.644027] [<8142f23c>] _raw_spin_unlock_irqrestore+0x3f/0x49 [ 29.644027] [<811c25a4>] uart_start+0x2d/0x32 [ 29.644027] [<811c2c04>] uart_write+0xc7/0xd6 [ 29.644027] [<811bc6f6>] n_tty_write+0xb8/0x35e [ 29.644027] [<811b9beb>] tty_write+0x163/0x1e4 [ 29.644027] [<811b9cd9>] redirected_tty_write+0x6d/0x75 [ 29.644027] [<810b6ed6>] vfs_write+0x75/0xb0 [ 29.644027] [<810b7265>] SyS_write+0x44/0x77 [ 29.644027] [<8142f8ee>] syscall_call+0x7/0xb [ 29.644027] [ 29.644027] -> #1 (&tty->write_wait){-.....}: [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e [ 29.644027] [<81046332>] __wake_up+0x15/0x3b [ 29.644027] [<811b8733>] tty_wakeup+0x49/0x51 [ 29.644027] [<811c3568>] uart_write_wakeup+0x17/0x19 [ 29.644027] [<811c5dc1>] serial8250_tx_chars+0xbc/0xfb [ 29.644027] [<811c5f28>] serial8250_handle_irq+0x54/0x6a [ 29.644027] [<811c5f57>] serial8250_default_handle_irq+0x19/0x1c [ 29.644027] [<811c56d8>] serial8250_interrupt+0x38/0x9e [ 29.644027] [<810510e7>] handle_irq_event_percpu+0x5f/0x1e2 [ 29.644027] [<81051296>] handle_irq_event+0x2c/0x43 [ 29.644027] [<81052cee>] handle_level_irq+0x57/0x80 [ 29.644027] [<81002a72>] handle_irq+0x46/0x5c [ 29.644027] [<810027df>] do_IRQ+0x32/0x89 [ 29.644027] [<8143036e>] common_interrupt+0x2e/0x33 [ 29.644027] [<8142f23c>] _raw_spin_unlock_irqrestore+0x3f/0x49 [ 29.644027] [<811c25a4>] uart_start+0x2d/0x32 [ 29.644027] [<811c2c04>] uart_write+0xc7/0xd6 [ 29.644027] [<811bc6f6>] n_tty_write+0xb8/0x35e [ 29.644027] [<811b9beb>] tty_write+0x163/0x1e4 [ 29.644027] [<811b9cd9>] redirected_tty_write+0x6d/0x75 [ 29.644027] [<810b6ed6>] vfs_write+0x75/0xb0 [ 29.644027] [<810b7265>] SyS_write+0x44/0x77 [ 29.644027] [<8142f8ee>] syscall_call+0x7/0xb [ 29.644027] [ 29.644027] -> #0 (&port_lock_key){-.....}: [ 29.644027] [<8104a62d>] __lock_acquire+0x9ea/0xc6d [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e [ 29.644027] [<811c60be>] serial8250_console_write+0x8c/0x10c [ 29.644027] [<8104e402>] call_console_drivers.constprop.31+0x87/0x118 [ 29.644027] [<8104f5d5>] console_unlock+0x1d7/0x398 [ 29.644027] [<8104fb70>] vprintk_emit+0x3da/0x3e4 [ 29.644027] [<81425f76>] printk+0x17/0x19 [ 29.644027] [<8105bfa0>] clockevents_program_min_delta+0x104/0x116 [ 29.644027] [<8105c548>] clockevents_program_event+0xe7/0xf3 [ 29.644027] [<8105cc1c>] tick_program_event+0x1e/0x23 [ 29.644027] [<8103c43c>] hrtimer_force_reprogram+0x88/0x8f [ 29.644027] [<8103c49e>] __remove_hrtimer+0x5b/0x79 [ 29.644027] [<8103cb21>] hrtimer_try_to_cancel+0x49/0x66 [ 29.644027] [<8103cb4b>] hrtimer_cancel+0xd/0x18 [ 29.644027] [<8107f102>] perf_swevent_cancel_hrtimer.part.60+0x2b/0x30 [ 29.644027] [<81080705>] task_clock_event_stop+0x20/0x64 [ 29.644027] [<81080756>] task_clock_event_del+0xd/0xf [ 29.644027] [<81081350>] event_sched_out+0xab/0x11e [ 29.644027] [<810813e0>] group_sched_out+0x1d/0x66 [ 29.644027] [<81081682>] ctx_sched_out+0xaf/0xbf [ 29.644027] [<81081e04>] __perf_event_task_sched_out+0x1ed/0x34f [ 29.644027] [<8142cacc>] __schedule+0x4c6/0x4cb [ 29.644027] [<8142cae0>] schedule+0xf/0x11 [ 29.644027] [<8142f9a6>] work_resched+0x5/0x30 [ 29.644027] [ 29.644027] other info that might help us debug this: [ 29.644027] [ 29.644027] Chain exists of: [ 29.644027] &port_lock_key --> &ctx->lock --> hrtimer_bases.lock [ 29.644027] [ 29.644027] Possible unsafe locking scenario: [ 29.644027] [ 29.644027] CPU0 CPU1 [ 29.644027] ---- ---- [ 29.644027] lock(hrtimer_bases.lock); [ 29.644027] lock(&ctx->lock); [ 29.644027] lock(hrtimer_bases.lock); [ 29.644027] lock(&port_lock_key); [ 29.644027] [ 29.644027] *** DEADLOCK *** [ 29.644027] [ 29.644027] 4 locks held by trinity-main/74: [ 29.644027] #0: (&rq->lock){-.-.-.}, at: [<8142c6f3>] __schedule+0xed/0x4cb [ 29.644027] #1: (&ctx->lock){......}, at: [<81081df3>] __perf_event_task_sched_out+0x1dc/0x34f [ 29.644027] #2: (hrtimer_bases.lock){-.-...}, at: [<8103caeb>] hrtimer_try_to_cancel+0x13/0x66 [ 29.644027] #3: (console_lock){+.+...}, at: [<8104fb5d>] vprintk_emit+0x3c7/0x3e4 [ 29.644027] [ 29.644027] stack backtrace: [ 29.644027] CPU: 0 PID: 74 Comm: trinity-main Not tainted 3.15.0-rc8-06195-g939f04b #2 [ 29.644027] 00000000 81c3a310 8b995c14 81426f69 8b995c44 81425a99 8161f671 8161f570 [ 29.644027] 8161f538 8161f559 8161f538 8b995c78 8b142bb0 00000004 8b142fdc 8b142bb0 [ 29.644027] 8b995ca8 8104a62d 8b142fac 000016f2 81c3a310 00000001 00000001 00000003 [ 29.644027] Call Trace: [ 29.644027] [<81426f69>] dump_stack+0x16/0x18 [ 29.644027] [<81425a99>] print_circular_bug+0x18f/0x19c [ 29.644027] [<8104a62d>] __lock_acquire+0x9ea/0xc6d [ 29.644027] [<8104a942>] lock_acquire+0x92/0x101 [ 29.644027] [<811c60be>] ? serial8250_console_write+0x8c/0x10c [ 29.644027] [<811c6032>] ? wait_for_xmitr+0x76/0x76 [ 29.644027] [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e [ 29.644027] [<811c60be>] ? serial8250_console_write+0x8c/0x10c [ 29.644027] [<811c60be>] serial8250_console_write+0x8c/0x10c [ 29.644027] [<8104af87>] ? lock_release+0x191/0x223 [ 29.644027] [<811c6032>] ? wait_for_xmitr+0x76/0x76 [ 29.644027] [<8104e402>] call_console_drivers.constprop.31+0x87/0x118 [ 29.644027] [<8104f5d5>] console_unlock+0x1d7/0x398 [ 29.644027] [<8104fb70>] vprintk_emit+0x3da/0x3e4 [ 29.644027] [<81425f76>] printk+0x17/0x19 [ 29.644027] [<8105bfa0>] clockevents_program_min_delta+0x104/0x116 [ 29.644027] [<8105c548>] clockevents_program_event+0xe7/0xf3 [ 29.644027] [<8105cc1c>] tick_program_event+0x1e/0x23 [ 29.644027] [<8103c43c>] hrtimer_force_reprogram+0x88/0x8f [ 29.644027] [<8103c49e>] __remove_hrtimer+0x5b/0x79 [ 29.644027] [<8103cb21>] hrtimer_try_to_cancel+0x49/0x66 [ 29.644027] [<8103cb4b>] hrtimer_cancel+0xd/0x18 [ 29.644027] [<8107f102>] perf_swevent_cancel_hrtimer.part.60+0x2b/0x30 [ 29.644027] [<81080705>] task_clock_event_stop+0x20/0x64 [ 29.644027] [<81080756>] task_clock_event_del+0xd/0xf [ 29.644027] [<81081350>] event_sched_out+0xab/0x11e [ 29.644027] [<810813e0>] group_sched_out+0x1d/0x66 [ 29.644027] [<81081682>] ctx_sched_out+0xaf/0xbf [ 29.644027] [<81081e04>] __perf_event_task_sched_out+0x1ed/0x34f [ 29.644027] [<8104416d>] ? __dequeue_entity+0x23/0x27 [ 29.644027] [<81044505>] ? pick_next_task_fair+0xb1/0x120 [ 29.644027] [<8142cacc>] __schedule+0x4c6/0x4cb [ 29.644027] [<81047574>] ? trace_hardirqs_off_caller+0xd7/0x108 [ 29.644027] [<810475b0>] ? trace_hardirqs_off+0xb/0xd [ 29.644027] [<81056346>] ? rcu_irq_exit+0x64/0x77 git bisect start 9f6226a762c7ae02f6a23a3d4fc552dafa57ea23 v3.15 -- git bisect bad 71998d1be4ae70e7d320cdd21595c1a02a29c61e # 01:13 79- 5 Merge branch 'x86-irq-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip git bisect bad 9ee4d7a6538308a7681b638d2f35f2a301420355 # 01:24 3- 1 Merge branch 'akpm' (patches from Andrew Morton) git bisect bad 9894e6d9c020b754dd962960e9f7eac18282f69f # 01:58 128- 5 Merge tag 'fbdev-omap-dt-3.16' of git://git.kernel.org/pub/scm/linux/kernel/git/tomba/linux git bisect bad 963649d735c8b6eb0f97e82c54f02426ff3f1f45 # 02:06 48- 3 Merge tag 'for-linus-3.16-merge-window' of git://git.kernel.org/pub/scm/linux/kernel/git/ericvh/v9fs git bisect bad b20dcab9d4589ef9918a13c888c5493945adfc13 # 02:13 35- 1 Merge tag 'llvmlinux-for-v3.16' of git://git.linuxfoundation.org/llvmlinux/kernel git bisect bad 3f17ea6dea8ba5668873afa54628a91aaa3fb1c0 # 02:19 58- 4 Merge branch 'next' (accumulated 3.16 merge window patches) into master git bisect good 49eb7b0750d9483c74e9c14ae6ea1e9d62481c3c # 02:35 300+ 7 Merge tag 'tty-3.16-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/tty into next git bisect good 15b588303155b22edd559672905db8e59a44ef9a # 02:51 300+ 0 Merge tag 'fbdev-omap-3.16' of git://git.kernel.org/pub/scm/linux/kernel/git/tomba/linux into next git bisect good d09cc3659db494aca4b3bb2393c533fb4946b794 # 03:19 300+ 1 Merge branch 'irq-core-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip into next git bisect bad cc07aabc53978ae09a1d539237189f7c9841060a # 03:37 66- 2 Merge tag 'arm64-upstream' of git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux into next git bisect bad 8091b895b76f690aa2f6689b6ed602f07525a938 # 04:55 103- 1 fs/ncpfs/getopt.c: replace simple_strtoul by kstrtoul git bisect good d53aea3d46d64e95da9952887969f7533b9ab25e # 05:59 300+ 19 mm, compaction: return failed migration target pages back to freelist git bisect good 72d09633c9afa02bea317d65eb8b8a4ce7659a2a # 06:31 300+ 10 mm/zswap: NUMA aware allocation for zswap_dstmem git bisect bad 0046dd9fed0c9313cbb4fb860324476cd298dc9f # 06:35 42- 1 lib/string.c: use the name "C-string" in comments git bisect good 0a581694ab7a5bc083d710df8a552a6a055b005f # 06:54 300+ 15 printk: split code for making free space in the log buffer git bisect bad 939f04bec1a4ef6ba4370b0f34b01decc844b1b1 # 06:58 46- 2 printk: enable interrupts before calling console_trylock_for_printk() git bisect good 034633ccb24d675850f99bf85c1c5880c831e4b6 # 07:16 300+ 28 printk: return really stored message length git bisect good 608873cacb9d0d2811586fcc79a38b64eabd6d32 # 07:29 300+ 22 printk: release lockbuf_lock before calling console_trylock_for_printk() git bisect good bd8d7cf5b8410fe98eba06a9aaa90efe88815d8a # 07:42 300+ 7 printk: fix lockdep instrumentation of console_sem # first bad commit: [939f04bec1a4ef6ba4370b0f34b01decc844b1b1] printk: enable interrupts before calling console_trylock_for_printk() git bisect good bd8d7cf5b8410fe98eba06a9aaa90efe88815d8a # 08:21 900+ 41 printk: fix lockdep instrumentation of console_sem git bisect bad fb3ec67942e92e5713e05b7691b277d0a0c0575d # 08:21 0- 5 KVM: arm64: GICv3: mandate page-aligned GICV region git bisect good 6f0928036bcbd8dd2ebee9201580da8bcc0a81af # 08:49 900+ 87 Merge tag 'pm+acpi-3.16-rc8' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm This script may reproduce the error. ---------------------------------------------------------------------------- #!/bin/bash kernel=$1 initrd=quantal-core-i386.cgz wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/raw/master/initrd/$initrd kvm=( qemu-system-x86_64 -enable-kvm -cpu Haswell,+smep,+smap -kernel $kernel -initrd $initrd -m 320 -smp 2 -net nic,vlan=1,model=e1000 -net user,vlan=1 -boot order=nc -no-reboot -watchdog i6300esb -rtc base=localtime -serial stdio -display none -monitor null ) append=( hung_task_panic=1 earlyprintk=ttyS0,115200 debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=10 softlockup_panic=1 nmi_watchdog=panic prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal root=/dev/ram0 rw drbd.minor_count=8 ) "${kvm[@]}" --append "${append[*]}" ---------------------------------------------------------------------------- Thanks, Fengguang