Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600

[Petr Mladek]

On Tue 2016-02-23 08:55:03, kernel test robot wrote:
> FYI, we noticed the below changes on
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master
> commit 34578dc67f38c02ccbe696e4099967884caa8e15 ("printk: set may_schedule for some of console_trylock() callers")
> 
> 
> +------------------------------------------------+------------+------------+
> |                                                | 08e0722e8e | 34578dc67f |
> +------------------------------------------------+------------+------------+
> | boot_successes                                 | 0          | 0          |
> | boot_failures                                  | 98         | 100        |
> | BUG:kernel_torture_test_oversize               | 98         | 50         |
> | EIP_is_at_raw_spin_unlock_irqrestore           | 0          | 3          |
> | Kernel_panic-not_syncing:softlockup:hung_tasks | 0          | 50         |
> | backtrace:of_unittest                          | 0          | 50         |
> | backtrace:kernel_init_freeable                 | 0          | 50         |
> | EIP_is_at_vprintk_emit                         | 0          | 28         |
> | EIP_is_at_lock_acquire                         | 0          | 5          |
> | EIP_is_at_of_unittest_overlay                  | 0          | 8          |
> | EIP_is_at_mutex_lock_nested                    | 0          | 1          |
> | EIP_is_at__mutex_unlock_slowpath               | 0          | 2          |
> | EIP_is_at_of_overlay_destroy                   | 0          | 1          |
> | EIP_is_at_idr_find_slowpath                    | 0          | 1          |
> | EIP_is_at___might_sleep                        | 0          | 1          |
> +------------------------------------------------+------------+------------+
> 
> 
> 
> [   33.497678] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
> [   33.497693] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper:1]
> [   33.497693] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper:1]
> [   33.497695] Modules linked in:
> [   33.497695] Modules linked in:
> [   33.497696] irq event stamp: 69018756
> [   33.497696] irq event stamp: 69018756
> [   33.497700] hardirqs last  enabled at (69018755): [<c068e185>] vprintk_emit+0x1e5/0x600
> [   33.497700] hardirqs last  enabled at (69018755): [<c068e185>] vprintk_emit+0x1e5/0x600
> [   33.497704] hardirqs last disabled at (69018756): [<c0a091b8>] apic_timer_interrupt+0x28/0x40
> [   33.497704] hardirqs last disabled at (69018756): [<c0a091b8>] apic_timer_interrupt+0x28/0x40
> [   33.497707] softirqs last  enabled at (68988726): [<c064cf32>] __do_softirq+0x312/0x3f0
> [   33.497707] softirqs last  enabled at (68988726): [<c064cf32>] __do_softirq+0x312/0x3f0
> [   33.497710] softirqs last disabled at (68988719): [<c0604c7e>] do_softirq_own_stack+0x1e/0x30
> [   33.497710] softirqs last disabled at (68988719): [<c0604c7e>] do_softirq_own_stack+0x1e/0x30
> [   33.497713] CPU: 0 PID: 1 Comm: swapper Not tainted 4.5.0-rc4-00295-g34578dc #1
> [   33.497713] CPU: 0 PID: 1 Comm: swapper Not tainted 4.5.0-rc4-00295-g34578dc #1
> [   33.497714] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014
> [   33.497714] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014
> [   33.497715] task: b0058000 ti: b0060000 task.ti: b0060000
> [   33.497715] task: b0058000 ti: b0060000 task.ti: b0060000
> [   33.497716] EIP: 0060:[<c068e18a>] EFLAGS: 00000246 CPU: 0
> [   33.497716] EIP: 0060:[<c068e18a>] EFLAGS: 00000246 CPU: 0
> [   33.497718] EIP is at vprintk_emit+0x1ea/0x600

This is located rather early in vprintk_emit(). It seems to be long
before the console is called.

Could you please tell us what exact code line corresponds with
vprintk_emit+0x1ea offset?


Best Regards,
Petr