x86/nmi: Push duration printk() to irq context
authorPeter Zijlstra <peterz@infradead.org>
Mon, 3 Feb 2014 17:02:09 +0000 (18:02 +0100)
committerIngo Molnar <mingo@kernel.org>
Sun, 9 Feb 2014 12:17:22 +0000 (13:17 +0100)
Calling printk() from NMI context is bad (TM), so move it to IRQ
context.

In doing so we slightly change (probably wreck) the debugfs
nmi_longest_ns thingy, in that it doesn't update to reflect the
longest, nor does writing to it reset the count.

Signed-off-by: Peter Zijlstra <peterz@infradead.org>
Cc: Don Zickus <dzickus@redhat.com>
Cc: Dave Hansen <dave.hansen@linux.intel.com>
Link: http://lkml.kernel.org/n/tip-rdw0au56a5ymis1u8p48c12d@git.kernel.org
Signed-off-by: Ingo Molnar <mingo@kernel.org>
arch/x86/include/asm/nmi.h
arch/x86/kernel/nmi.c

index 86f9301..5f2fc44 100644 (file)
@@ -1,6 +1,7 @@
 #ifndef _ASM_X86_NMI_H
 #define _ASM_X86_NMI_H
 
+#include <linux/irq_work.h>
 #include <linux/pm.h>
 #include <asm/irq.h>
 #include <asm/io.h>
@@ -38,6 +39,8 @@ typedef int (*nmi_handler_t)(unsigned int, struct pt_regs *);
 struct nmiaction {
        struct list_head        list;
        nmi_handler_t           handler;
+       u64                     max_duration;
+       struct irq_work         irq_work;
        unsigned long           flags;
        const char              *name;
 };
index 6fcb49c..b4872b9 100644 (file)
@@ -87,6 +87,7 @@ __setup("unknown_nmi_panic", setup_unknown_nmi_panic);
 #define nmi_to_desc(type) (&nmi_desc[type])
 
 static u64 nmi_longest_ns = 1 * NSEC_PER_MSEC;
+
 static int __init nmi_warning_debugfs(void)
 {
        debugfs_create_u64("nmi_longest_ns", 0644,
@@ -95,6 +96,20 @@ static int __init nmi_warning_debugfs(void)
 }
 fs_initcall(nmi_warning_debugfs);
 
+static void nmi_max_handler(struct irq_work *w)
+{
+       struct nmiaction *a = container_of(w, struct nmiaction, irq_work);
+       int remainder_ns, decimal_msecs;
+       u64 whole_msecs = ACCESS_ONCE(a->max_duration);
+
+       remainder_ns = do_div(whole_msecs, (1000 * 1000));
+       decimal_msecs = remainder_ns / 1000;
+
+       printk_ratelimited(KERN_INFO
+               "INFO: NMI handler (%ps) took too long to run: %lld.%03d msecs\n",
+               a->handler, whole_msecs, decimal_msecs);
+}
+
 static int __kprobes nmi_handle(unsigned int type, struct pt_regs *regs, bool b2b)
 {
        struct nmi_desc *desc = nmi_to_desc(type);
@@ -110,26 +125,20 @@ static int __kprobes nmi_handle(unsigned int type, struct pt_regs *regs, bool b2
         * to handle those situations.
         */
        list_for_each_entry_rcu(a, &desc->head, list) {
-               u64 before, delta, whole_msecs;
-               int remainder_ns, decimal_msecs, thishandled;
+               int thishandled;
+               u64 delta;
 
-               before = sched_clock();
+               delta = sched_clock();
                thishandled = a->handler(type, regs);
                handled += thishandled;
-               delta = sched_clock() - before;
+               delta = sched_clock() - delta;
                trace_nmi_handler(a->handler, (int)delta, thishandled);
 
-               if (delta < nmi_longest_ns)
+               if (delta < nmi_longest_ns || delta < a->max_duration)
                        continue;
 
-               nmi_longest_ns = delta;
-               whole_msecs = delta;
-               remainder_ns = do_div(whole_msecs, (1000 * 1000));
-               decimal_msecs = remainder_ns / 1000;
-               printk_ratelimited(KERN_INFO
-                       "INFO: NMI handler (%ps) took too long to run: "
-                       "%lld.%03d msecs\n", a->handler, whole_msecs,
-                       decimal_msecs);
+               a->max_duration = delta;
+               irq_work_queue(&a->irq_work);
        }
 
        rcu_read_unlock();
@@ -146,6 +155,8 @@ int __register_nmi_handler(unsigned int type, struct nmiaction *action)
        if (!action->handler)
                return -EINVAL;
 
+       init_irq_work(&action->irq_work, nmi_max_handler);
+
        spin_lock_irqsave(&desc->lock, flags);
 
        /*