perf/x86: Push the duration-logging printk() to IRQ context

Calling printk() from NMI context is bad (TM), so move it to IRQ
context.

This also avoids the problem where the printk() time is measured by
the generic NMI duration goo and triggers a second warning.

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-75dv35xf6dhhmeb7nq6fua31@git.kernel.org
Signed-off-by: Ingo Molnar <mingo@kernel.org>

diff --git a/include/linux/irq_work.h b/include/linux/irq_work.h
index 66017028dcb3d0aebf70aa7281e7758a42bcb3bf..add13c8624b701ea9f8e1ccf93d18a9d4ff0f2da 100644 (file)
--- a/include/linux/irq_work.h
+++ b/include/linux/irq_work.h
@@ -30,6 +30,8 @@ void init_irq_work(struct irq_work *work, void (*func)(struct irq_work *))
        work->func = func;
 }
 
+#define DEFINE_IRQ_WORK(name, _f) struct irq_work name = { .func = (_f), }
+
 void irq_work_queue(struct irq_work *work);
 void irq_work_run(void);
 void irq_work_sync(struct irq_work *work);

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 56003c6edfd38c03e8dd523f1efb01d99bcf2e84..2067cbb378eb40e7f0dbf348b8d54fe401a1adb9 100644 (file)
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -231,11 +231,29 @@ int perf_cpu_time_max_percent_handler(struct ctl_table *table, int write,
 #define NR_ACCUMULATED_SAMPLES 128
 static DEFINE_PER_CPU(u64, running_sample_length);
 
-void perf_sample_event_took(u64 sample_len_ns)
+static void perf_duration_warn(struct irq_work *w)
 {
+       u64 allowed_ns = ACCESS_ONCE(perf_sample_allowed_ns);
        u64 avg_local_sample_len;
        u64 local_samples_len;
+
+       local_samples_len = __get_cpu_var(running_sample_length);
+       avg_local_sample_len = local_samples_len/NR_ACCUMULATED_SAMPLES;
+
+       printk_ratelimited(KERN_WARNING
+                       "perf interrupt took too long (%lld > %lld), lowering "
+                       "kernel.perf_event_max_sample_rate to %d\n",
+                       avg_local_sample_len, allowed_ns,
+                       sysctl_perf_event_sample_rate);
+}
+
+static DEFINE_IRQ_WORK(perf_duration_work, perf_duration_warn);
+
+void perf_sample_event_took(u64 sample_len_ns)
+{
        u64 allowed_ns = ACCESS_ONCE(perf_sample_allowed_ns);
+       u64 avg_local_sample_len;
+       u64 local_samples_len;
 
        if (allowed_ns == 0)
                return;
@@ -263,13 +281,9 @@ void perf_sample_event_took(u64 sample_len_ns)
        sysctl_perf_event_sample_rate = max_samples_per_tick * HZ;
        perf_sample_period_ns = NSEC_PER_SEC / sysctl_perf_event_sample_rate;
 
-       printk_ratelimited(KERN_WARNING
-                       "perf samples too long (%lld > %lld), lowering "
-                       "kernel.perf_event_max_sample_rate to %d\n",
-                       avg_local_sample_len, allowed_ns,
-                       sysctl_perf_event_sample_rate);
-
        update_perf_cpu_limits();
+
+       irq_work_queue(&perf_duration_work);
 }
 
 static atomic64_t perf_event_id;