tracing: Updates for 4.9

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next

Head SHA1: 7b2c86250122de316cbab8754050622ead04af39

Dmitry Safonov (1):
tracing/uprobe: Drop isdigit() check in create_trace_uprobe

Jon Masters (1):
tracing: Add documentation for hwlat_detector tracer

Namhyung Kim (2):
function_graph: Handle TRACE_BPUTS in print_graph_comment
ftrace: Access ret_stack->subtime only in the function profiler

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/ftrace.txt         |  10 +-
 Documentation/trace/hwlat_detector.txt |  79 ++++
 arch/sh/kernel/ftrace.c                |   4 +-
 include/linux/ftrace.h                 |   2 +
 include/linux/ftrace_irq.h             |  31 +-
 kernel/trace/Kconfig                   |  35 ++
 kernel/trace/Makefile                  |   1 +
 kernel/trace/ftrace.c                  |   6 +
 kernel/trace/trace.c                   |   2 +-
 kernel/trace/trace.h                   |   3 +
 kernel/trace/trace_entries.h           |  27 ++
 kernel/trace/trace_functions_graph.c   |   6 +-
 kernel/trace/trace_hwlat.c             | 633 +++++++++++++++++++++++++++++++++
 kernel/trace/trace_output.c            |  66 ++++
 kernel/trace/trace_uprobe.c            |   4 -
 15 files changed, 892 insertions(+), 17 deletions(-)
 create mode 100644 Documentation/trace/hwlat_detector.txt
 create mode 100644 kernel/trace/trace_hwlat.c

From: Dmitry Safonov <[email protected]>

It's useless. Before:
[tracing]# echo 'p:test /a:0x0' >> uprobe_events [tracing]# echo 'p:test a:0x0' >> uprobe_events -bash: echo: write error: No such file or directory [tracing]# echo 'p:test 1:0x0' >> uprobe_events -bash: echo: write error: Invalid argument

After:
[tracing]# echo 'p:test 1:0x0' >> uprobe_events -bash: echo: write error: No such file or directory

---
 kernel/trace/trace_uprobe.c | 4 ----
 1 file changed, 4 deletions(-)

index c53485441c88..a74f2d9ff379 100644
@@ -427,10 +427,6 @@ static int create_trace_uprobe(int argc, char **argv)
 		pr_info("Probe point is not specified.\n");
 		return -EINVAL;
 	}
-	if (isdigit(argv[1][0])) {
-		pr_info("probe point must be have a filename.\n");
-		return -EINVAL;
-	}
 	arg = strchr(argv[1], ':');
 	if (!arg) {
 		ret = -EINVAL;

2.8.1

From: Namhyung Kim <[email protected]>

It missed to handle TRACE_BPUTS so messages recorded by trace_bputs() will be shown with symbol info unnecessarily.

You can see it with the trace_printk sample code:

  # cd /sys/kernel/tracing/
  # echo sys_sync > set_graph_function
  # echo 1 > options/sym-offset
  # echo function_graph > current_tracer

Note that the sys_sync filter was there to prevent recording other functions and the sym-offset option was needed since the first message was called from a module init function so kallsyms doesn't have the symbol and omitted in the output.

  # cd ~/build/kernel
  # insmod samples/trace_printk/trace-printk.ko

  # cd -
  # head trace

Before:

# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |

   1)               |  /* 0xffffffffa0002000: This is a static string that will use trace_bputs */
   1)               |  /* This is a dynamic string that will use trace_puts */
   1)               |  /* trace_printk_irq_work+0x5/0x7b [trace_printk]: (irq) This is a static string that will use trace_bputs */
   1)               |  /* (irq) This is a dynamic string that will use trace_puts */
   1)               |  /* (irq) This is a static string that will use trace_bprintk() */
   1)               |  /* (irq) This is a dynamic string that will use trace_printk */

After:

# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |

   1)               |  /* This is a static string that will use trace_bputs */
   1)               |  /* This is a dynamic string that will use trace_puts */
   1)               |  /* (irq) This is a static string that will use trace_bputs */
   1)               |  /* (irq) This is a dynamic string that will use trace_puts */
   1)               |  /* (irq) This is a static string that will use trace_bprintk() */
   1)               |  /* (irq) This is a dynamic string that will use trace_printk */

---
 kernel/trace/trace_functions_graph.c | 5 +++++
 1 file changed, 5 insertions(+)

index 7363ccf79512..e14017c36170 100644
@@ -1120,6 +1120,11 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
 	trace_seq_puts(s, "/* ");
 
 	switch (iter->ent->type) {
+	case TRACE_BPUTS:
+		ret = trace_print_bputs_msg_only(iter);
+		if (ret != TRACE_TYPE_HANDLED)
+			return ret;
+		break;
 	case TRACE_BPRINT:
 		ret = trace_print_bprintk_msg_only(iter);
 		if (ret != TRACE_TYPE_HANDLED)

2.8.1

From: Namhyung Kim <[email protected]>

The subtime is used only for function profiler with function graph tracer enabled. Move the definition of subtime under CONFIG_FUNCTION_PROFILER to reduce the memory usage. Also move the initialization of subtime into the graph entry callback.

---
 Documentation/trace/ftrace.txt       | 10 +++++-----
 include/linux/ftrace.h               |  2 ++
 kernel/trace/ftrace.c                |  6 ++++++
 kernel/trace/trace_functions_graph.c |  1 -
 4 files changed, 13 insertions(+), 6 deletions(-)

index a6b3705e62a6..185c39fea2a0 100644
@@ -858,11 +858,11 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
 	       When enabled, it will account time the task has been
 	       scheduled out as part of the function call.
 
-  graph-time - When running function graph tracer, to include the
-  	       time to call nested functions. When this is not set,
-	       the time reported for the function will only include
-	       the time the function itself executed for, not the time
-	       for functions that it called.
+  graph-time - When running function profiler with function graph tracer,
+	       to include the time to call nested functions. When this is
+	       not set, the time reported for the function will only
+	       include the time the function itself executed for, not the
+	       time for functions that it called.
 
   record-cmd - When any event or tracer is enabled, a hook is enabled
   	       in the sched_switch trace point to fill comm cache

index 7d565afe35d2..1e2b316d6693 100644
@@ -794,7 +794,9 @@ struct ftrace_ret_stack {
 	unsigned long ret;
 	unsigned long func;
 	unsigned long long calltime;
+#ifdef CONFIG_FUNCTION_PROFILER
 	unsigned long long subtime;
+#endif
 	unsigned long fp;
 };
 

index 84752c8e28b5..2050a7652a86 100644
@@ -872,7 +872,13 @@ function_profile_call(unsigned long ip, unsigned long parent_ip,
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 static int profile_graph_entry(struct ftrace_graph_ent *trace)
 {
+	int index = trace->depth;
+
 	function_profile_call(trace->func, 0, NULL, NULL);
+
+	if (index >= 0 && index < FTRACE_RETFUNC_DEPTH)
+		current->ret_stack[index].subtime = 0;
+
 	return 1;
 }
 

index e14017c36170..148c90f1e49b 100644
@@ -170,7 +170,6 @@ ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
 	current->ret_stack[index].ret = ret;
 	current->ret_stack[index].func = func;
 	current->ret_stack[index].calltime = calltime;
-	current->ret_stack[index].subtime = 0;
 	current->ret_stack[index].fp = frame_pointer;
 	*depth = current->curr_ret_stack;
 

2.8.1

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

index f4b86e8ca1e7..72c07c2ffd79 100644
@@ -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

index d0a1617b52b4..992ab9d99f35 100644
@@ -41,6 +41,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

index dade4c9559cc..474cc814e16d 100644
@@ -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);

index f783df416726..1d866b0c1567 100644
@@ -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,

index 5c30efcda5e6..70d47dd99359 100644
@@ -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
+);

2.8.1

From: 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

new file mode 100644
index 000000000000..c02e8ef800cf
@@ -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)

2.8.1

From: "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(+)

index c02e8ef800cf..3207717a0d1a 100644
@@ -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.

2.8.1

From: "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(-)

index 38993e09ef03..deb9eba3a43d 100644
@@ -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();

index dca7bf8cffe2..4ec2c9b205f2 100644
@@ -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 */

index 70d47dd99359..d1cc37e78f99 100644
@@ -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
 );

index d67a562df259..3fc20422c166 100644
@@ -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);
 }
 

2.8.1