Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

[Steven Rostedt <rostedt@goodmis.org>]

On Mon, 8 Apr 2019 14:24:47 +0200
Daniel Bristot de Oliveira <bristot@redhat.com> 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