Hi Jan, 0day kernel testing robot got the below dmesg and the first bad commit is git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master commit bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0 Author: Jan Kara AuthorDate: Thu May 22 10:43:35 2014 +1000 Commit: Stephen Rothwell CommitDate: Thu May 22 10:43:35 2014 +1000 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 +----------------------------------------------------+------------+------------+ | | ee75ecbd8b | bafe980f5a | +----------------------------------------------------+------------+------------+ | boot_successes | 60 | 0 | | boot_failures | 0 | 20 | | BUG:spinlock_lockup_suspected_on_CPU | 0 | 20 | | INFO:possible_circular_locking_dependency_detected | 0 | 20 | | backtrace:do_sys_open | 0 | 20 | | backtrace:SyS_open | 0 | 20 | | backtrace:kernel_init_freeable | 0 | 20 | | backtrace:print_ICs | 0 | 20 | | backtrace:setup_default_timer_irq | 0 | 20 | | backtrace:hpet_time_init | 0 | 20 | | backtrace:x86_late_time_init | 0 | 20 | +----------------------------------------------------+------------+------------+ [ 7.490555] EDD information not available. [ 7.490999] ### dt-test ### No testcase data in device tree; not running tests [ 7.491848] [ 7.492350] BUG: spinlock lockup suspected on CPU#0, swapper/1 [ 7.492350] lock: serial8250_ports+0x0/0x4c0, .magic: dead4ead, .owner: swapper/1, .owner_cpu: 0 [ 7.492350] CPU: 0 PID: 1 Comm: swapper Not tainted 3.15.0-rc5-00567-gbafe980 #1 [ 7.492350] 80038000 80038000 80027a8c 81b9bd30 80027ab4 81b968d0 81eb5198 82755f80 [ 7.492350] dead4ead 80038340 00000001 00000000 82755f80 a08b8bfc 80027ad0 81077777 [ 7.492350] a08b8bfc 00000000 82755f80 00000086 00000001 80027af0 81baeda4 00000000 [ 7.492350] Call Trace: [ 7.492350] [<81b9bd30>] dump_stack+0x16/0x18 [ 7.492350] [<81b968d0>] spin_dump+0x90/0x97 [ 7.492350] [<81077777>] do_raw_spin_lock+0xa7/0xf0 [ 7.492350] [<81baeda4>] _raw_spin_lock_irqsave+0x54/0x60 [ 7.492350] [<815f652c>] ? serial8250_console_write+0x11c/0x140 [ 7.492350] [<815f6410>] ? serial8250_modem_status+0xc0/0xc0 [ 7.492350] [<815f652c>] serial8250_console_write+0x11c/0x140 [ 7.492350] [<815f6410>] ? serial8250_modem_status+0xc0/0xc0 [ 7.492350] [<8107b534>] call_console_drivers.constprop.20+0x64/0x130 [ 7.492350] [<8107bcb5>] console_unlock+0x445/0x4d0 [ 7.492350] [<8107be98>] vprintk_emit+0x158/0x4d0 [ 7.492350] [<81b969b9>] printk+0x38/0x3a [ 7.492350] [<81b95fd0>] print_circular_bug_header+0x35/0xc1 [ 7.492350] [<81b960c6>] print_circular_bug+0x6a/0x268 [ 7.492350] [<810743c2>] __lock_acquire+0x19c2/0x1b20 [ 7.492350] [<81070d18>] ? check_irq_usage+0x88/0xc0 [ 7.492350] [<810750e5>] lock_acquire+0x85/0x190 [ 7.492350] [<8107dc8c>] ? __irq_get_desc_lock+0x3c/0x70 [ 7.492350] [<81baed9d>] _raw_spin_lock_irqsave+0x4d/0x60 [ 7.492350] [<8107dc8c>] ? __irq_get_desc_lock+0x3c/0x70 [ 7.492350] [<8107dc8c>] __irq_get_desc_lock+0x3c/0x70 [ 7.492350] [<8107eb1e>] __disable_irq_nosync+0x1e/0x50 [ 7.492350] [<8107eb58>] disable_irq_nosync+0x8/0x10 [ 7.492350] [<815f5c78>] serial8250_startup+0x488/0x720 [ 7.492350] [<810de6d0>] ? __get_free_pages+0x20/0x40 [ 7.492350] [<815f205e>] uart_startup.part.4+0x6e/0x1e0 [ 7.492350] [<815f2a40>] uart_open+0xe0/0x140 [ 7.492350] [<815f2960>] ? uart_ioctl+0x2f0/0x2f0 [ 7.492350] [<815e4b51>] tty_open+0x141/0x510 [ 7.492350] [<815e4a10>] ? tty_ioctl+0xb20/0xb20 [ 7.492350] [<81118bc0>] chrdev_open+0x60/0x140 [ 7.492350] [<8111372c>] do_dentry_open+0x14c/0x230 [ 7.492350] [<81118b60>] ? exact_lock+0x20/0x20 [ 7.492350] [<8111459e>] finish_open+0x2e/0x40 [ 7.492350] [<8112132a>] do_last+0x4aa/0xd30 [ 7.492350] [<8111f4fd>] ? link_path_walk+0x1dd/0x700 [ 7.492350] [<81121c5a>] path_openat+0xaa/0x610 [ 7.492350] [<811221ec>] do_filp_open+0x2c/0x70 [ 7.492350] [<81114a81>] do_sys_open+0x111/0x210 [ 7.492350] [<81600000>] ? _xfer_secondary_pool+0x150/0x230 [ 7.492350] [<81114b9d>] SyS_open+0x1d/0x20 [ 7.492350] [<8212bda4>] kernel_init_freeable+0x1c6/0x236 [ 7.492350] [<8212b4f2>] ? do_early_param+0x78/0x78 [ 7.492350] [<81b9238b>] kernel_init+0xb/0xd0 [ 7.492350] [<81063b12>] ? schedule_tail+0x12/0x40 [ 7.492350] [<81bb0080>] ret_from_kernel_thread+0x20/0x30 [ 7.492350] [<81b92380>] ? rest_init+0x130/0x130 [ 7.492350] ====================================================== git bisect start 07dd999f99b1135fdece697e17c4f4248ab40f72 53a4fdb4a7c8aeef977f8450bcdb92d1962e321e -- git bisect bad 54af61db1031c7ddef016987e9938cbbbaf92968 # 09:12 0- 18 Merge branch 'akpm-current/current' git bisect good d93e8dbb6c2cd2fde8d46e1ad12d19ffa1868747 # 09:19 20+ 0 mm: page_alloc: use unsigned int for order in more places git bisect bad 7ff60469e63f2bd110582cdf8ba95afa694bf7c6 # 09:24 0- 4 rtc: rtc-mv: make of_device_id array const git bisect bad 3c3ad385a174d5d2490b2f9c6513b588dc8a1ddb # 09:27 0- 19 printk: disable preemption for printk_sched git bisect good 456407d6fec5f28c1be67fcf803f9cca14b75142 # 09:31 20+ 0 do_shared_fault(): check that mmap_sem is held git bisect good e94a01e20b75345d1486e7d0bdf03313f8f47d0b # 09:36 20+ 0 kernel/utsname_sysctl.c: replace obsolete __initcall by device_initcall git bisect good 6f83a1a8d7e0a9e71f3ee1641a965aede0ee4c6c # 09:49 20+ 0 printk: shrink too long messages git bisect good 3bd16050e9c555cb7b08a4f830db95e9025336e6 # 09:54 20+ 0 printk-release-lockbuf_lock-before-calling-console_trylock_for_printk-fix git bisect bad bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0 # 10:00 0- 4 printk: enable interrupts before calling console_trylock_for_printk() git bisect good ee75ecbd8b9ad26cd0094573cd4b612ab20b3e71 # 10:10 20+ 0 printk: fix lockdep instrumentation of console_sem # first bad commit: [bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0] printk: enable interrupts before calling console_trylock_for_printk() git bisect good ee75ecbd8b9ad26cd0094573cd4b612ab20b3e71 # 10:13 60+ 0 printk: fix lockdep instrumentation of console_sem git bisect bad 07dd999f99b1135fdece697e17c4f4248ab40f72 # 10:13 0- 13 Add linux-next specific files for 20140529 git bisect good a991639c26c7231ddb6de7f34899fb70832b7d04 # 10:18 60+ 0 Merge tag 'arm64-fixes' of git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux git bisect bad 07dd999f99b1135fdece697e17c4f4248ab40f72 # 10:18 0- 13 Add linux-next specific files for 20140529 This script may reproduce the error. ----------------------------------------------------------------------------- #!/bin/bash kernel=$1 initrd=yocto-minimal-i386.cgz wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/blob/master/initrd/$initrd kvm=( qemu-system-x86_64 -cpu kvm64 -enable-kvm -kernel $kernel -initrd $initrd -smp 2 -m 256M -net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio -net user,vlan=0 -net nic,vlan=1,model=e1000 -net user,vlan=1 -boot order=nc -no-reboot -watchdog i6300esb -serial stdio -display none -monitor null ) append=( debug sched_debug apic=debug ignore_loglevel sysrq_always_enabled panic=10 prompt_ramdisk=0 earlyprintk=ttyS0,115200 console=ttyS0,115200 console=tty0 vga=normal root=/dev/ram0 rw ) "${kvm[@]}" --append "${append[*]}" ----------------------------------------------------------------------------- Thanks, Jet