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

[Daniel Bristot de Oliveira]

On 4/8/19 3:46 PM, Steven Rostedt wrote:
> 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.

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