* printk() from NMI backtrace can delay a lot
@ 2018-07-02 10:26 Tetsuo Handa
2018-07-02 10:39 ` Sergey Senozhatsky
2018-07-03 4:30 ` Sergey Senozhatsky
0 siblings, 2 replies; 8+ messages in thread
From: Tetsuo Handa @ 2018-07-02 10:26 UTC (permalink / raw)
To: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Peter Zijlstra,
Sergey Senozhatsky
Cc: linux-kernel, Dmitry Vyukov
Hello.
Today I was testing conditions when/how stall watchdog fires. I noticed that
printing NMI backtraces to consoles is delayed till IRQ is enabled or somebody
else schedules printk(). This is not a welcomed behavior when the cause of
lock up is doing nearly-infinite loop with IRQ disabled. Can we improve this?
----------
static int __init ccs_init(void)
{
unsigned long stamp = jiffies;
local_irq_disable();
while (time_before(jiffies, stamp + 130 * HZ)) /* Emulating a lockup bug. */
;
local_irq_enable();
return -EINVAL;
}
----------
Below samples used netconsole in order to show the lag between printk() saved uptime
and printk() wrote the pending lines.
Loading the module after
echo 25 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
----------
2018-07-02 12:11:40 192.168.159.129:6666 [ 58.090624] netconsole: network logging started
2018-07-02 12:12:11 192.168.159.129:6666 [ 89.017794] akari_test: loading out-of-tree module taints kernel.
2018-07-02 12:12:41 192.168.159.129:6666 [ 119.024961] INFO: rcu_sched detected stalls on CPUs/tasks:
2018-07-02 12:12:41 192.168.159.129:6666 [ 119.026970] 2-...0: (0 ticks this GP) idle=0be/1/4611686018427387904 softirq=5544/5544 fqs=7077
2018-07-02 12:12:41 192.168.159.129:6666 [ 119.030076] (detected by 3, t=30005 jiffies, g=2553, c=2552, q=94)
2018-07-02 12:12:41 192.168.159.129:6666 [ 119.032142] Sending NMI from CPU 3 to CPUs 2:
/* Here is a 32 seconds of lag which is flushed by */
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033877] NMI backtrace for cpu 2
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033884] CPU: 2 PID: 10038 Comm: insmod Tainted: G O 4.18.0-rc3 #643
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033886] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033895] RIP: 0010:__sanitizer_cov_trace_pc+0x20/0x50
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033896] Code: 5d c3 90 90 90 90 90 90 90 90 55 65 48 8b 04 25 40 5e 01 00 48 89 e5 65 8b 15 6c f6 d1 7e 81 e2 00 01 1f 00 48 8b 4d 08 75 2b <8b> 90 80 12 00 00 83 fa 02 75 20 48 8b b0 88 12 00 00 8b 80 84 12
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033942] RSP: 0018:ffffc9000205fc60 EFLAGS: 00000046
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033945] RAX: ffff880136312080 RBX: 00000000fffcc7e1 RCX: ffffffffa000d038
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033947] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffffa000d033
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033949] RBP: ffffc9000205fc60 R08: 0000000000000001 R09: 0000000000000000
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033951] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffa000d000
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033953] R13: ffff8801351cd940 R14: 0000000000000001 R15: ffffc9000205fe78
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033956] FS: 00007f90d3e62740(0000) GS:ffff88013a680000(0000) knlGS:0000000000000000
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033958] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033961] CR2: 00000000015051d8 CR3: 0000000136a66004 CR4: 00000000000606e0
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.033998] Call Trace:
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034006] ccs_init+0x38/0x79 [akari_test]
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034011] do_one_initcall+0x7a/0x460
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034016] ? trace_hardirqs_on+0xd/0x10
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034021] do_init_module+0x5a/0x1e0
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034024] load_module+0x2144/0x2800
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034030] __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034033] ? __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034038] __x64_sys_finit_module+0x15/0x20
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034041] do_syscall_64+0x81/0x260
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034047] entry_SYSCALL_64_after_hwframe+0x49/0xbe
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034050] RIP: 0033:0x7f90d3335ec9
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034050] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 cf 2c 00 f7 d8 64 89 01 48
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034096] RSP: 002b:00007ffce0ff8338 EFLAGS: 00000202 ORIG_RAX: 0000000000000139
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034100] RAX: ffffffffffffffda RBX: 00000000015051e0 RCX: 00007f90d3335ec9
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034102] RDX: 0000000000000000 RSI: 000000000041aa0e RDI: 0000000000000003
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034104] RBP: 000000000041aa0e R08: 0000000000000000 R09: 00007ffce0ff84d8
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034105] R10: 0000000000000003 R11: 0000000000000202 R12: 0000000000000000
2018-07-02 12:13:13 192.168.159.129:6666 [ 119.034107] R13: 0000000001504120 R14: 0000000000000000 R15: 0000000000000000
/* somebody else's printk(). */
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.518735] BUG: workqueue lockup - pool cpus=2 node=0 flags=0x0 nice=0 stuck for 61s!
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.598965] Showing busy workqueues and worker pools:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.601027] workqueue mm_percpu_wq: flags=0x8
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.602688] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.605458] pending: vmstat_update
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606825]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606827] ======================================================
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606829] WARNING: possible circular locking dependency detected
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606831] 4.18.0-rc3 #643 Tainted: G O
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606832] ------------------------------------------------------
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606834] swapper/0/0 is trying to acquire lock:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606840]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606841] but task is already holding lock:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606847]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606848] which lock already depends on the new lock.
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606849]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606849]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606851] the existing dependency chain (in reverse order) is:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606852]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606852] -> #4 (&(&pool->lock)->rlock){-.-.}:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606857] _raw_spin_lock+0x2a/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606858] __queue_work+0xfb/0x780
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606859] queue_work_on+0xde/0x110
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606861] put_pwq+0x85/0x90
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606862] put_pwq_unlocked.part.29+0x1d/0x30
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606863] destroy_workqueue+0x2df/0x320
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606865] tipc_topsrv_stop+0x1a0/0x290
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606866] tipc_exit_net+0x15/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606867] ops_exit_list.isra.8+0x4e/0x90
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606869] cleanup_net+0x219/0x390
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606870] process_one_work+0x2ec/0x800
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606871] worker_thread+0x45/0x4d0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606872] kthread+0x14c/0x170
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606874] ret_from_fork+0x3a/0x50
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606874]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606875] -> #3 (&pool->lock/1){-.-.}:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606880] _raw_spin_lock+0x2a/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606881] __queue_work+0xfb/0x780
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606882] queue_work_on+0xde/0x110
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606884] tty_flip_buffer_push+0x2f/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606885] pty_write+0xb0/0xc0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606886] n_tty_write+0x244/0x620
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606887] tty_write+0x1e3/0x3f0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606888] __vfs_write+0x54/0x270
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606890] vfs_write+0xf0/0x230
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606891] redirected_tty_write+0x61/0xb0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606892] do_iter_write+0x1ce/0x220
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606893] vfs_writev+0xb0/0x140
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606895] do_writev+0x6d/0x120
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606896] __x64_sys_writev+0x20/0x30
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606897] do_syscall_64+0x81/0x260
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606899] entry_SYSCALL_64_after_hwframe+0x49/0xbe
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606899]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606900] -> #2 (&(&port->lock)->rlock){-.-.}:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606905] _raw_spin_lock_irqsave+0x56/0x70
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606906] tty_port_tty_get+0x20/0x60
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606907] tty_port_default_wakeup+0x15/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606909] tty_port_tty_wakeup+0x20/0x30
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606910] uart_write_wakeup+0x26/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606911] serial8250_tx_chars+0x1ae/0x2d0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606913] serial8250_handle_irq.part.23+0x108/0x130
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606915] serial8250_default_handle_irq+0x7a/0x90
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606916] serial8250_interrupt+0x77/0x110
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606918] __handle_irq_event_percpu+0x80/0x480
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606919] handle_irq_event_percpu+0x35/0x90
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606920] handle_irq_event+0x39/0x60
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606922] handle_edge_irq+0xa5/0x230
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606923] handle_irq+0xae/0x120
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606924] do_IRQ+0x53/0x110
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606925] ret_from_intr+0x0/0x1e
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606927] free_unref_page_list+0x333/0x590
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606928] release_pages+0x44a/0x5c0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606930] free_pages_and_swap_cache+0x107/0x150
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606931] tlb_flush_mmu_free+0x4e/0x70
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606932] arch_tlb_finish_mmu+0x61/0xa0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606934] tlb_finish_mmu+0x36/0x50
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606935] exit_mmap+0x10a/0x230
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606936] mmput+0x92/0x1c0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606937] do_exit+0x365/0x10b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606938] do_group_exit+0x60/0x100
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606940] __x64_sys_exit_group+0x1c/0x20
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606941] do_syscall_64+0x81/0x260
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606943] entry_SYSCALL_64_after_hwframe+0x49/0xbe
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606943]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606944] -> #1 (&port_lock_key){-.-.}:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606948] _raw_spin_lock_irqsave+0x56/0x70
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606950] serial8250_console_write+0x30c/0x3b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606951] univ8250_console_write+0x35/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606953] console_unlock+0x650/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606954] register_console+0x339/0x540
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606955] univ8250_console_init+0x30/0x3a
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606957] console_init+0x2c6/0x424
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606958] start_kernel+0x466/0x61f
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606959] x86_64_start_reservations+0x2a/0x2c
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606961] x86_64_start_kernel+0x72/0x75
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606962] secondary_startup_64+0xa5/0xb0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606963]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606963] -> #0 (console_owner){-.-.}:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606968] lock_acquire+0xbf/0x220
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606969] console_unlock+0x23e/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606970] vprintk_emit+0x394/0x680
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606971] vprintk_default+0x28/0x30
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606973] vprintk_func+0x57/0xc0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606974] printk+0x5e/0x7d
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606975] show_workqueue_state+0x448/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606977] wq_watchdog_timer_fn+0x1df/0x320
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606978] call_timer_fn+0xb0/0x420
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606979] run_timer_softirq+0x2da/0x870
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606981] __do_softirq+0xd0/0x4fe
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606982] irq_exit+0xd4/0xe0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606983] smp_apic_timer_interrupt+0x9a/0x2b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606985] apic_timer_interrupt+0xf/0x20
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606986] native_safe_halt+0x6/0x10
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606987] default_idle+0x2e/0x1a0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606988] arch_cpu_idle+0x10/0x20
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606990] default_idle_call+0x1e/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606991] do_idle+0x205/0x2e0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606992] cpu_startup_entry+0x6e/0x70
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606993] rest_init+0xc7/0xd0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606995] start_kernel+0x5fc/0x61f
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606996] x86_64_start_reservations+0x2a/0x2c
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606997] x86_64_start_kernel+0x72/0x75
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606999] secondary_startup_64+0xa5/0xb0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606999]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607001] other info that might help us debug this:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607001]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607002] Chain exists of:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607003] console_owner --> &pool->lock/1 --> &(&pool->lock)->rlock
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607009]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607010] Possible unsafe locking scenario:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607011]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607012] CPU0 CPU1
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607014] ---- ----
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607014] lock(&(&pool->lock)->rlock);
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607017] lock(&pool->lock/1);
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607021] lock(&(&pool->lock)->rlock);
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607024] lock(console_owner);
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607026]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607027] *** DEADLOCK ***
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607027]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607028] 4 locks held by swapper/0/0:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607029] #0: 00000000acb744a0 ((&wq_watchdog_timer)){+.-.}, at: call_timer_fn+0x0/0x420
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607034] #1: 00000000918be876 (rcu_read_lock_sched){....}, at: show_workqueue_state+0x0/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607040] #2: 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607045] #3: 000000005fd39989 (console_lock){+.+.}, at: vprintk_emit+0x386/0x680
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607050]
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607051] stack backtrace:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607053] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G O 4.18.0-rc3 #643
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607056] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607057] Call Trace:
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607058] <IRQ>
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607059] dump_stack+0xe9/0x148
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607061] print_circular_bug.isra.39+0x1f3/0x201
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607062] __lock_acquire+0x135f/0x1400
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607063] lock_acquire+0xbf/0x220
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607065] ? console_unlock+0x215/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607066] ? lock_acquire+0xbf/0x220
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607067] ? console_unlock+0x1ce/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607068] console_unlock+0x23e/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607070] ? console_unlock+0x1ce/0x8b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607071] vprintk_emit+0x394/0x680
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607072] vprintk_default+0x28/0x30
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607073] vprintk_func+0x57/0xc0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607074] printk+0x5e/0x7d
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607076] show_workqueue_state+0x448/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607077] ? wq_watchdog_timer_fn+0x1a6/0x320
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607078] wq_watchdog_timer_fn+0x1df/0x320
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607080] ? show_workqueue_state+0x900/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607081] ? show_workqueue_state+0x900/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607082] call_timer_fn+0xb0/0x420
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607084] ? show_workqueue_state+0x900/0x900
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607085] run_timer_softirq+0x2da/0x870
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607086] __do_softirq+0xd0/0x4fe
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607087] irq_exit+0xd4/0xe0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607089] smp_apic_timer_interrupt+0x9a/0x2b0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607090] apic_timer_interrupt+0xf/0x20
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607091] </IRQ>
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607092] RIP: 0010:native_safe_halt+0x6/0x10
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607093] Code: 53 18 fe 65 48 8b 04 25 40 5e 01 00 f0 80 48 02 20 48 8b 00 a8 08 0f 84 57 ff ff ff eb a6 90 90 90 90 90 90 55 48 89 e5 fb f4 <5d> c3 0f 1f 84 00 00 00 00 00 55 48 89 e5 f4 5d c3 90 90 90 90 90
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607135] RSP: 0018:ffffffff84003df8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607138] RAX: ffffffff8406d7c0 RBX: 0000000000000000 RCX: 0000000000000000
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607140] RDX: ffffffff8406d7c0 RSI: 0000000000000001 RDI: ffffffff8406d7c0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607142] RBP: ffffffff84003df8 R08: 0000000000000001 R09: 0000000000000000
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607144] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607146] R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff84098920
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607148] ? trace_hardirqs_on+0xd/0x10
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607149] default_idle+0x2e/0x1a0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607150] arch_cpu_idle+0x10/0x20
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607151] default_idle_call+0x1e/0x40
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607152] do_idle+0x205/0x2e0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607154] ? do_idle+0xf9/0x2e0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607155] cpu_startup_entry+0x6e/0x70
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607156] rest_init+0xc7/0xd0
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607158] ? trace_event_define_fields_vector_alloc_managed+0x8b/0x8b
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607159] start_kernel+0x5fc/0x61f
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607161] x86_64_start_reservations+0x2a/0x2c
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607162] x86_64_start_kernel+0x72/0x75
2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607163] secondary_startup_64+0xa5/0xb0
2018-07-02 12:13:44 192.168.159.129:6666 [ 182.238928] BUG: workqueue lockup - pool cpus=2 node=0 flags=0x0 nice=0 stuck for 92s!
2018-07-02 12:13:44 192.168.159.129:6666 [ 182.241803] Showing busy workqueues and worker pools:
2018-07-02 12:13:44 192.168.159.129:6666 [ 182.243616] workqueue mm_percpu_wq: flags=0x8
2018-07-02 12:13:44 192.168.159.129:6666 [ 182.245141] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
2018-07-02 12:13:44 192.168.159.129:6666 [ 182.247130] pending: vmstat_update
2018-07-02 12:14:11 192.168.159.129:6666 [ 209.030165] INFO: rcu_sched detected stalls on CPUs/tasks:
2018-07-02 12:14:11 192.168.159.129:6666 [ 209.032175] 2-...0: (0 ticks this GP) idle=0be/1/4611686018427387904 softirq=5544/5544 fqs=27833
2018-07-02 12:14:11 192.168.159.129:6666 [ 209.035069] (detected by 3, t=120007 jiffies, g=2553, c=2552, q=1155)
2018-07-02 12:14:11 192.168.159.129:6666 [ 209.037220] Sending NMI from CPU 3 to CPUs 2:
/* Here is a 10 seconds of lag which is flushed by local_irq_enable(). */
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038805] NMI backtrace for cpu 2
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038813] CPU: 2 PID: 10038 Comm: insmod Tainted: G O 4.18.0-rc3 #643
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038815] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038827] RIP: 0010:__sanitizer_cov_trace_pc+0x26/0x50
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038828] Code: 90 90 90 90 55 65 48 8b 04 25 40 5e 01 00 48 89 e5 65 8b 15 6c f6 d1 7e 81 e2 00 01 1f 00 48 8b 4d 08 75 2b 8b 90 80 12 00 00 <83> fa 02 75 20 48 8b b0 88 12 00 00 8b 80 84 12 00 00 48 8b 16 48
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038881] RSP: 0018:ffffc9000205fc60 EFLAGS: 00000046
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038884] RAX: ffff880136312080 RBX: 00000000fffcc7e1 RCX: ffffffffa000d038
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038886] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffffa000d033
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038888] RBP: ffffc9000205fc60 R08: 0000000000000001 R09: 0000000000000000
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038890] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffa000d000
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038892] R13: ffff8801351cd940 R14: 0000000000000001 R15: ffffc9000205fe78
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038895] FS: 00007f90d3e62740(0000) GS:ffff88013a680000(0000) knlGS:0000000000000000
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038897] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038899] CR2: 00000000015051d8 CR3: 0000000136a66004 CR4: 00000000000606e0
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038941] Call Trace:
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038950] ccs_init+0x38/0x79 [akari_test]
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038956] do_one_initcall+0x7a/0x460
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038961] ? trace_hardirqs_on+0xd/0x10
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038966] do_init_module+0x5a/0x1e0
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038969] load_module+0x2144/0x2800
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038975] __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038978] ? __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038983] __x64_sys_finit_module+0x15/0x20
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038986] do_syscall_64+0x81/0x260
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038992] entry_SYSCALL_64_after_hwframe+0x49/0xbe
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038995] RIP: 0033:0x7f90d3335ec9
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.038996] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 cf 2c 00 f7 d8 64 89 01 48
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.039041] RSP: 002b:00007ffce0ff8338 EFLAGS: 00000202 ORIG_RAX: 0000000000000139
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.039045] RAX: ffffffffffffffda RBX: 00000000015051e0 RCX: 00007f90d3335ec9
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.039047] RDX: 0000000000000000 RSI: 000000000041aa0e RDI: 0000000000000003
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.039049] RBP: 000000000041aa0e R08: 0000000000000000 R09: 00007ffce0ff84d8
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.039051] R10: 0000000000000003 R11: 0000000000000202 R12: 0000000000000000
2018-07-02 12:14:21 192.168.159.129:6666 [ 209.039053] R13: 0000000001504120 R14: 0000000000000000 R15: 0000000000000000
----------
Loading the module after
echo 180 > /sys/module/workqueue/parameters/watchdog_thresh
echo 25 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
----------
2018-07-02 12:15:57 192.168.159.129:6666 [ 315.368812] INFO: rcu_sched detected stalls on CPUs/tasks:
2018-07-02 12:15:57 192.168.159.129:6666 [ 315.370959] 1-...0: (2 ticks this GP) idle=d0a/1/4611686018427387904 softirq=4587/4587 fqs=7128
2018-07-02 12:15:57 192.168.159.129:6666 [ 315.373828] (detected by 7, t=30007 jiffies, g=2649, c=2648, q=64)
2018-07-02 12:15:57 192.168.159.129:6666 [ 315.375881] Sending NMI from CPU 7 to CPUs 1:
/* Here is a 90 seconds of lag which is flushed by */
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377376] NMI backtrace for cpu 1
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377382] CPU: 1 PID: 10062 Comm: insmod Tainted: G O 4.18.0-rc3 #643
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377384] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377394] RIP: 0010:__sanitizer_cov_trace_pc+0x4b/0x50
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377395] Code: 90 80 12 00 00 83 fa 02 75 20 48 8b b0 88 12 00 00 8b 80 84 12 00 00 48 8b 16 48 83 c2 01 48 39 d0 76 07 48 89 0c d6 48 89 16 <5d> c3 0f 1f 00 55 48 89 e5 41 57 41 56 41 55 41 54 53 48 89 f3 48
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377451] RSP: 0018:ffffc90000cffc60 EFLAGS: 00000093
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377454] RAX: ffff88013091a600 RBX: 00000000ffffc6dd RCX: ffffffffa0012038
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377456] RDX: 0000000000000000 RSI: 0000000000000bfa RDI: ffffffffa0012033
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377458] RBP: ffffc90000cffc60 R08: 0000000000000000 R09: 0000000000000000
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377460] R10: ffffc90000cffbe8 R11: ffff88013091a600 R12: ffffffffa0012000
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377462] R13: ffff88012f7734e0 R14: 0000000000000001 R15: ffffc90000cffe78
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377466] FS: 00007fafb5b7b740(0000) GS:ffff88013a640000(0000) knlGS:0000000000000000
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377468] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377470] CR2: 00007fafb50bf910 CR3: 0000000130321006 CR4: 00000000000606e0
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377507] Call Trace:
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377515] ccs_init+0x38/0x79 [akari_test]
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377521] do_one_initcall+0x7a/0x460
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377526] ? trace_hardirqs_on+0xd/0x10
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377531] do_init_module+0x5a/0x1e0
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377534] load_module+0x2144/0x2800
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377540] __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377543] ? __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377548] __x64_sys_finit_module+0x15/0x20
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377552] do_syscall_64+0x81/0x260
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377557] entry_SYSCALL_64_after_hwframe+0x49/0xbe
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377560] RIP: 0033:0x7fafb504eec9
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377561] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 cf 2c 00 f7 d8 64 89 01 48
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377606] RSP: 002b:00007ffcd3167148 EFLAGS: 00000206 ORIG_RAX: 0000000000000139
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377610] RAX: ffffffffffffffda RBX: 00000000012ab1e0 RCX: 00007fafb504eec9
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377612] RDX: 0000000000000000 RSI: 000000000041aa0e RDI: 0000000000000003
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377614] RBP: 000000000041aa0e R08: 0000000000000000 R09: 00007ffcd31672e8
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377616] R10: 0000000000000003 R11: 0000000000000206 R12: 0000000000000000
2018-07-02 12:17:27 192.168.159.129:6666 [ 315.377618] R13: 00000000012aa120 R14: 0000000000000000 R15: 0000000000000000
/* somebody else's printk(). */
2018-07-02 12:17:27 192.168.159.129:6666 [ 405.373020] INFO: rcu_sched detected stalls on CPUs/tasks:
2018-07-02 12:17:27 192.168.159.129:6666 [ 405.449297] 1-...0: (2 ticks this GP) idle=d0a/1/4611686018427387904 softirq=4587/4587 fqs=27972
2018-07-02 12:17:27 192.168.159.129:6666 [ 405.452234] (detected by 2, t=120086 jiffies, g=2649, c=2648, q=537)
2018-07-02 12:17:27 192.168.159.129:6666 [ 405.454419] Sending NMI from CPU 2 to CPUs 1:
/* Here is a 10 seconds of lag which is flushed by local_irq_enable(). */
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.455947] NMI backtrace for cpu 1
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.455953] CPU: 1 PID: 10062 Comm: insmod Tainted: G O 4.18.0-rc3 #643
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.455956] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.455964] RIP: 0010:__sanitizer_cov_trace_pc+0x20/0x50
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.455965] Code: 5d c3 90 90 90 90 90 90 90 90 55 65 48 8b 04 25 40 5e 01 00 48 89 e5 65 8b 15 6c f6 d1 7e 81 e2 00 01 1f 00 48 8b 4d 08 75 2b <8b> 90 80 12 00 00 83 fa 02 75 20 48 8b b0 88 12 00 00 8b 80 84 12
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456012] RSP: 0018:ffffc90000cffc60 EFLAGS: 00000046
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456014] RAX: ffff88013091a600 RBX: 00000000ffffc6dd RCX: ffffffffa0012038
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456017] RDX: 0000000000000000 RSI: 0000000000000bfa RDI: ffffffffa0012033
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456018] RBP: ffffc90000cffc60 R08: 0000000000000000 R09: 0000000000000000
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456021] R10: ffffc90000cffbe8 R11: ffff88013091a600 R12: ffffffffa0012000
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456023] R13: ffff88012f7734e0 R14: 0000000000000001 R15: ffffc90000cffe78
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456026] FS: 00007fafb5b7b740(0000) GS:ffff88013a640000(0000) knlGS:0000000000000000
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456028] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456030] CR2: 00007fafb50bf910 CR3: 0000000130321006 CR4: 00000000000606e0
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456069] Call Trace:
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456077] ccs_init+0x38/0x79 [akari_test]
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456083] do_one_initcall+0x7a/0x460
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456088] ? trace_hardirqs_on+0xd/0x10
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456093] do_init_module+0x5a/0x1e0
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456096] load_module+0x2144/0x2800
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456102] __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456105] ? __do_sys_finit_module+0xd1/0xf0
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456110] __x64_sys_finit_module+0x15/0x20
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456113] do_syscall_64+0x81/0x260
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456119] entry_SYSCALL_64_after_hwframe+0x49/0xbe
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456122] RIP: 0033:0x7fafb504eec9
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456123] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 cf 2c 00 f7 d8 64 89 01 48
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456168] RSP: 002b:00007ffcd3167148 EFLAGS: 00000206 ORIG_RAX: 0000000000000139
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456172] RAX: ffffffffffffffda RBX: 00000000012ab1e0 RCX: 00007fafb504eec9
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456174] RDX: 0000000000000000 RSI: 000000000041aa0e RDI: 0000000000000003
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456176] RBP: 000000000041aa0e R08: 0000000000000000 R09: 00007ffcd31672e8
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456177] R10: 0000000000000003 R11: 0000000000000206 R12: 0000000000000000
2018-07-02 12:17:37 192.168.159.129:6666 [ 405.456179] R13: 00000000012aa120 R14: 0000000000000000 R15: 0000000000000000
----------
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-02 10:26 printk() from NMI backtrace can delay a lot Tetsuo Handa
@ 2018-07-02 10:39 ` Sergey Senozhatsky
2018-07-03 4:30 ` Sergey Senozhatsky
1 sibling, 0 replies; 8+ messages in thread
From: Sergey Senozhatsky @ 2018-07-02 10:39 UTC (permalink / raw)
To: Tetsuo Handa
Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Peter Zijlstra,
Sergey Senozhatsky, linux-kernel, Dmitry Vyukov
Hi,
On (07/02/18 19:26), Tetsuo Handa wrote:
> Hello.
>
> Today I was testing conditions when/how stall watchdog fires. I noticed that
> printing NMI backtraces to consoles is delayed till IRQ is enabled or somebody
> else schedules printk(). This is not a welcomed behavior when the cause of
> lock up is doing nearly-infinite loop with IRQ disabled. Can we improve this?
Hmm. We can't call console drivers from NMI, this can deadlock on
uart/etc locks. So we always need [except for panic()] someone else to
print NMI message for us. Either it's IRQ on a local CPU (we need two
IRQs actually - one to flush printk_nmi buffer and the second one to do
console_trylock()->console_unlock()), or printk() from another CPU that
would print pending logbuf entries. We used to have a fast path for
print_nmi messages (direct_nmi), which soon will be used only for
NMI->ftrace_dump(). Even if we re-introduce that fast path for printk_nmi
[may be we can do printk_direct_nmi type of checks for printk_nmi as well]
we still can't print anything from the NMI CPU.
I need to look more at the data you have provided.
-ss
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-02 10:26 printk() from NMI backtrace can delay a lot Tetsuo Handa
2018-07-02 10:39 ` Sergey Senozhatsky
@ 2018-07-03 4:30 ` Sergey Senozhatsky
2018-07-03 15:29 ` Tejun Heo
1 sibling, 1 reply; 8+ messages in thread
From: Sergey Senozhatsky @ 2018-07-03 4:30 UTC (permalink / raw)
To: Tetsuo Handa, Tejun Heo, Steven Rostedt, Petr Mladek
Cc: Peter Zijlstra, Linus Torvalds, Andrew Morton, Dmitry Vyukov,
linux-kernel, Sergey Senozhatsky, Sergey Senozhatsky
Cc-ing Linus, Tejun, Andrew
[I'll keep the entire lockdep report]
On (07/02/18 19:26), Tetsuo Handa wrote:
[..]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606834] swapper/0/0 is trying to acquire lock:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606840]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606841] but task is already holding lock:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606847]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606848] which lock already depends on the new lock.
> ...
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606851] the existing dependency chain (in reverse order) is:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606852]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606852] -> #4 (&(&pool->lock)->rlock){-.-.}:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606857] _raw_spin_lock+0x2a/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606858] __queue_work+0xfb/0x780
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606859] queue_work_on+0xde/0x110
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606861] put_pwq+0x85/0x90
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606862] put_pwq_unlocked.part.29+0x1d/0x30
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606863] destroy_workqueue+0x2df/0x320
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606865] tipc_topsrv_stop+0x1a0/0x290
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606866] tipc_exit_net+0x15/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606867] ops_exit_list.isra.8+0x4e/0x90
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606869] cleanup_net+0x219/0x390
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606870] process_one_work+0x2ec/0x800
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606871] worker_thread+0x45/0x4d0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606872] kthread+0x14c/0x170
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606874] ret_from_fork+0x3a/0x50
I assume this one is
pwq->pool->lock -> last_pool->lock ?
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606874]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606875] -> #3 (&pool->lock/1){-.-.}:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606880] _raw_spin_lock+0x2a/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606881] __queue_work+0xfb/0x780
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606882] queue_work_on+0xde/0x110
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606884] tty_flip_buffer_push+0x2f/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606885] pty_write+0xb0/0xc0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606886] n_tty_write+0x244/0x620
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606887] tty_write+0x1e3/0x3f0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606888] __vfs_write+0x54/0x270
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606890] vfs_write+0xf0/0x230
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606891] redirected_tty_write+0x61/0xb0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606892] do_iter_write+0x1ce/0x220
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606893] vfs_writev+0xb0/0x140
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606895] do_writev+0x6d/0x120
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606896] __x64_sys_writev+0x20/0x30
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606897] do_syscall_64+0x81/0x260
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606899] entry_SYSCALL_64_after_hwframe+0x49/0xbe
So #3 is
tty_port->lock -> WQ pool->lock
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606900] -> #2 (&(&port->lock)->rlock){-.-.}:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606905] _raw_spin_lock_irqsave+0x56/0x70
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606906] tty_port_tty_get+0x20/0x60
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606907] tty_port_default_wakeup+0x15/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606909] tty_port_tty_wakeup+0x20/0x30
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606910] uart_write_wakeup+0x26/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606911] serial8250_tx_chars+0x1ae/0x2d0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606913] serial8250_handle_irq.part.23+0x108/0x130
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606915] serial8250_default_handle_irq+0x7a/0x90
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606916] serial8250_interrupt+0x77/0x110
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606918] __handle_irq_event_percpu+0x80/0x480
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606919] handle_irq_event_percpu+0x35/0x90
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606920] handle_irq_event+0x39/0x60
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606922] handle_edge_irq+0xa5/0x230
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606923] handle_irq+0xae/0x120
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606924] do_IRQ+0x53/0x110
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606925] ret_from_intr+0x0/0x1e
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606927] free_unref_page_list+0x333/0x590
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606928] release_pages+0x44a/0x5c0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606930] free_pages_and_swap_cache+0x107/0x150
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606931] tlb_flush_mmu_free+0x4e/0x70
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606932] arch_tlb_finish_mmu+0x61/0xa0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606934] tlb_finish_mmu+0x36/0x50
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606935] exit_mmap+0x10a/0x230
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606936] mmput+0x92/0x1c0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606937] do_exit+0x365/0x10b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606938] do_group_exit+0x60/0x100
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606940] __x64_sys_exit_group+0x1c/0x20
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606941] do_syscall_64+0x81/0x260
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606943] entry_SYSCALL_64_after_hwframe+0x49/0xbe
#2 is
hard IRQ uart_port->lock -> tty_port->lock
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606943]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606944] -> #1 (&port_lock_key){-.-.}:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606948] _raw_spin_lock_irqsave+0x56/0x70
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606950] serial8250_console_write+0x30c/0x3b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606951] univ8250_console_write+0x35/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606953] console_unlock+0x650/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606954] register_console+0x339/0x540
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606955] univ8250_console_init+0x30/0x3a
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606957] console_init+0x2c6/0x424
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606958] start_kernel+0x466/0x61f
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606959] x86_64_start_reservations+0x2a/0x2c
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606961] x86_64_start_kernel+0x72/0x75
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606962] secondary_startup_64+0xa5/0xb0
Must be
console_sem / console_owner -> uart_port->lock ?
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606963]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606963] -> #0 (console_owner){-.-.}:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606968] lock_acquire+0xbf/0x220
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606969] console_unlock+0x23e/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606970] vprintk_emit+0x394/0x680
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606971] vprintk_default+0x28/0x30
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606973] vprintk_func+0x57/0xc0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606974] printk+0x5e/0x7d
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606975] show_workqueue_state+0x448/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606977] wq_watchdog_timer_fn+0x1df/0x320
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606978] call_timer_fn+0xb0/0x420
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606979] run_timer_softirq+0x2da/0x870
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606981] __do_softirq+0xd0/0x4fe
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606982] irq_exit+0xd4/0xe0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606983] smp_apic_timer_interrupt+0x9a/0x2b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606985] apic_timer_interrupt+0xf/0x20
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606986] native_safe_halt+0x6/0x10
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606987] default_idle+0x2e/0x1a0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606988] arch_cpu_idle+0x10/0x20
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606990] default_idle_call+0x1e/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606991] do_idle+0x205/0x2e0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606992] cpu_startup_entry+0x6e/0x70
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606993] rest_init+0xc7/0xd0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606995] start_kernel+0x5fc/0x61f
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606996] x86_64_start_reservations+0x2a/0x2c
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606997] x86_64_start_kernel+0x72/0x75
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606999] secondary_startup_64+0xa5/0xb0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606999]
#0 is
softirq WQ pool->lock -> console_sem / console_owner -> uart_port->lock
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607001] other info that might help us debug this:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607001]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607002] Chain exists of:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607003] console_owner --> &pool->lock/1 --> &(&pool->lock)->rlock
I don't quite understand how that direct "console_owner -> pool->lock" is
possible, there should be uart/tty somewhere in between. For instance:
console_owner -> uart_port->lock -> pool->lock -> &(&pool->lock)->rlock
But anyway. So we can have [but I'm not completely sure. Maybe lockdep has
something else on its mind] something like this:
CPU1 CPU0
#IRQ #soft irq
serial8250_handle_irq() wq_watchdog_timer_fn()
spin_lock(&uart_port->lock) show_workqueue_state()
serial8250_rx_chars() spin_lock(&pool->lock)
tty_flip_buffer_push() printk()
tty_schedule_flip() serial8250_console_write()
queue_work() spin_lock(&uart_port->lock)
__queue_work()
spin_lock(&pool->lock)
We need to break the pool->lock -> uart_port->lock chain.
- use printk_deferred() to show WQs states [show_workqueue_state() is
a timer callback, so local IRQs are enabled]. But show_workqueue_state()
is also available via sysrq.
- what Alan Cox suggested: use spin_trylock() in serial8250_console_write()
and just discard (do not print anything on console) console->writes() that
can deadlock us [uart_port->lock is already locked]. This basically means
that sometimes there will be no output on a serial console, or there
will be missing line. Which kind of contradicts the purpose of print
out.
We are facing the risk of no output on serial consoles in both case. Thus
there must be some other way out of this.
Any thoughts?
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607009]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607010] Possible unsafe locking scenario:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607011]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607012] CPU0 CPU1
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607014] ---- ----
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607014] lock(&(&pool->lock)->rlock);
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607017] lock(&pool->lock/1);
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607021] lock(&(&pool->lock)->rlock);
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607024] lock(console_owner);
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607026]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607027] *** DEADLOCK ***
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607027]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607028] 4 locks held by swapper/0/0:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607029] #0: 00000000acb744a0 ((&wq_watchdog_timer)){+.-.}, at: call_timer_fn+0x0/0x420
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607034] #1: 00000000918be876 (rcu_read_lock_sched){....}, at: show_workqueue_state+0x0/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607040] #2: 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607045] #3: 000000005fd39989 (console_lock){+.+.}, at: vprintk_emit+0x386/0x680
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607050]
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607051] stack backtrace:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607053] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G O 4.18.0-rc3 #643
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607056] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607057] Call Trace:
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607058] <IRQ>
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607059] dump_stack+0xe9/0x148
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607061] print_circular_bug.isra.39+0x1f3/0x201
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607062] __lock_acquire+0x135f/0x1400
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607063] lock_acquire+0xbf/0x220
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607065] ? console_unlock+0x215/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607066] ? lock_acquire+0xbf/0x220
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607067] ? console_unlock+0x1ce/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607068] console_unlock+0x23e/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607070] ? console_unlock+0x1ce/0x8b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607071] vprintk_emit+0x394/0x680
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607072] vprintk_default+0x28/0x30
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607073] vprintk_func+0x57/0xc0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607074] printk+0x5e/0x7d
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607076] show_workqueue_state+0x448/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607077] ? wq_watchdog_timer_fn+0x1a6/0x320
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607078] wq_watchdog_timer_fn+0x1df/0x320
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607080] ? show_workqueue_state+0x900/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607081] ? show_workqueue_state+0x900/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607082] call_timer_fn+0xb0/0x420
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607084] ? show_workqueue_state+0x900/0x900
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607085] run_timer_softirq+0x2da/0x870
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607086] __do_softirq+0xd0/0x4fe
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607087] irq_exit+0xd4/0xe0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607089] smp_apic_timer_interrupt+0x9a/0x2b0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607090] apic_timer_interrupt+0xf/0x20
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607091] </IRQ>
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607092] RIP: 0010:native_safe_halt+0x6/0x10
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607093] Code: 53 18 fe 65 48 8b 04 25 40 5e 01 00 f0 80 48 02 20 48 8b 00 a8 08 0f 84 57 ff ff ff eb a6 90 90 90 90 90 90 55 48 89 e5 fb f4 <5d> c3 0f 1f 84 00 00 00 00 00 55 48 89 e5 f4 5d c3 90 90 90 90 90
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607135] RSP: 0018:ffffffff84003df8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607138] RAX: ffffffff8406d7c0 RBX: 0000000000000000 RCX: 0000000000000000
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607140] RDX: ffffffff8406d7c0 RSI: 0000000000000001 RDI: ffffffff8406d7c0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607142] RBP: ffffffff84003df8 R08: 0000000000000001 R09: 0000000000000000
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607144] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607146] R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff84098920
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607148] ? trace_hardirqs_on+0xd/0x10
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607149] default_idle+0x2e/0x1a0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607150] arch_cpu_idle+0x10/0x20
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607151] default_idle_call+0x1e/0x40
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607152] do_idle+0x205/0x2e0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607154] ? do_idle+0xf9/0x2e0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607155] cpu_startup_entry+0x6e/0x70
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607156] rest_init+0xc7/0xd0
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607158] ? trace_event_define_fields_vector_alloc_managed+0x8b/0x8b
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607159] start_kernel+0x5fc/0x61f
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607161] x86_64_start_reservations+0x2a/0x2c
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607162] x86_64_start_kernel+0x72/0x75
> 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.607163] secondary_startup_64+0xa5/0xb0
> 2018-07-02 12:13:44 192.168.159.129:6666 [ 182.238928] BUG: workqueue lockup - pool cpus=2 node=0 flags=0x0 nice=0 stuck for 92s!
> 2018-07-02 12:13:44 192.168.159.129:6666 [ 182.241803] Showing busy workqueues and worker pools:
> 2018-07-02 12:13:44 192.168.159.129:6666 [ 182.243616] workqueue mm_percpu_wq: flags=0x8
> 2018-07-02 12:13:44 192.168.159.129:6666 [ 182.245141] pwq 4: cpus=2 node=0 flags=0x0 nice=0 active=1/256
> 2018-07-02 12:13:44 192.168.159.129:6666 [ 182.247130] pending: vmstat_update
> 2018-07-02 12:14:11 192.168.159.129:6666 [ 209.030165] INFO: rcu_sched detected stalls on CPUs/tasks:
> 2018-07-02 12:14:11 192.168.159.129:6666 [ 209.032175] 2-...0: (0 ticks this GP) idle=0be/1/4611686018427387904 softirq=5544/5544 fqs=27833
> 2018-07-02 12:14:11 192.168.159.129:6666 [ 209.035069] (detected by 3, t=120007 jiffies, g=2553, c=2552, q=1155)
> 2018-07-02 12:14:11 192.168.159.129:6666 [ 209.037220] Sending NMI from CPU 3 to CPUs 2:
-ss
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-03 4:30 ` Sergey Senozhatsky
@ 2018-07-03 15:29 ` Tejun Heo
2018-07-03 16:31 ` Sergey Senozhatsky
0 siblings, 1 reply; 8+ messages in thread
From: Tejun Heo @ 2018-07-03 15:29 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: Tetsuo Handa, Steven Rostedt, Petr Mladek, Peter Zijlstra,
Linus Torvalds, Andrew Morton, Dmitry Vyukov, linux-kernel,
Sergey Senozhatsky
Hello, Sergey.
On Tue, Jul 03, 2018 at 01:30:21PM +0900, Sergey Senozhatsky wrote:
> Cc-ing Linus, Tejun, Andrew
> [I'll keep the entire lockdep report]
>
> On (07/02/18 19:26), Tetsuo Handa wrote:
> [..]
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606834] swapper/0/0 is trying to acquire lock:
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606840]
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606841] but task is already holding lock:
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606847]
> > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606848] which lock already depends on the new lock.
...
> But anyway. So we can have [but I'm not completely sure. Maybe lockdep has
> something else on its mind] something like this:
>
> CPU1 CPU0
>
> #IRQ #soft irq
> serial8250_handle_irq() wq_watchdog_timer_fn()
> spin_lock(&uart_port->lock) show_workqueue_state()
> serial8250_rx_chars() spin_lock(&pool->lock)
> tty_flip_buffer_push() printk()
> tty_schedule_flip() serial8250_console_write()
> queue_work() spin_lock(&uart_port->lock)
> __queue_work()
> spin_lock(&pool->lock)
>
> We need to break the pool->lock -> uart_port->lock chain.
>
> - use printk_deferred() to show WQs states [show_workqueue_state() is
> a timer callback, so local IRQs are enabled]. But show_workqueue_state()
> is also available via sysrq.
>
> - what Alan Cox suggested: use spin_trylock() in serial8250_console_write()
> and just discard (do not print anything on console) console->writes() that
> can deadlock us [uart_port->lock is already locked]. This basically means
> that sometimes there will be no output on a serial console, or there
> will be missing line. Which kind of contradicts the purpose of print
> out.
>
> We are facing the risk of no output on serial consoles in both case. Thus
> there must be some other way out of this.
show_workqueue_state() is only used when something is already horribly
broken or when invoked through sysrq. I'm not sure it's worthwhile to
make invasive changes to avoid lockdep warnings. If anything, we
should make show_workqueue_state() avoid grabbing pool->lock (e.g. use
trylock and fallback to probe_kernel_reads if that fails). I'm a bit
skeptical how actually useful that'd be tho.
Thanks.
--
tejun
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-03 15:29 ` Tejun Heo
@ 2018-07-03 16:31 ` Sergey Senozhatsky
2018-07-03 16:39 ` Sergey Senozhatsky
2018-07-10 11:50 ` Petr Mladek
0 siblings, 2 replies; 8+ messages in thread
From: Sergey Senozhatsky @ 2018-07-03 16:31 UTC (permalink / raw)
To: Tejun Heo
Cc: Sergey Senozhatsky, Tetsuo Handa, Steven Rostedt, Petr Mladek,
Peter Zijlstra, Linus Torvalds, Andrew Morton, Dmitry Vyukov,
linux-kernel, Sergey Senozhatsky
Hello, Tejun
On (07/03/18 08:29), Tejun Heo wrote:
> Hello, Sergey.
>
> On Tue, Jul 03, 2018 at 01:30:21PM +0900, Sergey Senozhatsky wrote:
> > Cc-ing Linus, Tejun, Andrew
> > [I'll keep the entire lockdep report]
> >
> > On (07/02/18 19:26), Tetsuo Handa wrote:
> > [..]
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606834] swapper/0/0 is trying to acquire lock:
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606840]
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606841] but task is already holding lock:
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606847]
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606848] which lock already depends on the new lock.
> ...
> > But anyway. So we can have [but I'm not completely sure. Maybe lockdep has
> > something else on its mind] something like this:
> >
> > CPU1 CPU0
> >
> > #IRQ #soft irq
> > serial8250_handle_irq() wq_watchdog_timer_fn()
> > spin_lock(&uart_port->lock) show_workqueue_state()
> > serial8250_rx_chars() spin_lock(&pool->lock)
> > tty_flip_buffer_push() printk()
> > tty_schedule_flip() serial8250_console_write()
> > queue_work() spin_lock(&uart_port->lock)
> > __queue_work()
> > spin_lock(&pool->lock)
> >
> > We need to break the pool->lock -> uart_port->lock chain.
> >
> > - use printk_deferred() to show WQs states [show_workqueue_state() is
> > a timer callback, so local IRQs are enabled]. But show_workqueue_state()
> > is also available via sysrq.
> >
> > - what Alan Cox suggested: use spin_trylock() in serial8250_console_write()
> > and just discard (do not print anything on console) console->writes() that
> > can deadlock us [uart_port->lock is already locked]. This basically means
> > that sometimes there will be no output on a serial console, or there
> > will be missing line. Which kind of contradicts the purpose of print
> > out.
> >
> > We are facing the risk of no output on serial consoles in both case. Thus
> > there must be some other way out of this.
>
> show_workqueue_state() is only used when something is already horribly
> broken or when invoked through sysrq.
Tetsuo is hammering sysrq for fun and profit ;)
> I'm not sure it's worthwhile to make invasive changes to avoid lockdep
> warnings. If anything, we should make show_workqueue_state() avoid
> grabbing pool->lock (e.g. use trylock and fallback to probe_kernel_reads
> if that fails). I'm a bit skeptical how actually useful that'd be tho.
So, I agree.
Another option *possibly* could be...
... maybe we can brake another lock dependency. I don't quite understand,
and surely I'm missing something here, why serial driver call
tty_flip_buffer_push() under uart_port->lock. E.g.
serial_driver_handle_irq()
{
spin_lock(uart_port->lock);
.. TX() / RX()
tty_flip_buffer_push(uart_port->tty_port);
spin_unlock(uart_port->lock);
}
it might be the case that we can do
serial_driver_handle_irq()
{
spin_loc(uart_port->lock);
.. TX / RX
spin_unlock(uart_port->lock);
tty_flip_buffer_push(uart_port->tty_port);
}
This should break this chain
uart_port->lock -> pool->lock // -> sheduler/etc.
Can we do it? What am I missing?
-ss
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-03 16:31 ` Sergey Senozhatsky
@ 2018-07-03 16:39 ` Sergey Senozhatsky
2018-07-10 11:50 ` Petr Mladek
1 sibling, 0 replies; 8+ messages in thread
From: Sergey Senozhatsky @ 2018-07-03 16:39 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: Tejun Heo, Sergey Senozhatsky, Tetsuo Handa, Steven Rostedt,
Petr Mladek, Peter Zijlstra, Linus Torvalds, Andrew Morton,
Dmitry Vyukov, linux-kernel
On (07/04/18 01:31), Sergey Senozhatsky wrote:
> it might be the case that we can do
>
> serial_driver_handle_irq()
> {
> spin_loc(uart_port->lock);
>
> .. TX / RX
>
> spin_unlock(uart_port->lock);
>
> tty_flip_buffer_push(uart_port->tty_port);
> }
>
> This should break this chain
>
> uart_port->lock -> pool->lock // -> sheduler/etc.
>
>
> Can we do it? What am I missing?
Hmm, and we actually have some serial drivers that do tty_filp_buffer_push()
outside of uart_port->lock. For instance, drivers/tty/serial/efm32-uart.c
irqreturn_t efm32_uart_rxirq().
-ss
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-03 16:31 ` Sergey Senozhatsky
2018-07-03 16:39 ` Sergey Senozhatsky
@ 2018-07-10 11:50 ` Petr Mladek
2018-07-11 7:27 ` Sergey Senozhatsky
1 sibling, 1 reply; 8+ messages in thread
From: Petr Mladek @ 2018-07-10 11:50 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: Tejun Heo, Sergey Senozhatsky, Tetsuo Handa, Steven Rostedt,
Peter Zijlstra, Linus Torvalds, Andrew Morton, Dmitry Vyukov,
linux-kernel
On Wed 2018-07-04 01:31:45, Sergey Senozhatsky wrote:
> Hello, Tejun
>
> On (07/03/18 08:29), Tejun Heo wrote:
> > Hello, Sergey.
> >
> > On Tue, Jul 03, 2018 at 01:30:21PM +0900, Sergey Senozhatsky wrote:
> > > Cc-ing Linus, Tejun, Andrew
> > > [I'll keep the entire lockdep report]
> > >
> > > On (07/02/18 19:26), Tetsuo Handa wrote:
> > > [..]
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606834] swapper/0/0 is trying to acquire lock:
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606840]
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606841] but task is already holding lock:
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606847]
> > > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606848] which lock already depends on the new lock.
> > ...
> > > But anyway. So we can have [but I'm not completely sure. Maybe lockdep has
> > > something else on its mind] something like this:
> > >
> > > CPU1 CPU0
> > >
> > > #IRQ #soft irq
> > > serial8250_handle_irq() wq_watchdog_timer_fn()
> > > spin_lock(&uart_port->lock) show_workqueue_state()
> > > serial8250_rx_chars() spin_lock(&pool->lock)
> > > tty_flip_buffer_push() printk()
> > > tty_schedule_flip() serial8250_console_write()
> > > queue_work() spin_lock(&uart_port->lock)
> > > __queue_work()
> > > spin_lock(&pool->lock)
> > >
> > > We need to break the pool->lock -> uart_port->lock chain.
> > >
> > > - use printk_deferred() to show WQs states [show_workqueue_state() is
> > > a timer callback, so local IRQs are enabled]. But show_workqueue_state()
> > > is also available via sysrq.
> > >
> > > - what Alan Cox suggested: use spin_trylock() in serial8250_console_write()
> > > and just discard (do not print anything on console) console->writes() that
> > > can deadlock us [uart_port->lock is already locked]. This basically means
> > > that sometimes there will be no output on a serial console, or there
> > > will be missing line. Which kind of contradicts the purpose of print
> > > out.
> > >
> > > We are facing the risk of no output on serial consoles in both case. Thus
> > > there must be some other way out of this.
> >
> > show_workqueue_state() is only used when something is already horribly
> > broken or when invoked through sysrq.
>
> Tetsuo is hammering sysrq for fun and profit ;)
>
> > I'm not sure it's worthwhile to make invasive changes to avoid lockdep
> > warnings. If anything, we should make show_workqueue_state() avoid
> > grabbing pool->lock (e.g. use trylock and fallback to probe_kernel_reads
> > if that fails). I'm a bit skeptical how actually useful that'd be tho.
>
> So, I agree.
>
> Another option *possibly* could be...
>
> ... maybe we can brake another lock dependency. I don't quite understand,
> and surely I'm missing something here, why serial driver call
> tty_flip_buffer_push() under uart_port->lock. E.g.
>
> serial_driver_handle_irq()
> {
> spin_lock(uart_port->lock);
>
> .. TX() / RX()
>
> tty_flip_buffer_push(uart_port->tty_port);
> spin_unlock(uart_port->lock);
> }
>
> it might be the case that we can do
>
> serial_driver_handle_irq()
> {
> spin_loc(uart_port->lock);
>
> .. TX / RX
>
> spin_unlock(uart_port->lock);
>
> tty_flip_buffer_push(uart_port->tty_port);
Hmm, this looks racy. For example, I see the following in
serial_lpc32xx_interrupt():
tty_insert_flip_char(tport, 0, TTY_OVERRUN);
tty_schedule_flip(tport);
where tty_insert_flip_char() manipulates flag/char/used:
*flag_buf_ptr(tb, tb->used) = flag;
*char_buf_ptr(tb, tb->used++) = ch;
and tty_schedule_flip() copies "used" -> "commit":
smp_store_release(&buf->tail->commit, buf->tail->used);
queue_work(system_unbound_wq, &buf->work);
I do not have the entire picture but I guess that we need to
commit only correctly set characters and flags. Therefore
the manipulation of flag/ch/used/commit need to be synchronized.
It seems that &port->lock is used for this.
Sigh, I am not aware of any good solution.
I agree with Tejun that using printk_deferred() in
show_workqueue_state() is questionable. Basically any deferring
is risky. There is no guarantee that the deferred operation will
get realized.
Also Alan Cox's idea: "use spin_trylock() in
serial8250_console_write()" has problems. Sergey already mentioned
that we might then miss random lines on a particular console.
So far, the best (and realistic?) idea seems to be switching to
printk_deferred() context when port->lock is taken. It would
be a well defined pattern that people might get used to.
Of course, the best solution would be to have printk and
console->write() lock-less. But this would mean a lot of
tricky code unless anyone comes with a brilliant design.
Best Regards,
Petr
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: printk() from NMI backtrace can delay a lot
2018-07-10 11:50 ` Petr Mladek
@ 2018-07-11 7:27 ` Sergey Senozhatsky
0 siblings, 0 replies; 8+ messages in thread
From: Sergey Senozhatsky @ 2018-07-11 7:27 UTC (permalink / raw)
To: Petr Mladek, Alan Cox, Greg Kroah-Hartman, Jiri Slaby
Cc: Sergey Senozhatsky, Tejun Heo, Sergey Senozhatsky, Tetsuo Handa,
Steven Rostedt, Peter Zijlstra, Linus Torvalds, Andrew Morton,
Dmitry Vyukov, linux-kernel
Cc-ng Alan, Greg, Jiri
A lockdep report: https://lore.kernel.org/lkml/20180703043021.GA547@jagdpanzerIV/T/#u
On (07/10/18 13:50), Petr Mladek wrote:
> >
> > Another option *possibly* could be...
> >
> > ... maybe we can brake another lock dependency. I don't quite understand,
> > and surely I'm missing something here, why serial driver call
> > tty_flip_buffer_push() under uart_port->lock. E.g.
> >
> > serial_driver_handle_irq()
> > {
> > spin_lock(uart_port->lock);
> >
> > .. TX() / RX()
> >
> > tty_flip_buffer_push(uart_port->tty_port);
> > spin_unlock(uart_port->lock);
> > }
> >
> > it might be the case that we can do
> >
> > serial_driver_handle_irq()
> > {
> > spin_loc(uart_port->lock);
> >
> > .. TX / RX
> >
> > spin_unlock(uart_port->lock);
> >
> > tty_flip_buffer_push(uart_port->tty_port);
>
> Hmm, this looks racy. For example, I see the following in
> serial_lpc32xx_interrupt():
>
> tty_insert_flip_char(tport, 0, TTY_OVERRUN);
> tty_schedule_flip(tport);
>
> where tty_insert_flip_char() manipulates flag/char/used:
>
> *flag_buf_ptr(tb, tb->used) = flag;
> *char_buf_ptr(tb, tb->used++) = ch;
>
> and tty_schedule_flip() copies "used" -> "commit":
>
> smp_store_release(&buf->tail->commit, buf->tail->used);
> queue_work(system_unbound_wq, &buf->work);
I'm lacking some ["a lot of", actually] knowledge here.
Alan, Jiri could you help us?
Correct me if I'm wrong. I thought that flip buffers are used to "cache"
received chars/commands from the device before device "sends" (flushes)
them to ldisc. So chars are added to flip buffers by the device itself - RX
function, which is most commonly called from the device's IRQ handler.
That's why we see things like
foo_irq_handler()
{
... spin_lock(uart_port->lock);
foo_TX_chars();
tty_flip_buffer_push(); // tty_schedule_flip()
...
spin_unlock(uart_port->lock);
}
or
foo_irq_handler()
{
... spin_lock(uart_port->lock);
foo_TX_chars()
{
...
tty_insert_flip_char();
tty_schedule_flip();
}
...
spin_unlock(uart_port->lock);
}
So it seems that flip buffers are for RX routines. Is this right?
Thus, if foo_irq_handler()->tty_flip_buffer_push() raced with something, then
it must have been another IRQ that appended data to the same uart_port flip
buffer. Which, probably, should not happen. There should be no other race
conditions. Correct?
So I'm still wondering if we can safely change this
foo_irq_handler()
{
... spin_lock(uart_port->lock);
foo_TX_chars();
tty_flip_buffer_push(); // tty_schedule_flip()
...
spin_unlock(uart_port->lock);
}
to this
foo_irq_handler()
{
... spin_lock(uart_port->lock);
foo_TX_chars();
...
spin_unlock(uart_port->lock);
tty_flip_buffer_push(); // tty_schedule_flip()
}
Alan, Jiri, can we do this?
> So far, the best (and realistic?) idea seems to be switching to
> printk_deferred() context when port->lock is taken. It would
> be a well defined pattern that people might get used to.
Hmm. Not sure, maybe I'm missing something. In this particular case we
don't call printk() under port->lock, so it doesn't matter if we are in
"normal" printk mode or in some "safe" printk mode. What we have is:
UART port->lock --> WQ pool->lock
Which is OK, and port->lock is sort of "innocent".
It's the stuff that we do under WQ pool->lock that hurts (deadlock).
WQ pool->lock -> printk -> UART port->lock
If we want printk_deferred() / printk_safe() to help us here, then
we need to switch to printk_deferred() / printk_safe() every time
we take WQ pool->lock. Which is, basically, what I have already
suggested.
But I'd rather try to move tty_flip_buffer_push() out of uart_port->lock
scope [if possible], so we would break the
uart_port->lock -> WQ pool->lock
dependency.
-ss
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2018-07-11 7:27 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-07-02 10:26 printk() from NMI backtrace can delay a lot Tetsuo Handa
2018-07-02 10:39 ` Sergey Senozhatsky
2018-07-03 4:30 ` Sergey Senozhatsky
2018-07-03 15:29 ` Tejun Heo
2018-07-03 16:31 ` Sergey Senozhatsky
2018-07-03 16:39 ` Sergey Senozhatsky
2018-07-10 11:50 ` Petr Mladek
2018-07-11 7:27 ` Sergey Senozhatsky
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).