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. -- Steve
