tracing: Add Hardware Latency detector tracer
Subsystems (5)
Steven Rostedt
maintainerv2 cover tracing: Add Hardware Latency detector tracer
This adds the PREEMPT_RT hwlat detector as a Linux tracer in mainline. In the PREEMPT_RT patch set, it is a separate entity that is controlled by the debugfs file system. I found that it is better suited as a latency tracer in the tracing directory, as it follows pretty much the same paradigm as the other latency tracers that already exist. All I had to add was a hwlat_detector directory that contained a window and width for the period and duration respectively of the test. But the samples would just write to the tracing ring buffer and the max latency would be stored in tracing_max_latency, and the threshold can be set by the existing tracing_threshold. The last patch also adds a new feature that would have the kthread migrate after each period to another CPU specified by tracing_cpumask.
Here's the documention that is added to hwlat_detector.txt in the Documentation directory:
Introduction:
-------------
The tracer hwlat_detector is a special purpose tracer that is used to detect large system latencies induced by the behavior of certain underlying hardware or firmware, independent of Linux itself. The code was developed originally to detect SMIs (System Management Interrupts) on x86 systems, however there is nothing x86 specific about this patchset. It was originally written for use by the "RT" patch since the Real Time kernel is highly latency sensitive.
SMIs are not serviced by the Linux kernel, which means that it does not even know that they are occuring. SMIs are instead set up by BIOS code and are serviced by BIOS code, usually for "critical" events such as management of thermal sensors and fans. Sometimes though, SMIs are used for other tasks and those tasks can spend an inordinate amount of time in the handler (sometimes measured in milliseconds). Obviously this is a problem if you are trying to keep event service latencies down in the microsecond range.
The hardware latency detector works by hogging one of the cpus for configurable amounts of time (with interrupts disabled), polling the CPU Time Stamp Counter for some period, then looking for gaps in the TSC data. Any gap indicates a time when the polling was interrupted and since the interrupts are disabled, the only thing that could do that would be an SMI or other hardware hiccup (or an NMI, but those can be tracked).
Note that the hwlat detector should *NEVER* be used in a production environment. It is intended to be run manually to determine if the hardware platform has a problem with long system firmware service routines.
Usage:
------
Write the ASCII text "hwlat" into the current_tracer file of the tracing system (mounted at /sys/kernel/tracing or /sys/kernel/tracing). It is possible to redefine the threshold in microseconds (us) above which latency spikes will be taken into account.
Example:
# echo hwlat > /sys/kernel/tracing/current_tracer # echo 100 > /sys/kernel/tracing/tracing_thresh
The /sys/kernel/tracing/hwlat_detector interface contains the following files:
width - time period to sample with CPUs held (usecs)
must be less than the total window size (enforced)
window - total period of sampling, width being inside (usecs)
By default the width is set to 500,000 and window to 1,000,000, meaning that for every 1,000,000 usecs (1s) the hwlat detector will spin for 500,000 usecs (0.5s). If tracing_thresh contains zero when hwlat tracer is enabled, it will change to a default of 10 usecs. If any latencies that exceed the threshold is observed then the data will be written to the tracing ring buffer.
The minimum sleep time between periods is 1 millisecond. Even if width is less than 1 millisecond apart from window, to allow the system to not be totally starved.
If tracing_thresh was zero when hwlat detector was started, it will be set back to zero if another tracer is loaded. Note, the last value in tracing_thresh that hwlat detector had will be saved and this value will be restored in tracing_thresh if it is still zero when hwlat detector is started again.
The following tracing directory files are used by the hwlat_detector:
in /sys/kernel/tracing:
tracing_threshold - minimum latency value to be considered (usecs)
tracing_max_latency - maximum hardware latency actually observed (usecs)
hwlat_detector/width - specified amount of time to spin within window (usecs)
hwlat_detector/window - amount of time between (width) runs (usecs)
Changes since v1:
. Added checks for CONFIG_GENERIC_SCHED_CLOCK, and if that is set,
only nmi_counts will be recorded when an NMI is triggered, but not the time in NMI, because the generic sched_clock is not NMI safe. (suggested by Sebastian Andrzej Siewior)
. Changed the format a little to be a little nicer looking.
Was: [99] inner:13 outer:16 ts:1470352534.886878855
Now: #99 inner/outer(us): 13/16 ts:1470352534.886878855
. Included the NMI patch into the main patch set.
. Holding off SMI counting until I have an arch_smi_count() that isn't
so "really yucky".
Jon Masters (1):
tracing: Add documentation for hwlat_detector tracer
Steven Rostedt (Red Hat) (3):
tracing: Added hardware latency tracer
tracing: Have hwlat trace migrate across tracing_cpumask CPUs
tracing: Add NMI tracing in hwlat detector
----
Documentation/trace/hwlat_detector.txt | 79 ++++ arch/sh/kernel/ftrace.c | 4 +- include/linux/ftrace_irq.h | 31 +- kernel/trace/Kconfig | 35 ++ kernel/trace/Makefile | 1 + kernel/trace/trace.c | 2 +- kernel/trace/trace.h | 3 + kernel/trace/trace_entries.h | 27 ++ kernel/trace/trace_hwlat.c | 633 +++++++++++++++++++++++++++++++++ kernel/trace/trace_output.c | 66 ++++ 10 files changed, 874 insertions(+), 7 deletions(-) create mode 100644 Documentation/trace/hwlat_detector.txt create mode 100644 kernel/trace/trace_hwlat.c
Steven Rostedt
maintainerPATCH v2 1/4 tracing: Added hardware latency tracer
From: "Steven Rostedt (Red Hat)" <[email protected]>
The hardware latency tracer has been in the PREEMPT_RT patch for some time. It is used to detect possible SMIs or any other hardware interruptions that the kernel is unaware of. Note, NMIs may also be detected, but that may be good to note as well.
The logic is pretty simple. It simply creates a thread that spins on a single CPU for a specified amount of time (width) within a periodic window (window). These numbers may be adjusted by their cooresponding names in
/sys/kernel/tracing/hwlat_detector/
The defaults are window = 1000000 us (1 second)
width = 500000 us (1/2 second)
The loop consists of:
t1 = trace_clock_local(); t2 = trace_clock_local();
Where trace_clock_local() is a variant of sched_clock().
The difference of t2 - t1 is recorded as the "inner" timestamp and also the timestamp t1 - prev_t2 is recorded as the "outer" timestamp. If either of these differences are greater than the time denoted in /sys/kernel/tracing/tracing_thresh then it records the event.
When this tracer is started, and tracing_thresh is zero, it changes to the default threshold of 10 us.
The hwlat tracer in the PREEMPT_RT patch was originally written by Jon Masters. I have modified it quite a bit and turned it into a tracer.
--- kernel/trace/Kconfig | 35 +++ kernel/trace/Makefile | 1 + kernel/trace/trace.c | 2 +- kernel/trace/trace.h | 3 + kernel/trace/trace_entries.h | 23 ++ kernel/trace/trace_hwlat.c | 527 +++++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace_output.c | 52 +++++ 7 files changed, 642 insertions(+), 1 deletion(-) create mode 100644 kernel/trace/trace_hwlat.c
kernel/trace/Kconfig +35 -0
@@ -221,6 +221,41 @@ config SCHED_TRACER This tracer tracks the latency of the highest priority task to be scheduled in, starting from the point it has woken up. +config HWLAT_TRACER + bool "Tracer to detect hardware latencies (like SMIs)" + select GENERIC_TRACER + help + This tracer, when enabled will create one or more kernel threads, + depening on what the cpumask file is set to, which each thread + spinning in a loop looking for interruptions caused by + something other than the kernel. For example, if a + System Management Interrupt (SMI) takes a noticeable amount of + time, this tracer will detect it. This is useful for testing + if a system is reliable for Real Time tasks. + + Some files are created in the tracing directory when this + is enabled: + + hwlat_detector/width - time in usecs for how long to spin for + hwlat_detector/window - time in usecs between the start of each + iteration + + A kernel thread is created that will spin with interrupts disabled + for "width" microseconds in every "widow" cycle. It will not spin + for "window - width" microseconds, where the system can + continue to operate. + + The output will appear in the trace and trace_pipe files. + + When the tracer is not running, it has no affect on the system, + but when it is running, it can cause the system to be + periodically non responsive. Do not run this tracer on a + production system. + + To enable this tracer, echo in "hwlat" into the current_tracer + file. Every time a latency is greater than tracing_thresh, it will + be recorded into the ring buffer. + config ENABLE_DEFAULT_TRACERS bool "Trace process context switches and events" depends on !GENERIC_TRACER
kernel/trace/Makefile +1 -0
@@ -37,6 +37,7 @@ obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o +obj-$(CONFIG_HWLAT_TRACER) += trace_hwlat.o obj-$(CONFIG_NOP_TRACER) += trace_nop.o obj-$(CONFIG_STACK_TRACER) += trace_stack.o obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
kernel/trace/trace.c +1 -1
@@ -1047,7 +1047,7 @@ void disable_trace_on_warning(void)* * Shows real state of the ring buffer if it is enabled or not. */ -static int tracer_tracing_is_on (struct trace_array *tr) +int tracer_tracing_is_on (struct trace_array *tr) {if (tr->trace_buffer.buffer)return ring_buffer_record_is_on (tr->trace_buffer.buffer);
kernel/trace/trace.h +3 -0
@@ -38,6 +38,7 @@ enum trace_type {TRACE_USER_STACK ,TRACE_BLK ,TRACE_BPUTS , +TRACE_HWLAT , __TRACE_LAST_TYPE, };
@@ -326,6 +327,7 @@ extern void __ftrace_bad_type(void); IF_ASSIGN(var, ent, struct print_entry, TRACE_PRINT); \ IF_ASSIGN(var, ent, struct bprint_entry, TRACE_BPRINT); \ IF_ASSIGN(var, ent, struct bputs_entry, TRACE_BPUTS); \ + IF_ASSIGN(var, ent, struct hwlat_entry, TRACE_HWLAT); \ IF_ASSIGN(var, ent, struct trace_mmiotrace_rw, \TRACE_MMIO_RW ); \ IF_ASSIGN(var, ent, struct trace_mmiotrace_map, \
@@ -571,6 +573,7 @@ void tracing_reset_current(int cpu);void tracing_reset_all_online_cpus (void );int tracing_open_generic (struct inode *inode,struct file *filp);bool tracing_is_disabled (void ); +int tracer_tracing_is_on (struct trace_array *tr); struct dentry *trace_create_file(const char *name, umode_t mode, struct dentry *parent,
kernel/trace/trace_entries.h +23 -0
@@ -322,3 +322,26 @@ FTRACE_ENTRY(branch, trace_branch,FILTER_OTHER ); + +FTRACE_ENTRY (hwlat, hwlat_entry, + +TRACE_HWLAT , + +F_STRUCT ( + __field( u64, duration ) + __field( u64, outer_duration ) + __field_struct( struct timespec, timestamp ) + __field_desc( long, timestamp, tv_sec ) + __field_desc( long, timestamp, tv_nsec ) + __field( unsigned int, seqnum ) + ), + +F_printk ("cnt:%u\tts:%010lu.%010lu\tinner:%llu\touter:%llu\n" , + __entry->seqnum, + __entry->tv_sec, + __entry->tv_nsec, + __entry->duration, + __entry->outer_duration), + +FILTER_OTHER +);
kernel/trace/trace_hwlat.c new file +527 -0
527 lines not on this page · raw message
kernel/trace/trace_output.c +52 -0
64 lines not on this page · raw message
Signature · 1 line
2.8.1
Re: [PATCH v2 1/4] tracing: Added hardware latency tracer
Quoted 91 lines · Steven Rostedt
kernel/trace/trace_hwlat.c new file +85
-0@@ -0,0 +1,527 @@ +/* +* trace_hwlatdetect.c - A simple Hardware Latency detector. +* +* Use this tracer to detect large system latencies induced by the behavior of +* certain underlying system hardware or firmware, independent of Linux itself. +* The code was developed originally to detect the presence of SMIs on Intel +* and AMD systems, although there is no dependency upon x86 herein. +* +* The classical example usage of this tracer is in detecting the presence of +* SMIs or System Management Interrupts on Intel and AMD systems. An SMI is a +* somewhat special form of hardware interrupt spawned from earlier CPU debug +* modes in which the (BIOS/EFI/etc.) firmware arranges for the South Bridge +* LPC (or other device) to generate a special interrupt under certain +* circumstances, for example, upon expiration of a special SMI timer device, +* due to certain external thermal readings, on certain I/O address accesses, +* and other situations. An SMI hits a special CPU pin, triggers a special +* SMI mode (complete with special memory map), and the OS is unaware. +* +* Although certain hardware-inducing latencies are necessary (for example, +* a modern system often requires an SMI handler for correct thermal control +* and remote management) they can wreak havoc upon any OS-level performance +* guarantees toward low-latency, especially when the OS is not even made +* aware of the presence of these interrupts. For this reason, we need a +* somewhat brute force mechanism to detect these interrupts. In this case, +* we do it by hogging all of the CPU(s) for configurable timer intervals, +* sampling the built-in CPU timer, looking for discontiguous readings. +* +* WARNING: This implementation necessarily introduces latencies. Therefore, +* you should NEVER use this tracer while running in a production +* environment requiring any kind of low-latency performance +* guarantee(s). +* +* Copyright (C) 2008-2009 Jon Masters, Red Hat, Inc. <[email protected]> +* Copyright (C) 2013-2016 Steven Rostedt, Red Hat, Inc. <[email protected]> +* +* Includes useful feedback from Clark Williams <[email protected]> +* +* This file is licensed under the terms of the GNU General Public +* License version 2. This program is licensed "as is" without any +* warranty of any kind, whether express or implied. +*/ +#include <linux/kthread.h> +#include <linux/tracefs.h> +#include <linux/uaccess.h> +#include <linux/delay.h> +#include "trace.h" + +static struct trace_array *hwlat_trace; + +#define U64STR_SIZE 22/* 20 digits max */ + +#define BANNER "hwlat_detector: " +#define DEFAULT_SAMPLE_WINDOW 1000000/* 1s */ +#define DEFAULT_SAMPLE_WIDTH 500000/* 0.5s */ +#define DEFAULT_LAT_THRESHOLD 10/* 10us */ + +/* sampling thread*/ +static struct task_struct *hwlat_kthread; + +static struct dentry *hwlat_sample_width;/* sample width us */ +static struct dentry *hwlat_sample_window;/* sample window us */ + +/* Save the previous tracing_thresh value */ +static unsigned long save_tracing_thresh; + +/* If the user changed threshold, remember it */ +static u64 last_tracing_thresh =DEFAULT_LAT_THRESHOLD *NSEC_PER_USEC ; + +/* Individual latency samples are stored here when detected. */ +struct hwlat_sample { +u64 seqnum;/* unique sequence */ +u64 duration;/* delta */ +u64 outer_duration;/* delta (outer loop) */ +struct timespec timestamp;/* wall time */ +}; + +/* keep the global state somewhere. */ +static struct hwlat_data { + + struct mutex lock; /* protect changes */ + + u64 count; /* total since reset */ + + u64 sample_window; /* total sampling window (on+off) */ + u64 sample_width; /* active sampling portion of window */
kernel/trace/trace_hwlat.c line 95
Quoted 10 lines
kernel/trace/trace_hwlat.c new file +10
-0+ +} hwlat_data = { + .sample_window = DEFAULT_SAMPLE_WINDOW, + .sample_width = DEFAULT_SAMPLE_WIDTH, +}; + +static void trace_hwlat_sample (struct hwlat_sample *sample) +{ +struct trace_array *tr = hwlat_trace; +struct trace_event_call *call = &event_hwlat;
Steven, where is this variable event_hwlat declared? To me it seems that some macro is declaring it (most likely DEFINE_EVENT) but I was not able to figure out the chain that ends up in the declaration.
--
Nilay
Steven Rostedt
maintainerRe: [PATCH v2 1/4] tracing: Added hardware latency tracer
Quoted 8 lines · On Mon, 22 Aug 2016 12:27:58 -0500 Nilay Vaish <[email protected]> wrote:
kernel/trace/trace_hwlat.c line 95
Quoted 4 lines
kernel/trace/trace_hwlat.c new file +4
-0+static void trace_hwlat_sample (struct hwlat_sample *sample) +{ +struct trace_array *tr = hwlat_trace; +struct trace_event_call *call = &event_hwlat;Steven, where is this variable
event_hwlatdeclared? To me it seems that some macro is declaring it (most likelyDEFINE_EVENT) but I was not able to figure out the chain that ends up in the declaration.
Yeah, it's created similarly to how trace_events are created.
It's created via kernel/trace/trace_export.c using kernel/trace/trace_entries.h
-- Steve
Steven Rostedt
maintainerPATCH v2 2/4 tracing: Add documentation for hwlat_detector tracer
In reply to Steven RostedtFrom: Jon Masters <[email protected]>
Added the documentation on how to use th hwlat_detector.
--- Documentation/trace/hwlat_detector.txt | 73 ++++++++++++++++++++++++++++++++++ 1 file changed, 73 insertions(+) create mode 100644 Documentation/trace/hwlat_detector.txt
Documentation/trace/hwlat_detector.txt new file +73 -0
@@ -0,0 +1,73 @@ +Introduction: +------------- + +The tracer hwlat_detector is a special purpose tracer that is used to +detect large system latencies induced by the behavior of certain underlying +hardware or firmware, independent of Linux itself. The code was developed +originally to detect SMIs (System Management Interrupts) on x86 systems, +however there is nothing x86 specific about this patchset. It was +originally written for use by the "RT" patch since the Real Time +kernel is highly latency sensitive. + +SMIs are not serviced by the Linux kernel, which means that it does not +even know that they are occuring. SMIs are instead set up by BIOS code +and are serviced by BIOS code, usually for "critical" events such as +management of thermal sensors and fans. Sometimes though, SMIs are used for +other tasks and those tasks can spend an inordinate amount of time in the +handler (sometimes measured in milliseconds). Obviously this is a problem if +you are trying to keep event service latencies down in the microsecond range. + +The hardware latency detector works by hogging one of the cpus for configurable +amounts of time (with interrupts disabled), polling the CPU Time Stamp Counter +for some period, then looking for gaps in the TSC data. Any gap indicates a +time when the polling was interrupted and since the interrupts are disabled, +the only thing that could do that would be an SMI or other hardware hiccup +(or an NMI, but those can be tracked). + +Note that the hwlat detector should *NEVER* be used in a production environment. +It is intended to be run manually to determine if the hardware platform has a +problem with long system firmware service routines. + +Usage: +------ + +Write the ASCII text "hwlat" into the current_tracer file of the tracing system +(mounted at /sys/kernel/tracing or /sys/kernel/tracing). It is possible to +redefine the threshold in microseconds (us) above which latency spikes will +be taken into account. + +Example: + + # echo hwlat > /sys/kernel/tracing/current_tracer + # echo 100 > /sys/kernel/tracing/tracing_thresh + +The /sys/kernel/tracing/hwlat_detector interface contains the following files: + +width - time period to sample with CPUs held (usecs) + must be less than the total window size (enforced) +window - total period of sampling, width being inside (usecs) + +By default the width is set to 500,000 and window to 1,000,000, meaning that +for every 1,000,000 usecs (1s) the hwlat detector will spin for 500,000 usecs +(0.5s). If tracing_thresh contains zero when hwlat tracer is enabled, it will +change to a default of 10 usecs. If any latencies that exceed the threshold is +observed then the data will be written to the tracing ring buffer. + +The minimum sleep time between periods is 1 millisecond. Even if width +is less than 1 millisecond apart from window, to allow the system to not +be totally starved. + +If tracing_thresh was zero when hwlat detector was started, it will be set +back to zero if another tracer is loaded. Note, the last value in +tracing_thresh that hwlat detector had will be saved and this value will +be restored in tracing_thresh if it is still zero when hwlat detector is +started again. + +The following tracing directory files are used by the hwlat_detector: + +in /sys/kernel/tracing: + + tracing_threshold - minimum latency value to be considered (usecs) + tracing_max_latency - maximum hardware latency actually observed (usecs) + hwlat_detector/width - specified amount of time to spin within window (usecs) + hwlat_detector/window - amount of time between (width) runs (usecs)
Signature · 1 line
2.8.1
Steven Rostedt
maintainerPATCH v2 3/4 tracing: Have hwlat trace migrate across tracing_cpumask CPUs
In reply to Steven RostedtFrom: "Steven Rostedt (Red Hat)" <[email protected]>
Instead of having the hwlat detector thread stay on one CPU, have it migrate across all the CPUs specified by tracing_cpumask. If the user modifies the thread's CPU affinity, the migration will stop until the next instance that the tracer is instantiated. The migration happens at the end of each window (period).
--- Documentation/trace/hwlat_detector.txt | 6 ++++ kernel/trace/trace_hwlat.c | 55 ++++++++++++++++++++++++++++++++++ 2 files changed, 61 insertions(+)
Documentation/trace/hwlat_detector.txt +6 -0
@@ -69,5 +69,11 @@ in /sys/kernel/tracing: tracing_threshold - minimum latency value to be considered (usecs) tracing_max_latency - maximum hardware latency actually observed (usecs) + tracing_cpumask - the CPUs to move the hwlat thread across hwlat_detector/width - specified amount of time to spin within window (usecs) hwlat_detector/window - amount of time between (width) runs (usecs) + +The hwlat detector's kernel thread will migrate across each CPU specified in +tracing_cpumask between each window. To limit the migration, either modify +tracing_cpumask, or modify the hwlat kernel thread (named [hwlatd]) CPU +affinity directly, and the migration will stop.
kernel/trace/trace_hwlat.c +55 -0
79 lines not on this page · raw message
Signature · 1 line
2.8.1
Steven Rostedt
maintainerPATCH v2 4/4 tracing: Add NMI tracing in hwlat detector
In reply to Steven RostedtFrom: "Steven Rostedt (Red Hat)" <[email protected]>
As NMIs can also cause latency when interrupts are disabled, the hwlat detectory has no way to know if the latency it detects is from an NMI or an SMI or some other hardware glitch.
As ftrace_nmi_enter/exit() funtions are no longer used (except for sh, which isn't supported anymore), I converted those to "arch_ftrace_nmi_enter/exit" and use ftrace_nmi_enter/exit() to check if hwlat detector is tracing or not, and if so, it calls into the hwlat utility.
Since the hwlat detector only has a single kthread that is spinning with interrupts disabled, it marks what CPU it is on, and if the NMI callback happens on that CPU, it records the time spent in that NMI. This is added to the output that is generated by the hwlat detector as:
#3 inner/outer(us): 9/9 ts:1470836488.206734548 #4 inner/outer(us): 0/8 ts:1470836497.140808588 #5 inner/outer(us): 0/6 ts:1470836499.140825168 nmi-total:5 nmi-count:1 #6 inner/outer(us): 9/9 ts:1470836501.140841748
All time is still tracked in microseconds.
The NMI information is only shown when an NMI occurred during the sample.
--- arch/sh/kernel/ftrace.c | 4 ++-- include/linux/ftrace_irq.h | 31 +++++++++++++++++++++++---- kernel/trace/trace_entries.h | 8 +++++-- kernel/trace/trace_hwlat.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace_output.c | 16 +++++++++++++- 5 files changed, 101 insertions(+), 9 deletions(-)
arch/sh/kernel/ftrace.c +2 -2
@@ -139,7 +139,7 @@ static void ftrace_mod_code(void)clear_mod_flag (); } -void ftrace_nmi_enter (void ) +void arch_ftrace_nmi_enter (void ) {if (atomic_inc_return (&nmi_running) &MOD_CODE_WRITE_FLAG ) {smp_rmb ();
@@ -150,7 +150,7 @@ void ftrace_nmi_enter(void)smp_mb (); } -void ftrace_nmi_exit (void ) +void arch_ftrace_nmi_exit (void ) {/* Finish all executions before clearing nmi_running */ smp_mb ();
include/linux/ftrace_irq.h +27 -4
@@ -3,11 +3,34 @@#ifdef CONFIG_FTRACE_NMI_ENTER -extern void ftrace_nmi_enter (void ); -extern void ftrace_nmi_exit (void ); +extern void arch_ftrace_nmi_enter (void ); +extern void arch_ftrace_nmi_exit (void );#else -static inline void ftrace_nmi_enter (void ) { } -static inline void ftrace_nmi_exit (void ) { } +static inline void arch_ftrace_nmi_enter (void ) { } +static inline void arch_ftrace_nmi_exit (void ) { }#endif +#ifdef CONFIG_HWLAT_TRACER +extern bool trace_hwlat_callback_enabled; +extern void trace_hwlat_callback (bool enter); +#endif + +static inline void ftrace_nmi_enter (void ) +{ +#ifdef CONFIG_HWLAT_TRACER +if (trace_hwlat_callback_enabled) +trace_hwlat_callback (true); +#endif +arch_ftrace_nmi_enter (); +} + +static inline void ftrace_nmi_exit (void ) +{ +arch_ftrace_nmi_exit (); +#ifdef CONFIG_HWLAT_TRACER +if (trace_hwlat_callback_enabled) +trace_hwlat_callback (false); +#endif +} +#endif /* _LINUX_FTRACE_IRQ_H */
kernel/trace/trace_entries.h +6 -2
@@ -330,18 +330,22 @@ FTRACE_ENTRY(hwlat, hwlat_entry,F_STRUCT (__field (u64 ,duration )__field ( u64, outer_duration ) +__field ( u64, nmi_total_ts ) __field_struct( struct timespec, timestamp )__field_desc ( long, timestamp, tv_sec )__field_desc ( long, timestamp, tv_nsec ) + __field( unsigned int, nmi_count ) __field( unsigned int, seqnum ) ), - F_printk("cnt:%u\tts:%010lu.%010lu\tinner:%llu\touter:%llu\n", + F_printk("cnt:%u\tts:%010lu.%010lu\tinner:%llu\touter:%llunmi-ts:%llu\tnmi-count:%u\n", __entry->seqnum, __entry->tv_sec, __entry->tv_nsec, __entry->duration, - __entry->outer_duration), + __entry->outer_duration, + __entry->nmi_total_ts, + __entry->nmi_count),FILTER_OTHER );
kernel/trace/trace_hwlat.c +51 -0
99 lines not on this page · raw message
kernel/trace/trace_output.c +15 -1
@@ -1109,13 +1109,27 @@ trace_hwlat_print(struct trace_iterator *iter, int flags,trace_assign_type (field, entry); -trace_seq_printf (s,"#%-5u inner/outer(us): %4llu/%-5llu ts:%ld.%09ld\n" , +trace_seq_printf (s,"#%-5u inner/outer(us): %4llu/%-5llu ts:%ld.%09ld" , field->seqnum, field->duration, field->outer_duration, field->timestamp.tv_sec, field->timestamp.tv_nsec); +if (field->nmi_count) { +/* +* The generic sched_clock() is not NMI safe, thus +* we only record the count and not the time. +*/ +if (!IS_ENABLED (CONFIG_GENERIC_SCHED_CLOCK )) +trace_seq_printf (s," nmi-total:%llu" , + field->nmi_total_ts); +trace_seq_printf (s," nmi-count:%u" , + field->nmi_count); + } + +trace_seq_putc (s,'\n' ); +return trace_handle_return (s); }
Signature · 1 line
2.8.1
Quoted 4 lines · Steven Rostedt
This adds the
PREEMPT_RThwlat detector as a Linux tracer in mainline. In thePREEMPT_RTpatch set, it is a separate entity that is controlled by the debugfs file system. I found that it is better suited as a latency tracer in the tracing directory, as it follows pretty much the
Quoted 8 lines
same paradigm as the other latency tracers that already exist. All I had to add was a
hwlat_detectordirectory that contained a window and width for the period and duration respectively of the test. But the samples would just write to the tracing ring buffer and the max latency would be stored intracing_max_latency, and the threshold can be set by the existingtracing_threshold. The last patch also adds a new feature that would have the kthread migrate after each period to another CPU specified bytracing_cpumask.
Hi!
I tested this patchset in a system which I can cause SMIs. The results are consistent with the latency I see when I run cyclictest in this box and cause SMIs on it. The tracer will be more accurate, as expected. So:
Regarding SMI count, when I added SMI count support to cyclictest I based hardware support check on turbostat's implementation, at
tools/power/x86/turbostat/turbostat.c:probe_nhm_msrs()
It is for user-space, but I think it is a good starting point... Just thinking aloud.
-- Daniel
Quoted 6 lines · Steven Rostedt
Changes since v1:
. Added checks for
CONFIG_GENERIC_SCHED_CLOCK, and if that is set,
onlynmi_countswill be recorded when an NMI is triggered, but not the time in NMI, because the genericsched_clockis not NMI safe. (suggested by Sebastian Andrzej Siewior)
So any of the platforms using GENERIC_SCHED_CLOCK _have_ NMIs ?
In any case, for those you could probably use ktime_get_mono_fast_ns().
Steven Rostedt
maintainerQuoted 8 lines · On Fri, 19 Aug 2016 16:09:28 +0200 Peter Zijlstra <[email protected]> wrote:
Quoted 6 lines · Steven Rostedt
Changes since v1:
. Added checks for
CONFIG_GENERIC_SCHED_CLOCK, and if that is set,
onlynmi_countswill be recorded when an NMI is triggered, but not the time in NMI, because the genericsched_clockis not NMI safe. (suggested by Sebastian Andrzej Siewior)
Quoted 6 lines
So any of the platforms using
GENERIC_SCHED_CLOCK_have_ NMIs ?From what I gather, the answer is no, so I don't think this is an issue.
In any case, for those you could probably use
ktime_get_mono_fast_ns().
Is that safe to call from NMI? Looking into the code I see:
now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr);
where timekeeping_get_ns() has:
timekeeping_get_delta()
which does:
read_seqcount_begin()
which has (eventually):
repeat:
ret = READ_ONCE(s->sequence);
if (unlikely(ret & 1)) {
cpu_relax();
goto repeat;
}
return ret;Which I think could cause a deadlock from an NMI.
-- Steve
Quoted 3 lines · Steven Rostedt
Quoted 1 line
In any case, for those you could probably use
ktime_get_mono_fast_ns().Is that safe to call from NMI?
It should be, we were very careful to make it so. Also read the comment with __ktime_get_fast_ns().
Quoted 6 lines
Looking into the code I see:
now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr);where
timekeeping_get_ns()has:
Quoted 7 lines
timekeeping_get_delta()which does:
read_seqcount_begin()which has (eventually):
That's a bug in CONFIG_DEBUG_TIMEKEEPING, if you look at the !timekeeping_get_delta() it does no such thing.
John, looks like 4ca22c2648f9 ("timekeeping: Add warnings when overflows or underflows are observed") buggered things.
Quoted 20 lines · Peter Zijlstra
Quoted 3 lines · Steven Rostedt
Quoted 1 line
In any case, for those you could probably use
ktime_get_mono_fast_ns().Is that safe to call from NMI?
It should be, we were very careful to make it so. Also read the comment with
__ktime_get_fast_ns().Quoted 12 lines
Looking into the code I see:
now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr);where
timekeeping_get_ns()has:
timekeeping_get_delta()which does:
read_seqcount_begin()
Quoted 7 lines
Quoted 1 line
which has (eventually):
That's a bug in
CONFIG_DEBUG_TIMEKEEPING, if you look at the !timekeeping_get_delta() it does no such thing.John, looks like
4ca22c2648f9("timekeeping: Add warnings when overflows or underflows are observed") buggered things.
Oof. Apologies. I missed that the fast methods called that helper as well.
Any objection to open-coding it for the fast method, like (sorry for the whitespace damage here):
@@ -401,7 +401,10 @@ static __always_inline u64__ktime_get_fast_ns(struct tk_fast *tkf)
do {
seq = raw_read_seqcount_latch(&tkf->seq);
tkr = tkf->base + (seq & 0x01);- now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr);
+ now = ktime_to_ns(tkr->base);
+
+ now += clocksource_delta(tkr->read(tkr->clock),
+ tkr->cycle_last, tkr->mask);
} while (read_seqcount_retry(&tkf->seq, seq));
return now;If not I'll get such a patch sorted, tested and tagged for -stable.
thanks
-john
Quoted 24 lines · John Stultz
Quoted 2 lines · Peter Zijlstra
John, looks like
4ca22c2648f9("timekeeping: Add warnings when overflows or underflows are observed") buggered things.Oof. Apologies. I missed that the fast methods called that helper as well.
Any objection to open-coding it for the fast method, like (sorry for the whitespace damage here):
(quoted diff) +4
-1@@ -401,7 +401,10 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf) do { seq = raw_read_seqcount_latch(&tkf->seq); tkr = tkf->base + (seq & 0x01); - now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr); + now = ktime_to_ns(tkr->base); + + now += clocksource_delta(tkr->read(tkr->clock), + tkr->cycle_last, tkr->mask); } while (read_seqcount_retry(&tkf->seq, seq));return now;
Quoted 1 line
If not I'll get such a patch sorted, tested and tagged for -stable.
Works for me, Thomas?
Quoted 23 lines · Peter Zijlstra
Quoted 22 lines · John Stultz
Quoted 2 lines · Peter Zijlstra
John, looks like
4ca22c2648f9("timekeeping: Add warnings when overflows or underflows are observed") buggered things.Oof. Apologies. I missed that the fast methods called that helper as well.
Any objection to open-coding it for the fast method, like (sorry for the whitespace damage here):
(quoted diff) +4
-1@@ -401,7 +401,10 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf) do { seq = raw_read_seqcount_latch(&tkf->seq); tkr = tkf->base + (seq & 0x01); - now = ktime_to_ns(tkr->base) + timekeeping_get_ns(tkr); + now = ktime_to_ns(tkr->base); + + now += clocksource_delta(tkr->read(tkr->clock), + tkr->cycle_last, tkr->mask); } while (read_seqcount_retry(&tkf->seq, seq));
Quoted 5 lines
Quoted 3 lines
return now;If not I'll get such a patch sorted, tested and tagged for -stable.
Works for me, Thomas?
No objections.