linux-kernel - Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20190408094633.7ff8dbf4@gandalf.local.home>
Date:   Mon, 8 Apr 2019 09:46:33 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Daniel Bristot de Oliveira <bristot@...hat.com>
Cc:     Thomas Gleixner <tglx@...utronix.de>,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Ingo Molnar <mingo@...hat.com>,
        Peter Zijlstra <peterz@...radead.org>,
        Andy Lutomirski <luto@...nel.org>,
        Clark Williams <williams@...hat.com>, x86@...nel.org
Subject: Re: [PATCH V2 2/2] trace,x86: Add nmi to the irq_vectors class

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