On 4/8/19 3:46 PM, Steven Rostedt wrote: > On Mon, 8 Apr 2019 14:24:47 +0200 > Daniel Bristot de Oliveira <[email protected]> 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.
The example is "to show that the new tracepoints would have shown that the NMI was longer than what the existing tracepoint pointed." The example was not the best, I agree.. but... it serves to illustrate the idea. -- Daniel
