releases/4.14.69/printk-tracing-do-not-trace-printk_nmi_enter.patch

   1 From d1c392c9e2a301f38998a353f467f76414e38725 Mon Sep 17 00:00:00 2001
   2 From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
   3 Date: Wed, 5 Sep 2018 16:29:49 -0400
   4 Subject: printk/tracing: Do not trace printk_nmi_enter()
   5
   6 From: Steven Rostedt (VMware) <rostedt@goodmis.org>
   7
   8 commit d1c392c9e2a301f38998a353f467f76414e38725 upstream.
   9
  10 I hit the following splat in my tests:
  11
  12 ------------[ cut here ]------------
  13 IRQs not enabled as expected
  14 WARNING: CPU: 3 PID: 0 at kernel/time/tick-sched.c:982 tick_nohz_idle_enter+0x44/0x8c
  15 Modules linked in: ip6t_REJECT nf_reject_ipv6 ip6table_filter ip6_tables ipv6
  16 CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.19.0-rc2-test+ #2
  17 Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
  18 EIP: tick_nohz_idle_enter+0x44/0x8c
  19 Code: ec 05 00 00 00 75 26 83 b8 c0 05 00 00 00 75 1d 80 3d d0 36 3e c1 00
  20 75 14 68 94 63 12 c1 c6 05 d0 36 3e c1 01 e8 04 ee f8 ff <0f> 0b 58 fa bb a0
  21 e5 66 c1 e8 25 0f 04 00 64 03 1d 28 31 52 c1 8b
  22 EAX: 0000001c EBX: f26e7f8c ECX: 00000006 EDX: 00000007
  23 ESI: f26dd1c0 EDI: 00000000 EBP: f26e7f40 ESP: f26e7f38
  24 DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00010296
  25 CR0: 80050033 CR2: 0813c6b0 CR3: 2f342000 CR4: 001406f0
  26 Call Trace:
  27  do_idle+0x33/0x202
  28  cpu_startup_entry+0x61/0x63
  29  start_secondary+0x18e/0x1ed
  30  startup_32_smp+0x164/0x168
  31 irq event stamp: 18773830
  32 hardirqs last  enabled at (18773829): [<c040150c>] trace_hardirqs_on_thunk+0xc/0x10
  33 hardirqs last disabled at (18773830): [<c040151c>] trace_hardirqs_off_thunk+0xc/0x10
  34 softirqs last  enabled at (18773824): [<c0ddaa6f>] __do_softirq+0x25f/0x2bf
  35 softirqs last disabled at (18773767): [<c0416bbe>] call_on_stack+0x45/0x4b
  36 ---[ end trace b7c64aa79e17954a ]---
  37
  38 After a bit of debugging, I found what was happening. This would trigger
  39 when performing "perf" with a high NMI interrupt rate, while enabling and
  40 disabling function tracer. Ftrace uses breakpoints to convert the nops at
  41 the start of functions to calls to the function trampolines. The breakpoint
  42 traps disable interrupts and this makes calls into lockdep via the
  43 trace_hardirqs_off_thunk in the entry.S code. What happens is the following:
  44
  45   do_idle {
  46
  47     [interrupts enabled]
  48
  49     <interrupt> [interrupts disabled]
  50         TRACE_IRQS_OFF [lockdep says irqs off]
  51         [...]
  52         TRACE_IRQS_IRET
  53             test if pt_regs say return to interrupts enabled [yes]
  54             TRACE_IRQS_ON [lockdep says irqs are on]
  55
  56             <nmi>
  57                 nmi_enter() {
  58                     printk_nmi_enter() [traced by ftrace]
  59                     [ hit ftrace breakpoint ]
  60                     <breakpoint exception>
  61                         TRACE_IRQS_OFF [lockdep says irqs off]
  62                         [...]
  63                         TRACE_IRQS_IRET [return from breakpoint]
  64                            test if pt_regs say interrupts enabled [no]
  65                            [iret back to interrupt]
  66            [iret back to code]
  67
  68     tick_nohz_idle_enter() {
  69
  70         lockdep_assert_irqs_enabled() [lockdep say no!]
  71
  72 Although interrupts are indeed enabled, lockdep thinks it is not, and since
  73 we now do asserts via lockdep, it gives a false warning. The issue here is
  74 that printk_nmi_enter() is called before lockdep_off(), which disables
  75 lockdep (for this reason) in NMIs. By simply not allowing ftrace to see
  76 printk_nmi_enter() (via notrace annotation) we keep lockdep from getting
  77 confused.
  78
  79 Cc: stable@vger.kernel.org
  80 Fixes: 42a0bb3f71383 ("printk/nmi: generic solution for safe printk in NMI")
  81 Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
  82 Acked-by: Petr Mladek <pmladek@suse.com>
  83 Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
  84 Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
  85
  86 ---
  87  kernel/printk/printk_safe.c |    4 ++--
  88  1 file changed, 2 insertions(+), 2 deletions(-)
  89
  90 --- a/kernel/printk/printk_safe.c
  91 +++ b/kernel/printk/printk_safe.c
  92 @@ -309,12 +309,12 @@ static __printf(1, 0) int vprintk_nmi(co
  93         return printk_safe_log_store(s, fmt, args);
  94  }
  95
  96 -void printk_nmi_enter(void)
  97 +void notrace printk_nmi_enter(void)
  98  {
  99         this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
 100  }
 101
 102 -void printk_nmi_exit(void)
 103 +void notrace printk_nmi_exit(void)
 104  {
 105         this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK);
 106  }