[3.2.6] console lockup upon printk()?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



I got below failure while my code was printk()ing so frequently.

[   49.931115] left_op=38 right_op=48 left.type=1 right.type=1
[   49.931550] 3562::not matched
[   49.931559] left_op=38 right_op=48 left.type=1 right.type=1
[   49.931561] 3562::not matched
[  100.212171] BUG: soft lockup - CPU#0 stuck for 23s! [sh:3219]
[  100.212171] Modules linked in: binfmt_misc ccsecurity [last unloaded: scsi_wait_scan]
[  100.212171] irq event stamp: 42407026
[  100.212171] hardirqs last  enabled at (42407025): [<c139a185>] _raw_spin_unlock_irqrestore+0x35/0x60
[  100.212171] hardirqs last disabled at (42407026): [<c139a604>] apic_timer_interrupt+0x28/0x34
[  100.212171] softirqs last  enabled at (42405952): [<c1040cb1>] __do_softirq+0xe1/0x130
[  100.212171] softirqs last disabled at (42405947): [<c1004ad7>] do_softirq+0x87/0xd0
[  100.212171] Modules linked in: binfmt_misc ccsecurity [last unloaded: scsi_wait_scan]
[  100.212171] 
[  100.212171] Pid: 3219, comm: sh Not tainted 3.2.6-ccs-dev #1 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
[  100.212171] EIP: 0060:[<c139a187>] EFLAGS: 00000282 CPU: 0
[  100.212171] EIP is at _raw_spin_unlock_irqrestore+0x37/0x60
[  100.212171] EAX: d7b9a6a0 EBX: c150ec60 ECX: 00000006 EDX: d7b9ab28
[  100.212171] ESI: 00000282 EDI: 00001e01 EBP: dd725d8c ESP: dd725d84
[  100.212171]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[  100.212171] Process sh (pid: 3219, ti=dd724000 task=d7b9a6a0 task.ti=dd724000)
[  100.212171] Stack:
[  100.212171]  00129e02 00000000 dd725db0 c103b825 00000001 ffffc000 00000282 00129e02
[  100.212171]  c1520380 dd725de8 00500001 dd725dc4 c103b9a2 dd978f30 dabb9db4 00000000
[  100.212171]  dd725df8 c1203fe0 d7b9a6a0 dd725dec dabb9db4 d7b9a6a0 00008802 00000000
[  100.212171] Call Trace:
[  100.212171]  [<c103b825>] console_unlock+0x1e5/0x250
[  100.212171]  [<c103b9a2>] console_device+0x42/0x50
[  100.212171]  [<c1203fe0>] tty_open+0x3d0/0x4f0
[  100.212171]  [<c10ccdfa>] chrdev_open+0xba/0x190
[  100.212171]  [<c10c6c88>] __dentry_open+0x258/0x340
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10c6dde>] nameidata_to_filp+0x6e/0x80
[  100.212171]  [<c10ccd40>] ? cdev_put+0x20/0x20
[  100.212171]  [<c10d4e8f>] do_last+0x37f/0x780
[  100.212171]  [<c10d5f7b>] path_openat+0x9b/0x310
[  100.212171]  [<c10d62d0>] do_filp_open+0x30/0x80
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10e296c>] ? alloc_fd+0x14c/0x190
[  100.212171]  [<c10c80eb>] do_sys_open+0xeb/0x1b0
[  100.212171]  [<c10cd8e3>] ? sys_readlinkat+0x83/0xa0
[  100.212171]  [<c10c8219>] sys_open+0x29/0x40
[  100.212171]  [<c139aa4c>] sysenter_do_call+0x12/0x32
[  100.212171] Code: 89 c3 89 74 24 04 8d 40 10 89 d6 ba 01 00 00 00 e8 ff 2d cd ff 89 d8 e8 98 11 e2 ff f7 c6 00 02 00 00 74 18 e8 1b 15 cd ff 56 9d <8b> 1c 24 8b 74 24 04 89 ec 5d c3 8d b6 00 00 00 00 56 9d e8 01 
[  100.212171] Call Trace:
[  100.212171]  [<c103b825>] console_unlock+0x1e5/0x250
[  100.212171]  [<c103b9a2>] console_device+0x42/0x50
[  100.212171]  [<c1203fe0>] tty_open+0x3d0/0x4f0
[  100.212171]  [<c10ccdfa>] chrdev_open+0xba/0x190
[  100.212171]  [<c10c6c88>] __dentry_open+0x258/0x340
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10c6dde>] nameidata_to_filp+0x6e/0x80
[  100.212171]  [<c10ccd40>] ? cdev_put+0x20/0x20
[  100.212171]  [<c10d4e8f>] do_last+0x37f/0x780
[  100.212171]  [<c10d5f7b>] path_openat+0x9b/0x310
[  100.212171]  [<c10d62d0>] do_filp_open+0x30/0x80
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10e296c>] ? alloc_fd+0x14c/0x190
[  100.212171]  [<c10c80eb>] do_sys_open+0xeb/0x1b0
[  100.212171]  [<c10cd8e3>] ? sys_readlinkat+0x83/0xa0
[  100.212171]  [<c10c8219>] sys_open+0x29/0x40
[  100.212171]  [<c139aa4c>] sysenter_do_call+0x12/0x32
[  100.212171] Kernel panic - not syncing: softlockup: hung tasks
[  100.212171] Pid: 3219, comm: sh Not tainted 3.2.6-ccs-dev #1
[  100.212171] Call Trace:
[  100.212171]  [<c1396a90>] panic+0x57/0x166
[  100.212171]  [<c10879f1>] watchdog_timer_fn+0x171/0x180
[  100.212171]  [<c105a668>] hrtimer_run_queues+0xb8/0x270
[  100.212171]  [<c1087880>] ? touch_softlockup_watchdog_sync+0x30/0x30
[  100.212171]  [<c1046f08>] run_local_timers+0x8/0x20
[  100.212171]  [<c1046f4f>] update_process_times+0x2f/0x70
[  100.212171]  [<c1065b45>] tick_periodic+0x25/0x80
[  100.212171]  [<c1065bb9>] tick_handle_periodic+0x19/0x80
[  100.212171]  [<c101ca4f>] smp_apic_timer_interrupt+0x4f/0x90
[  100.212171]  [<c11ab574>] ? trace_hardirqs_off_thunk+0xc/0x18
[  100.212171]  [<c139a60b>] apic_timer_interrupt+0x2f/0x34
[  100.212171]  [<c139a187>] ? _raw_spin_unlock_irqrestore+0x37/0x60
[  100.212171]  [<c103b825>] console_unlock+0x1e5/0x250
[  100.212171]  [<c103b9a2>] console_device+0x42/0x50
[  100.212171]  [<c1203fe0>] tty_open+0x3d0/0x4f0
[  100.212171]  [<c10ccdfa>] chrdev_open+0xba/0x190
[  100.212171]  [<c10c6c88>] __dentry_open+0x258/0x340
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10c6dde>] nameidata_to_filp+0x6e/0x80
[  100.212171]  [<c10ccd40>] ? cdev_put+0x20/0x20
[  100.212171]  [<c10d4e8f>] do_last+0x37f/0x780
[  100.212171]  [<c10d5f7b>] path_openat+0x9b/0x310
[  100.212171]  [<c10d62d0>] do_filp_open+0x30/0x80
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10e296c>] ? alloc_fd+0x14c/0x190
[  100.212171]  [<c10c80eb>] do_sys_open+0xeb/0x1b0
[  100.212171]  [<c10cd8e3>] ? sys_readlinkat+0x83/0xa0
[  100.212171]  [<c10c8219>] sys_open+0x29/0x40
[  100.212171]  [<c139aa4c>] sysenter_do_call+0x12/0x32
[  100.212171] ------------[ cut here ]------------
[  100.212171] WARNING: at kernel/lockdep.c:2592 trace_hardirqs_on_caller+0x15d/0x1c0()
[  100.212171] Hardware name: VMware Virtual Platform
[  100.212171] Modules linked in: binfmt_misc ccsecurity [last unloaded: scsi_wait_scan]
[  100.212171] Pid: 3219, comm: sh Not tainted 3.2.6-ccs-dev #1
[  100.212171] Call Trace:
[  100.212171]  [<c103acbd>] warn_slowpath_common+0x6d/0xa0
[  100.212171]  [<c106b63d>] ? trace_hardirqs_on_caller+0x15d/0x1c0
[  100.212171]  [<c106b63d>] ? trace_hardirqs_on_caller+0x15d/0x1c0
[  100.212171]  [<c1396b60>] ? panic+0x127/0x166
[  100.212171]  [<c103ad0d>] warn_slowpath_null+0x1d/0x20
[  100.212171]  [<c106b63d>] trace_hardirqs_on_caller+0x15d/0x1c0
[  100.212171]  [<c106b6ab>] trace_hardirqs_on+0xb/0x10
[  100.212171]  [<c1396b60>] panic+0x127/0x166
[  100.212171]  [<c10879f1>] watchdog_timer_fn+0x171/0x180
[  100.212171]  [<c105a668>] hrtimer_run_queues+0xb8/0x270
[  100.212171]  [<c1087880>] ? touch_softlockup_watchdog_sync+0x30/0x30
[  100.212171]  [<c1046f08>] run_local_timers+0x8/0x20
[  100.212171]  [<c1046f4f>] update_process_times+0x2f/0x70
[  100.212171]  [<c1065b45>] tick_periodic+0x25/0x80
[  100.212171]  [<c1065bb9>] tick_handle_periodic+0x19/0x80
[  100.212171]  [<c101ca4f>] smp_apic_timer_interrupt+0x4f/0x90
[  100.212171]  [<c11ab574>] ? trace_hardirqs_off_thunk+0xc/0x18
[  100.212171]  [<c139a60b>] apic_timer_interrupt+0x2f/0x34
[  100.212171]  [<c139a187>] ? _raw_spin_unlock_irqrestore+0x37/0x60
[  100.212171]  [<c103b825>] console_unlock+0x1e5/0x250
[  100.212171]  [<c103b9a2>] console_device+0x42/0x50
[  100.212171]  [<c1203fe0>] tty_open+0x3d0/0x4f0
[  100.212171]  [<c10ccdfa>] chrdev_open+0xba/0x190
[  100.212171]  [<c10c6c88>] __dentry_open+0x258/0x340
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10c6dde>] nameidata_to_filp+0x6e/0x80
[  100.212171]  [<c10ccd40>] ? cdev_put+0x20/0x20
[  100.212171]  [<c10d4e8f>] do_last+0x37f/0x780
[  100.212171]  [<c10d5f7b>] path_openat+0x9b/0x310
[  100.212171]  [<c10d62d0>] do_filp_open+0x30/0x80
[  100.212171]  [<c139a1cd>] ? _raw_spin_unlock+0x1d/0x20
[  100.212171]  [<c10e296c>] ? alloc_fd+0x14c/0x190
[  100.212171]  [<c10c80eb>] do_sys_open+0xeb/0x1b0
[  100.212171]  [<c10cd8e3>] ? sys_readlinkat+0x83/0xa0
[  100.212171]  [<c10c8219>] sys_open+0x29/0x40
[  100.212171]  [<c139aa4c>] sysenter_do_call+0x12/0x32
[  100.212171] ---[ end trace 982e5dcc48c519ad ]---

Lookingt at console_unlock()

1249 void console_unlock(void)
1250 {
1251         unsigned long flags;
1252         unsigned _con_start, _log_end;
1253         unsigned wake_klogd = 0, retry = 0;
1254 
1255         if (console_suspended) {
1256                 up(&console_sem);
1257                 return;
1258         }
1259 
1260         console_may_schedule = 0;
1261 
1262 again:
1263         for ( ; ; ) {
1264                 raw_spin_lock_irqsave(&logbuf_lock, flags);
1265                 wake_klogd |= log_start - log_end;
1266                 if (con_start == log_end)
1267                         break;                  /* Nothing to print */
1268                 _con_start = con_start;
1269                 _log_end = log_end;
1270                 con_start = log_end;            /* Flush */
1271                 raw_spin_unlock(&logbuf_lock);
1272                 stop_critical_timings();        /* don't trace print latency */
1273                 call_console_drivers(_con_start, _log_end);
1274                 start_critical_timings();
1275                 local_irq_restore(flags);
1276         }
1277         console_locked = 0;
1278 
1279         /* Release the exclusive_console once it is used */
1280         if (unlikely(exclusive_console))
1281                 exclusive_console = NULL;
1282 
1283         raw_spin_unlock(&logbuf_lock);
1284 
1285         up(&console_sem);
1286 
1287         /*
1288          * Someone could have filled up the buffer again, so re-check if there's
1289          * something to flush. In case we cannot trylock the console_sem again,
1290          * there's a new owner and the console_unlock() from them will do the
1291          * flush, no worries.
1292          */
1293         raw_spin_lock(&logbuf_lock);
1294         if (con_start != log_end)
1295                 retry = 1;
1296         raw_spin_unlock_irqrestore(&logbuf_lock, flags);

it is spinning here. Is

  raw_spin_lock_irqsave(&logbuf_lock, flags);
  raw_spin_unlock(&logbuf_lock);
  up(&console_sem);
  raw_spin_lock(&logbuf_lock);
  raw_spin_unlock_irqrestore(&logbuf_lock, flags);

sequence safe even if debugging options are enabled?

1297 
1298         if (retry && console_trylock())
1299                 goto again;
1300 
1301         if (wake_klogd)
1302                 wake_up_klogd();
1303 }

$ grep LOCK .config
CONFIG_CLOCKSOURCE_WATCHDOG=y
CONFIG_GENERIC_CLOCKEVENTS=y
CONFIG_GENERIC_CLOCKEVENTS_BROADCAST=y
CONFIG_LOCKDEP_SUPPORT=y
# CONFIG_RWSEM_GENERIC_SPINLOCK is not set
CONFIG_HAVE_UNSTABLE_SCHED_CLOCK=y
CONFIG_BLOCK=y
# CONFIG_INLINE_SPIN_TRYLOCK is not set
# CONFIG_INLINE_SPIN_TRYLOCK_BH is not set
# CONFIG_INLINE_SPIN_LOCK is not set
# CONFIG_INLINE_SPIN_LOCK_BH is not set
# CONFIG_INLINE_SPIN_LOCK_IRQ is not set
# CONFIG_INLINE_SPIN_LOCK_IRQSAVE is not set
# CONFIG_INLINE_SPIN_UNLOCK is not set
# CONFIG_INLINE_SPIN_UNLOCK_BH is not set
# CONFIG_INLINE_SPIN_UNLOCK_IRQ is not set
# CONFIG_INLINE_SPIN_UNLOCK_IRQRESTORE is not set
# CONFIG_INLINE_READ_TRYLOCK is not set
# CONFIG_INLINE_READ_LOCK is not set
# CONFIG_INLINE_READ_LOCK_BH is not set
# CONFIG_INLINE_READ_LOCK_IRQ is not set
# CONFIG_INLINE_READ_LOCK_IRQSAVE is not set
# CONFIG_INLINE_READ_UNLOCK is not set
# CONFIG_INLINE_READ_UNLOCK_BH is not set
# CONFIG_INLINE_READ_UNLOCK_IRQ is not set
# CONFIG_INLINE_READ_UNLOCK_IRQRESTORE is not set
# CONFIG_INLINE_WRITE_TRYLOCK is not set
# CONFIG_INLINE_WRITE_LOCK is not set
# CONFIG_INLINE_WRITE_LOCK_BH is not set
# CONFIG_INLINE_WRITE_LOCK_IRQ is not set
# CONFIG_INLINE_WRITE_LOCK_IRQSAVE is not set
# CONFIG_INLINE_WRITE_UNLOCK is not set
# CONFIG_INLINE_WRITE_UNLOCK_BH is not set
# CONFIG_INLINE_WRITE_UNLOCK_IRQ is not set
# CONFIG_INLINE_WRITE_UNLOCK_IRQRESTORE is not set
CONFIG_GENERIC_CLOCKEVENTS_BUILD=y
CONFIG_GENERIC_CLOCKEVENTS_MIN_ADJUST=y
CONFIG_HAVE_MEMBLOCK=y
CONFIG_SPLIT_PTLOCK_CPUS=999999
# CONFIG_TELCLOCK is not set
CONFIG_I8253_LOCK=y
CONFIG_FILE_LOCKING=y
CONFIG_LOCKD=y
CONFIG_LOCKD_V4=y
CONFIG_LOCKUP_DETECTOR=y
CONFIG_HARDLOCKUP_DETECTOR=y
# CONFIG_BOOTPARAM_HARDLOCKUP_PANIC is not set
CONFIG_BOOTPARAM_HARDLOCKUP_PANIC_VALUE=0
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC=y
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=1
CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_LOCK_ALLOC=y
CONFIG_PROVE_LOCKING=y
CONFIG_LOCKDEP=y
CONFIG_LOCK_STAT=y
CONFIG_DEBUG_LOCKDEP=y
CONFIG_DEBUG_LOCKING_API_SELFTESTS=y
# CONFIG_DEBUG_BLOCK_EXT_DEVT is not set
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


[Index of Archives]

  Powered by Linux

[Older Kernel Discussion]     [Yosemite National Park Forum]     [Large Format Photos]     [Gimp]     [Yosemite Photos]     [Stuff]     [Index of Other Archives]