Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class
From: Steven Rostedt
Date: Mon Apr 08 2019 - 09:46:38 EST
On Mon, 8 Apr 2019 14:24:47 +0200
Daniel Bristot de Oliveira <bristot@xxxxxxxxxx> wrote:
> NMI starts:
> f-4447 [000] d.Z. 1487.689290: nmi_entry: vector=2
> f-4447 [000] d.Z. 1487.689291: default_do_nmi <-do_nmi
> f-4447 [000] d.Z. 1487.689291: nmi_handle <-default_do_nmi
> f-4447 [000] d.Z. 1487.689291: nmi_cpu_backtrace_handler <-nmi_handle
>
> It handles very fast:
> f-4447 [000] d.Z. 1487.689292: nmi_handler: nmi_cpu_backtrace_handler()
> delta_ns: 780 handled: 0
>
> But some other functions continues running in the NMI context:
> [Dazed and confused, but trying to continue message ]
> f-4447 [000] d.Z. 1487.689292: _raw_spin_trylock <-default_do_nmi
> f-4447 [000] d.Z. 1487.689566: unknown_nmi_error <-default_do_nmi
> f-4447 [000] d.Z. 1487.689566: nmi_handle <-unknown_nmi_error
> f-4447 [000] d.Z. 1487.689567: printk <-unknown_nmi_error
> f-4447 [000] d.Z. 1487.689567: vprintk_func <-printk
> f-4447 [000] d.Z. 1487.689567: printk_safe_log_store <-vprintk_func
> f-4447 [000] d.Z. 1487.689569: arch_irq_work_raise <-irq_work_queue
> f-4447 [000] d.Z. 1487.689569: default_send_IPI_self <-arch_irq_work_raise
> f-4447 [000] d.Z. 1487.689569: __default_send_IPI_shortcut
> <-default_send_IPI_self
Just to remove confusion. Your example is to show that the new
tracepoints would have shown that the NMI was long due to the printk? As
running printk from NMI (even with the delayed output) isn't a normal
path.
-- Steve