| 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
| ||
|
Message-Id: <20130529222803.9A11A23E@viggo.jf.intel.com>
Date: Wed, 29 May 2013 15:28:03 -0700
From: Dave Hansen <dave@...1.net>
To: a.p.zijlstra@...llo.nl
Cc: mingo@...hat.com, paulus@...ba.org, acme@...stprotocols.net,
tglx@...utronix.de, x86@...nel.org, linux-kernel@...r.kernel.org,
Dave Hansen <dave@...1.net>
Subject: [v3][PATCH 4/4] x86: nmi length tracepoints
From: Dave Hansen <dave.hansen@...ux.intel.com>
This patch has been invaluable in my adventures finding
issues in the perf NMI handler. I'm as big a fan of
printk() as anybody is, but using printk() in NMIs is
deadly when they're happening frequently.
Even hacking in trace_printk() ended up eating enough
CPU to throw off some of the measurements I was making.
Signed-off-by: Dave Hansen <dave.hansen@...ux.intel.com>
---
linux.git-davehans/Documentation/trace/events-nmi.txt | 43 ++++++++++++++++++
linux.git-davehans/arch/x86/kernel/nmi.c | 9 ++-
linux.git-davehans/include/trace/events/nmi.h | 37 +++++++++++++++
3 files changed, 87 insertions(+), 2 deletions(-)
diff -puN arch/x86/kernel/nmi.c~nmi-tracepoints arch/x86/kernel/nmi.c
--- linux.git/arch/x86/kernel/nmi.c~nmi-tracepoints 2013-05-29 15:10:19.717684752 -0700
+++ linux.git-davehans/arch/x86/kernel/nmi.c 2013-05-29 15:10:19.720684883 -0700
@@ -30,6 +30,9 @@
#include <asm/nmi.h>
#include <asm/x86_init.h>
+#define CREATE_TRACE_POINTS
+#include <trace/events/nmi.h>
+
struct nmi_desc {
spinlock_t lock;
struct list_head head;
@@ -108,11 +111,13 @@ static int __kprobes nmi_handle(unsigned
*/
list_for_each_entry_rcu(a, &desc->head, list) {
u64 before, delta, whole_msecs;
- int decimal_msecs;
+ int decimal_msecs, thishandled;
before = local_clock();
- handled += a->handler(type, regs);
+ thishandled = a->handler(type, regs);
+ handled += thishandled;
delta = local_clock() - before;
+ trace_nmi_handler(a->handler, (int)delta, thishandled);
if (delta < nmi_longest_ns)
continue;
diff -puN /dev/null Documentation/trace/events-nmi.txt
--- /dev/null 2013-03-17 11:51:50.342329668 -0700
+++ linux.git-davehans/Documentation/trace/events-nmi.txt 2013-05-29 15:10:19.720684883 -0700
@@ -0,0 +1,43 @@
+NMI Trace Events
+
+These events normally show up here:
+
+ /sys/kernel/debug/tracing/events/nmi
+
+--
+
+nmi_handler:
+
+You might want to use this tracepoint if you suspect that your
+NMI handlers are hogging large amounts of CPU time. The kernel
+will warn if it sees long-running handlers:
+
+ INFO: NMI handler took too long to run: 9.207 msecs
+
+and this tracepoint will allow you to drill down and get some
+more details.
+
+Let's say you suspect that perf_event_nmi_handler() is causing
+you some problems and you only want to trace that handler
+specifically. You need to find its address:
+
+ $ grep perf_event_nmi_handler /proc/kallsyms
+ ffffffff81625600 t perf_event_nmi_handler
+
+Let's also say you are only interested in when that function is
+really hogging a lot of CPU time, like a millisecond at a time.
+Note that the kernel's output is in milliseconds, but the input
+to the filter is in nanoseconds! You can filter on 'delta_ns':
+
+cd /sys/kernel/debug/tracing/events/nmi/nmi_handler
+echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter
+echo 1 > enable
+
+Your output would then look like:
+
+$ cat /sys/kernel/debug/tracing/trace_pipe
+<idle>-0 [000] d.h3 505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 1
+<idle>-0 [000] d.h3 505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 1
+<idle>-0 [000] d.h3 506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 1
+<idle>-0 [000] d.h3 506.334346: nmi_handler: perf_event_nmi_handler() delta_ns: 3080351 handled: 1
+
diff -puN /dev/null include/trace/events/nmi.h
--- /dev/null 2013-03-17 11:51:50.342329668 -0700
+++ linux.git-davehans/include/trace/events/nmi.h 2013-05-29 15:10:19.720684883 -0700
@@ -0,0 +1,37 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM nmi
+
+#if !defined(_TRACE_NMI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_NMI_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(nmi_handler,
+
+ TP_PROTO(void *handler, s64 delta_ns, int handled),
+
+ TP_ARGS(handler, delta_ns, handled),
+
+ TP_STRUCT__entry(
+ __field( void *, handler )
+ __field( s64, delta_ns)
+ __field( int, handled )
+ ),
+
+ TP_fast_assign(
+ __entry->handler = handler;
+ __entry->delta_ns = delta_ns;
+ __entry->handled = handled;
+ ),
+
+ TP_printk("%ps() delta_ns: %lld handled: %d",
+ __entry->handler,
+ __entry->delta_ns,
+ __entry->handled)
+);
+
+#endif /* _TRACE_NMI_H */
+
+/* This part ust be outside protection */
+#include <trace/define_trace.h>
_
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists