From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
To: Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>,
Tejun Heo <tj@kernel.org>, Steven Rostedt <rostedt@goodmis.org>,
Petr Mladek <pmladek@suse.com>
Cc: Peter Zijlstra <peterz@infradead.org>,
Linus Torvalds <torvalds@linux-foundation.org>,
Andrew Morton <akpm@linux-foundation.org>,
Dmitry Vyukov <dvyukov@google.com>,
linux-kernel@vger.kernel.org,
Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Subject: Re: printk() from NMI backtrace can delay a lot
Date: Tue, 3 Jul 2018 13:30:21 +0900 [thread overview]
Message-ID: <20180703043021.GA547@jagdpanzerIV> (raw)
In-Reply-To: <bf037670-c647-b34a-486b-53ec3661b48e@i-love.sakura.ne.jp>
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
next prev parent reply other threads:[~2018-07-03 4:30 UTC|newest]
Thread overview: 8+ messages / expand[flat|nested] mbox.gz Atom feed top
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 [this message]
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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20180703043021.GA547@jagdpanzerIV \
--to=sergey.senozhatsky.work@gmail.com \
--cc=akpm@linux-foundation.org \
--cc=dvyukov@google.com \
--cc=linux-kernel@vger.kernel.org \
--cc=penguin-kernel@i-love.sakura.ne.jp \
--cc=peterz@infradead.org \
--cc=pmladek@suse.com \
--cc=rostedt@goodmis.org \
--cc=sergey.senozhatsky@gmail.com \
--cc=tj@kernel.org \
--cc=torvalds@linux-foundation.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox