hwlat improvements and osnoise/timerlat tracers

This series proposes a set of improvements and new features for the tracing subsystem to facilitate the debugging of low latency deployments.

Currently, hwlat runs on a single CPU at a time, migrating across a set of CPUs in a round-robin fashion. This series improves hwlat to allow hwlat to run on multiple CPUs in parallel, increasing the chances of detecting a hardware latency, at the cost of using more CPU time.

It also proposes a new tracer named osnoise, that aims to help users of isolcpus= (or a similar method) to measure how much noise the OS and the hardware add to the isolated application. The osnoise tracer bases on the hwlat detector code. The difference is that, instead of sampling with interrupts disabled, the osnoise tracer samples the CPU with interrupts and preemption enabled. In this way, the sampling thread will suffer any source of noise from the OS. The detection and classification of the type of noise are then made by observing the entry points of NMIs, IRQs, SoftIRQs, and threads. If none of these sources of noise is detected, the tool associates the noise with the hardware. The tool periodically prints a status, printing the total noise of the period, the max single noise observed, the percentage of CPU available for the task, along with the counters of each source of the noise. To debug the sources of noise, the tracer also adds a set of tracepoints that print any NMI, IRQ, SofIRQ, and thread occurrence. These tracepoints print the starting time and the noise's net duration at the end of the noise. In this way, it reduces the number of tracepoints (one instead of two) and the need to manually accounting the contribution of each noise independently.

Finaly, the timerlat tracer aims to help the preemptive kernel developers to find sources of wakeup latencies of real-time threads. The tracer creates a per-cpu kernel thread with real-time priority. The tracer thread sets a periodic timer to wakeup itself, and goes to sleep waiting for the timer to fire. At the wakeup, the thread then computes a wakeup latency value as the difference between the current time and the absolute time that the timer was set to expire. The tracer prints two lines at every activation. The first is the timer latency observed at the hardirq context before the activation of the thread. The second is the timer latency observed by the thread, which is the same level that cyclictest reports. The ACTIVATION ID field serves to relate the irq execution to its respective thread execution. The tracer is build on top of osnoise tracer, and the osnoise: events can be used to trace the source of interference from NMI, IRQs and other threads. It also enables the capture of the stacktrace at the IRQ context, which helps to identify the code path that can cause thread delay.

Changes from v3:
- Remove /** from comments (Rostedt)
- Support hotplug operations (Rostedt)
- Change the name of ull_config to trace_min_max - and improve patch description (Rostedt)
- Remove leftovers from older versions (Juri Lelli)
- Remove printk from main loop - use trace buffer instead (Rostedt)
- Move the arch specific code to arch/*/kernel/trace.c (Rostedt)
- Improve timerlat documentation (Rostedt)
- Add () around params usage of "value" on __print_ns_to_secs(value) (Rostedt)
- Rename osnoise/stop_tracing* files (Rostedt)
- Reduce the size of the per-cpu data to store stack tracers on timerlat (Rostedt)
- Add osn_* prefix to structures (Rostedt)
- Fix stop tracing to work with trace instances (Rostedt)
- Changing osnoise/cpus restarts the threads accordingly (Rostedt)
- Lots of cosmetics/typos changes (Rostedt)

Changes from v2:
- osnoise sample reports in nanoseconds (as all other osnoise tracepoints) (Bristot)
- Remove divisions from osnoise main loop (Bristot)
- Make the tracers work well when starting via kernel-cmdline (Red Hat's performance team need)
- Rename main/interrupt functions (Bristot)
- Fix timerlat reset (Juri Lelli)
- Fix timerlat start (Juri Lelli)

Changes from v1:
- Remove `` from RST (Corbet)
- Add RST files to the index (Corbet)
- Fix text and typos (Rostedt)
- Remove the cpus from hwlat (Rostedt)
- Remove the disable_migrate/fallback to mode none on hwlat (Rostedt)
- Add a generic way to read/write u64 and use it on hwlat/osnoise/timerlat (Rostedt)
- Make osnoise/timerlat to work properly with trace-cmd/tracer instances (Rostedt)
- osnoise using the tracing_threshold (Rostedt)
- Rearrange tracepoint structure to avoid "holes" (Rostedt)

*** BLURB HERE ***

Daniel Bristot de Oliveira (11):
trace/hwlat: Fix Clark's email
trace/hwlat: Implement the mode config option trace/hwlat: Switch disable_migrate to mode none trace/hwlat: Implement the per-cpu mode
trace/hwlat: Support hotplug operations
trace: Add a generic function to read/write u64 values from tracefs trace/hwlat: Use trace_min_max_param for width and window params trace/hwlat: Remove printk from sampling loop
trace: Add osnoise tracer
trace: Add timerlat tracer
trace/osnoise: Support hotplug operations

Steven Rostedt (1):
trace: Add __print_ns_to_secs() and __print_ns_without_secs() helpers

 Documentation/trace/hwlat_detector.rst  |   13 +-
 Documentation/trace/index.rst           |    2 +
 Documentation/trace/osnoise-tracer.rst  |  152 ++
 Documentation/trace/timerlat-tracer.rst |  181 ++
 arch/x86/kernel/Makefile                |    1 +
 arch/x86/kernel/trace.c                 |  238 +++
 include/linux/ftrace_irq.h              |   13 +
 include/trace/events/osnoise.h          |  142 ++
 include/trace/trace_events.h            |   25 +
 kernel/trace/Kconfig                    |   62 +
 kernel/trace/Makefile                   |    1 +
 kernel/trace/trace.c                    |   92 ++
 kernel/trace/trace.h                    |   29 +-
 kernel/trace/trace_entries.h            |   41 +
 kernel/trace/trace_hwlat.c              |  494 ++++--
 kernel/trace/trace_osnoise.c            | 2004 +++++++++++++++++++++++
 kernel/trace/trace_osnoise.h            |    9 +
 kernel/trace/trace_output.c             |  119 +-
 18 files changed, 3469 insertions(+), 149 deletions(-)
 create mode 100644 Documentation/trace/osnoise-tracer.rst
 create mode 100644 Documentation/trace/timerlat-tracer.rst
 create mode 100644 arch/x86/kernel/trace.c
 create mode 100644 include/trace/events/osnoise.h
 create mode 100644 kernel/trace/trace_osnoise.c
 create mode 100644 kernel/trace/trace_osnoise.h

2.31.1

Clark's email is [email protected]

No functional change.

---
 kernel/trace/trace_hwlat.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 632ef88131a9..0a5635401125 100644
@@ -34,7 +34,7 @@
  * 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]>
+ * Includes useful feedback from Clark Williams <[email protected]>
  *
  */
 #include <linux/kthread.h>

2.31.1

Provides the "mode" config to the hardware latency detector. hwlatd has two different operation modes. The default mode is the "round-robin" one, in which a single hwlatd thread runs, migrating among the allowed CPUs in a "round-robin" fashion. This is the current behavior.

The "none" sets the allowed cpumask for a single hwlatd thread at the startup, but skips the round-robin, letting the scheduler handle the migration.

In preparation to the per-cpu mode.

---
 Documentation/trace/hwlat_detector.rst |  12 +-
 kernel/trace/trace_hwlat.c             | 179 +++++++++++++++++++++++--
 2 files changed, 175 insertions(+), 16 deletions(-)

index 5739349649c8..4d952df0586a 100644
@@ -76,8 +76,12 @@ in /sys/kernel/tracing:
  - 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)
+ - hwlat_detector/mode	- the thread mode
 
-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.
+By default, the hwlat detector's kernel thread will migrate across each CPU
+specified in cpumask at the beginning of a new window, in a round-robin
+fashion. This behavior can be changed by changing the thread mode,
+the available options are:
+
+ - none:        do not force migration
+ - round-robin: migrate across each CPU specified in cpumask [default]

2.31.1

When in the round-robin mode, if the tracer detects a change in the hwlatd thread affinity by an external tool, e.g., taskset, the round-robin logic is disabled. The disable_migrate variable currently tracks this.

With the addition of the "mode" config and the mode "none," the disable_migrate logic is equivalent to switch to the "none" mode.

Hence, instead of using a hidden variable to track this behavior, switch the mode to none, informing the user about this change.

---
 kernel/trace/trace_hwlat.c | 13 +++++--------
 1 file changed, 5 insertions(+), 8 deletions(-)

index 43a436d85a01..bae74b95cf55 100644
@@ -286,7 +286,6 @@ static int get_sample(void)
 }
 
 static struct cpumask save_cpumask;
-static bool disable_migrate;
 
 static void move_to_next_cpu(void)
 {

@@ -294,15 +293,13 @@ static void move_to_next_cpu(void)
 	struct trace_array *tr = hwlat_trace;
 	int next_cpu;
 
-	if (disable_migrate)
-		return;
 	/*
 	 * If for some reason the user modifies the CPU affinity
 	 * of this thread, then stop migrating for the duration
 	 * of the current test.
 	 */
 	if (!cpumask_equal(current_mask, current->cpus_ptr))
-		goto disable;
+		goto change_mode;
 
 	get_online_cpus();
 	cpumask_and(current_mask, cpu_online_mask, tr->tracing_cpumask);

@@ -313,7 +310,7 @@ static void move_to_next_cpu(void)
 		next_cpu = cpumask_first(current_mask);
 
 	if (next_cpu >= nr_cpu_ids) /* Shouldn't happen! */
-		goto disable;
+		goto change_mode;
 
 	cpumask_clear(current_mask);
 	cpumask_set_cpu(next_cpu, current_mask);

@@ -321,8 +318,9 @@ static void move_to_next_cpu(void)
 	sched_setaffinity(0, current_mask);
 	return;
 
- disable:
-	disable_migrate = true;
+ change_mode:
+	hwlat_data.thread_mode = MODE_NONE;
+	pr_info(BANNER "cpumask changed while in round-robin mode, switching to mode none\n");
 }
 
 /*

@@ -744,7 +742,6 @@ static int hwlat_tracer_init(struct trace_array *tr)
 
 	hwlat_trace = tr;
 
-	disable_migrate = false;
 	hwlat_data.count = 0;
 	tr->max_latency = 0;
 	save_tracing_thresh = tracing_thresh;

2.31.1

Implements the per-cpu mode in which a sampling thread is created for each cpu in the "cpus" (and tracing_mask).

The per-cpu mode has the potention to speed up the hwlat detection by running on multiple CPUs at the same time, at the cost of higher cpu usage with irqs disabled. Use with care.

---
 Documentation/trace/hwlat_detector.rst |   3 +-
 kernel/trace/trace_hwlat.c             | 188 ++++++++++++++++++++-----
 2 files changed, 153 insertions(+), 38 deletions(-)

index 4d952df0586a..8881ce919553 100644
@@ -78,10 +78,11 @@ in /sys/kernel/tracing:
  - hwlat_detector/window	- amount of time between (width) runs (usecs)
  - hwlat_detector/mode	- the thread mode
 
-By default, the hwlat detector's kernel thread will migrate across each CPU
+By default, one hwlat detector kernel thread will migrate across each CPU
 specified in cpumask at the beginning of a new window, in a round-robin
 fashion. This behavior can be changed by changing the thread mode,
 the available options are:
 
  - none:        do not force migration
  - round-robin: migrate across each CPU specified in cpumask [default]
+ - per-cpu:     create one thread for each cpu in tracing_cpumask

2.31.1

Enable and disable hwlat thread during cpu hotplug online and offline operations, respectivelly.

---
 kernel/trace/trace.c       |  6 ++++++
 kernel/trace/trace_hwlat.c | 34 ++++++++++++++++++++++++++++++++++
 2 files changed, 40 insertions(+)

index 9299057feb56..c094865e2f71 100644
@@ -5064,7 +5064,13 @@ int tracing_set_cpumask(struct trace_array *tr,
 	arch_spin_unlock(&tr->max_lock);
 	local_irq_enable();
 
+	/*
+	 * tracing_cpumask is read by tracers that support CPU
+	 * hotplug.
+	 */
+	get_online_cpus();
 	cpumask_copy(tr->tracing_cpumask, tracing_cpumask_new);
+	put_online_cpus();
 
 	return 0;
 }

index 6c6918e86087..9fcfd588c4f6 100644
@@ -490,6 +490,35 @@ static int start_cpu_kthread(unsigned int cpu)
 	return 0;
 }
 
+/*
+ * hwlat_cpu_init - CPU hotplug online callback function
+ */
+static int hwlat_cpu_init(unsigned int cpu)
+{
+	struct trace_array *tr = hwlat_trace;
+
+	if (!hwlat_busy)
+		return 0;
+
+	if (!cpumask_test_cpu(cpu, tr->tracing_cpumask))
+		return 0;
+
+	return start_cpu_kthread(cpu);
+}
+
+/*
+ * hwlat_cpu_die - CPU hotplug offline callback function
+ */
+static int hwlat_cpu_die(unsigned int cpu)
+{
+	if (!hwlat_busy)
+		return 0;
+
+	stop_cpu_kthread(cpu);
+
+	return 0;
+}
+
 /*
  * start_per_cpu_kthreads - Kick off the hardware latency sampling/detector kthreads
  *

@@ -903,6 +932,11 @@ __init static int init_hwlat_tracer(void)
 	if (ret)
 		return ret;
 
+	ret = cpuhp_setup_state(CPUHP_AP_ONLINE_DYN, "trace/hwlat:online",
+				hwlat_cpu_init, hwlat_cpu_die);
+	if (ret < 0)
+		pr_warn(BANNER "Error to init cpu hotplug support\n");
+
 	init_tracefs();
 
 	return 0;

2.31.1

And of course, because get_online_cpus() is called within trace_types_lock, doing this check is going to cause a lock inversion.

The only thing I could think of is to wake up a worker thread to do the work. That is, this just wakes the worker thread, then the worker grabs the trace_types_lock, iterates through the cpu mask of expect running threads, and then starts or kills them depending on the hwlat_busy value.

-- Steve

Yep! I tried to take the trace_type_lock here, and got the lockdep info about this problem.

So, it will not wait for the kworker to run?

-- Daniel

What wont wait?

-- Steve

For example, at the shutdown, should the hotplug callback wait for the workqueue to run & kill the thread, or not?

-- Daniel

Doing that won't help the deadlock situation.

	CPU 1			CPU 2
	-----			-----
    Start shutdown
    down online_cpus()

			   mutex_lock(trace_types_lock);
			   get_online_cpus()
			   [BLOCK]

    wake_up_thread;
    [schedule worker]

    mutex_lock(trace_types_lock);

[ DEADLOCK ]

Make all access to save_cpumask and hwlat_per_cpu_data inside the get_online_cpus() protection. (like in move_to_next_cpu(), start_single_thread() expand the get_online_cpus()).

Then in the cpu going down case, we can simply kill the thread and update the save_cpumask, as it will be protected by the get_online_cpus() code.

That is, don't even check if hwlat_busy is set or not. Just simply do:

CPU_DOWN:

	stop_cpu_kthead(cpu);

That will stop the kthread if it is running. But we should update that function to also set per_cpu(hwlat_per_cpu_data).kthread = NULL; Like stop_single_kthread() does.

But for CPU_UP, we should do the work via a worker thread.

CPU_UP:

	schedule_work_on(&update_kthreads, cpu);

Which in the work function for that update_kthreads work queue:

	mutex_lock(&trace_types_lock);
	if (!hwlat_busy || hwlat_data.thread_mode != MODE_PER_CPU)
		goto out_unlock;

	get_online_cpus();
	if (!this_cpu(hwlat_per_cpu_data).kthread)
		start_per_cpu_kthread(smp_processor_id());
	put_online_cpus();

out_unlock:

	mutex_unlock(&trace_types_lock);

Or something like that.

-- Steve

yep, that is why I asked... :-(

It works!

I will send a v5 with all the fixes requested, including this one.

Thanks Steven!
-- Daniel

The hwlat detector and (in preparation for) the osnoise/timerlat tracers have a set of u64 parameters that the user can read/write via tracefs. For instance, we have hwlat_detector's window and width.

To reduce the code duplication, hwlat's window and width share the same read function. However, they do not share the write functions because they do different parameter checks. For instance, the width needs to be smaller than the window, while the window needs to be larger than the window. The same pattern repeats on osnoise/timerlat, and a large portion of the code was devoted to the write function.

Despite having different checks, the write functions have the same structure:

read a user-space buffer
take the lock that protects the value check for minimum and maximum acceptable values
save the value
release the lock
return success or error

To reduce the code duplication also in the write functions, this patch provides a generic read and write implementation for u64 values that need to be within some minimum and/or maximum parameters, while (potentially) being protected by a lock.

To use this interface, the structure trace_min_max_param needs to be filled:

 struct trace_min_max_param {
         struct mutex    *lock;
         u64             *val;
         u64             *min;
         u64             *max;

};

The desired value is stored on the variable pointed by *val. If *min points to a minimum acceptable value, it will be checked during the write operation. Likewise, if *max points to a maximum allowable value, it will be checked during the write operation. Finally, if *lock points to a mutex, it will be taken at the beginning of the operation and released at the end.

The definition of a trace_min_max_param needs to passed as the (private) *data for tracefs_create_file(), and the trace_min_max_fops (added by this patch) as the *fops file_operations.

---
 kernel/trace/trace.c | 86 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h | 18 ++++++++++
 2 files changed, 104 insertions(+)

index c094865e2f71..e03343e8f332 100644
@@ -7545,6 +7545,92 @@ static const struct file_operations snapshot_raw_fops = {
 
 #endif /* CONFIG_TRACER_SNAPSHOT */
 
+/*
+ * trace_min_max_write - Write a u64 value to a trace_min_max_param struct
+ * @filp: The active open file structure
+ * @ubuf: The userspace provided buffer to read value into
+ * @cnt: The maximum number of bytes to read
+ * @ppos: The current "file" position
+ *
+ * This function implements the write interface for a struct trace_min_max_param.
+ * The filp->private_data must point to a trace_min_max_param structure that
+ * defines where to write the value, the min and the max acceptable values,
+ * and a lock to protect the write.
+ */
+static ssize_t
+trace_min_max_write(struct file *filp, const char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+	struct trace_min_max_param *param = filp->private_data;
+	u64 val;
+	int err;
+
+	if (!param)
+		return -EFAULT;
+
+	err = kstrtoull_from_user(ubuf, cnt, 10, &val);
+	if (err)
+		return err;
+
+	if (param->lock)
+		mutex_lock(param->lock);
+
+	if (param->min && val < *param->min)
+		err = -EINVAL;
+
+	if (param->max && val > *param->max)
+		err = -EINVAL;
+
+	if (!err)
+		*param->val = val;
+
+	if (param->lock)
+		mutex_unlock(param->lock);
+
+	if (err)
+		return err;
+
+	return cnt;
+}
+
+/*
+ * trace_min_max_read - Read a u64 value from a trace_min_max_param struct
+ * @filp: The active open file structure
+ * @ubuf: The userspace provided buffer to read value into
+ * @cnt: The maximum number of bytes to read
+ * @ppos: The current "file" position
+ *
+ * This function implements the read interface for a struct trace_min_max_param.
+ * The filp->private_data must point to a trace_min_max_param struct with valid
+ * data.
+ */
+static ssize_t
+trace_min_max_read(struct file *filp, char __user *ubuf, size_t cnt,
+		      loff_t *ppos)
+{
+	struct trace_min_max_param *param = filp->private_data;
+	char buf[ULL_STR_SIZE];
+	u64 val;
+        int len;
+
+        if (!param)
+                return -EFAULT;
+
+	val = *param->val;
+
+        if (cnt > sizeof(buf))
+                cnt = sizeof(buf);
+
+        len = snprintf(buf, sizeof(buf), "%llu\n", val);
+
+        return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
+}
+
+const struct file_operations trace_min_max_fops = {
+	.open		= tracing_open_generic,
+	.read		= trace_min_max_read,
+	.write		= trace_min_max_write,
+};
+
 #define TRACING_LOG_ERRS_MAX	8
 #define TRACING_LOG_LOC_MAX	128
 

index cd80d046c7a5..7bfb50461d5e 100644
@@ -1952,4 +1952,22 @@ static inline bool is_good_name(const char *name)
 	return true;
 }
 
+/*
+ * This is a generic way to read and write a u64 value from a file in tracefs.
+ *
+ * The value is stored on the variable pointed by *val. The value needs
+ * to be at least *min and at most *max. The write is protected by an
+ * existing *lock.
+ */
+struct trace_min_max_param {
+	struct mutex	*lock;
+	u64		*val;
+	u64		*min;
+	u64		*max;
+};
+
+#define ULL_STR_SIZE		22	/* 20 digits max */
+
+extern const struct file_operations trace_min_max_fops;
+
 #endif /* _LINUX_KERNEL_TRACE_H */

2.31.1

<talking to myself>
daniel daniel daniel.... after all these years...
</talking to myself>

Sorry... it was only in this patch.

I will do that!

-- Daniel

Use the trace_min_max_param to reduce code duplication.

No functional change.

---
 kernel/trace/trace_hwlat.c | 145 ++++++-------------------------------
 1 file changed, 24 insertions(+), 121 deletions(-)

index 9fcfd588c4f6..0ab6acf6ae9a 100644
@@ -556,115 +556,6 @@ static int start_per_cpu_kthreads(struct trace_array *tr)
 	return retval;
 }
 
-/*
- * hwlat_read - Wrapper read function for reading both window and width
- * @filp: The active open file structure
- * @ubuf: The userspace provided buffer to read value into
- * @cnt: The maximum number of bytes to read
- * @ppos: The current "file" position
- *
- * This function provides a generic read implementation for the global state
- * "hwlat_data" structure filesystem entries.
- */
-static ssize_t hwlat_read(struct file *filp, char __user *ubuf,
-			  size_t cnt, loff_t *ppos)
-{
-	char buf[U64STR_SIZE];
-	u64 *entry = filp->private_data;
-	u64 val;
-	int len;
-
-	if (!entry)
-		return -EFAULT;
-
-	if (cnt > sizeof(buf))
-		cnt = sizeof(buf);
-
-	val = *entry;
-
-	len = snprintf(buf, sizeof(buf), "%llu\n", val);
-
-	return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
-}
-
-/**
- * hwlat_width_write - Write function for "width" entry
- * @filp: The active open file structure
- * @ubuf: The user buffer that contains the value to write
- * @cnt: The maximum number of bytes to write to "file"
- * @ppos: The current position in @file
- *
- * This function provides a write implementation for the "width" interface
- * to the hardware latency detector. It can be used to configure
- * for how many us of the total window us we will actively sample for any
- * hardware-induced latency periods. Obviously, it is not possible to
- * sample constantly and have the system respond to a sample reader, or,
- * worse, without having the system appear to have gone out to lunch. It
- * is enforced that width is less that the total window size.
- */
-static ssize_t
-hwlat_width_write(struct file *filp, const char __user *ubuf,
-		  size_t cnt, loff_t *ppos)
-{
-	u64 val;
-	int err;
-
-	err = kstrtoull_from_user(ubuf, cnt, 10, &val);
-	if (err)
-		return err;
-
-	mutex_lock(&hwlat_data.lock);
-	if (val < hwlat_data.sample_window)
-		hwlat_data.sample_width = val;
-	else
-		err = -EINVAL;
-	mutex_unlock(&hwlat_data.lock);
-
-	if (err)
-		return err;
-
-	return cnt;
-}
-
-/**
- * hwlat_window_write - Write function for "window" entry
- * @filp: The active open file structure
- * @ubuf: The user buffer that contains the value to write
- * @cnt: The maximum number of bytes to write to "file"
- * @ppos: The current position in @file
- *
- * This function provides a write implementation for the "window" interface
- * to the hardware latency detector. The window is the total time
- * in us that will be considered one sample period. Conceptually, windows
- * occur back-to-back and contain a sample width period during which
- * actual sampling occurs. Can be used to write a new total window size. It
- * is enforced that any value written must be greater than the sample width
- * size, or an error results.
- */
-static ssize_t
-hwlat_window_write(struct file *filp, const char __user *ubuf,
-		   size_t cnt, loff_t *ppos)
-{
-	u64 val;
-	int err;
-
-	err = kstrtoull_from_user(ubuf, cnt, 10, &val);
-	if (err)
-		return err;
-
-	mutex_lock(&hwlat_data.lock);
-	if (hwlat_data.sample_width < val)
-		hwlat_data.sample_window = val;
-	else
-		err = -EINVAL;
-	mutex_unlock(&hwlat_data.lock);
-
-	if (err)
-		return err;
-
-	return cnt;
-}
-
 static void *s_mode_start(struct seq_file *s, loff_t *pos)
 {
 	int mode = *pos;

@@ -789,16 +680,28 @@ static ssize_t hwlat_mode_write(struct file *filp, const char __user *ubuf,
 	return ret;
 }
 
-static const struct file_operations width_fops = {
-	.open		= tracing_open_generic,
-	.read		= hwlat_read,
-	.write		= hwlat_width_write,
+/*
+ * The width parameter is read/write using the generic trace_min_max_param
+ * method. The *val is protected by the hwlat_data lock and is upper
+ * bounded by the window parameter.
+ */
+static struct trace_min_max_param hwlat_width = {
+	.lock		= &hwlat_data.lock,
+	.val		= &hwlat_data.sample_width,
+	.max		= &hwlat_data.sample_window,
+	.min		= NULL,
 };
 
-static const struct file_operations window_fops = {
-	.open		= tracing_open_generic,
-	.read		= hwlat_read,
-	.write		= hwlat_window_write,
+/*
+ * The window parameter is read/write using the generic trace_min_max_param
+ * method. The *val is protected by the hwlat_data lock and is lower
+ * bounded by the width parameter.
+ */
+static struct trace_min_max_param hwlat_window = {
+	.lock		= &hwlat_data.lock,
+	.val		= &hwlat_data.sample_window,
+	.max		= NULL,
+	.min		= &hwlat_data.sample_width,
 };
 
 static const struct file_operations thread_mode_fops = {

@@ -831,15 +734,15 @@ static int init_tracefs(void)
 
 	hwlat_sample_window = tracefs_create_file("window", 0640,
 						  top_dir,
-						  &hwlat_data.sample_window,
-						  &window_fops);
+						  &hwlat_window,
+						  &trace_min_max_fops);
 	if (!hwlat_sample_window)
 		goto err;
 
 	hwlat_sample_width = tracefs_create_file("width", 0644,
 						 top_dir,
-						 &hwlat_data.sample_width,
-						 &width_fops);
+						 &hwlat_width,
+						 &trace_min_max_fops);
 	if (!hwlat_sample_width)
 		goto err;
 

2.31.1

hwlat has some time operation checks on the sample loop, and it is currently using pr_err (printk) to report them. The problem is that this can lead the system to an unresponsible state due to an overflow of printk messages. This problem can be mitigated by writing the error message to the trace buffer.

Remove the printk messages from the sampling loop, switching the to messages in the trace buffer.

No functional change.

---
 kernel/trace/trace_hwlat.c | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)

index 0ab6acf6ae9a..86e8541d4331 100644
@@ -182,6 +182,15 @@ void trace_hwlat_callback(bool enter)
 		kdata->nmi_count++;
 }
 
+/*
+ * hwlat_err - report a hwlat error.
+ */
+#define hwlat_err(msg) ({							\
+	struct trace_array *tr = hwlat_trace;					\
+										\
+	trace_array_printk_buf(tr->array_buffer.buffer, _THIS_IP_, msg);	\
+})
+
 /**
  * get_sample - sample the CPU TSC and look for likely hardware latencies
  *

@@ -225,7 +234,7 @@ static int get_sample(void)
 			outer_diff = time_to_us(time_sub(t1, last_t2));
 			/* This shouldn't happen */
 			if (outer_diff < 0) {
-				pr_err(BANNER "time running backwards\n");
+				hwlat_err(BANNER "time running backwards\n");
 				goto out;
 			}
 			if (outer_diff > outer_sample)

@@ -237,7 +246,7 @@ static int get_sample(void)
 
 		/* Check for possible overflows */
 		if (total < last_total) {
-			pr_err("Time total overflowed\n");
+			hwlat_err("Time total overflowed\n");
 			break;
 		}
 		last_total = total;

@@ -253,7 +262,7 @@ static int get_sample(void)
 
 		/* This shouldn't happen */
 		if (diff < 0) {
-			pr_err(BANNER "time running backwards\n");
+			hwlat_err(BANNER "time running backwards\n");
 			goto out;
 		}
 

2.31.1

From: Steven Rostedt <[email protected]>

To have nanosecond output displayed in a more human readable format, its nicer to convert it to a seconds format (XXX.YYYYYYYYY). The problem is that to do so, the numbers must be divided by NSEC_PER_SEC, and moded too. But as these numbers are 64 bit, this can not be done simply with '/' and '%' operators, but must use do_div() instead.

Instead of performing the expensive do_div() in the hot path of the tracepoint, it is more efficient to perform it during the output phase. But passing in do_div() can confuse the parser, and do_div() doesn't work exactly like a normal C function. It modifies the number in place, and we don't want to modify the actual values in the ring buffer.

Two helper functions are now created:

__print_ns_to_secs() and __print_ns_without_secs()

They both take a value of nanoseconds, and the former will return that number divided by NSEC_PER_SEC, and the latter will mod it with NSEC_PER_SEC giving a way to print a nice human readable format:

__print_fmt("time=%llu.%09u",

	__print_ns_to_secs(REC->nsec_val),
	__print_ns_without_secs(REC->nsec_val))

---
 include/trace/trace_events.h | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

index 8268bf747d6f..acc17194c160 100644
@@ -358,6 +358,21 @@ TRACE_MAKE_SYSTEM_STR();
 	trace_print_hex_dump_seq(p, prefix_str, prefix_type,		\
 				 rowsize, groupsize, buf, len, ascii)
 
+#undef __print_ns_to_secs
+#define __print_ns_to_secs(value)			\
+	({						\
+		u64 ____val = (u64)(value);		\
+		do_div(____val, NSEC_PER_SEC);		\
+		____val;				\
+	})
+
+#undef __print_ns_without_secs
+#define __print_ns_without_secs(value)			\
+	({						\
+		u64 ____val = (u64)(value);		\
+		(u32) do_div(____val, NSEC_PER_SEC);	\
+	})
+
 #undef DECLARE_EVENT_CLASS
 #define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
 static notrace enum print_line_t					\

@@ -736,6 +751,16 @@ static inline void ftrace_test_probe_##call(void)			\
 #undef __print_array
 #undef __print_hex_dump
 
+/*
+ * The below is not executed in the kernel. It is only what is
+ * displayed in the print format for userspace to parse.
+ */
+#undef __print_ns_to_secs
+#define __print_ns_to_secs(val) (val) / 1000000000UL
+
+#undef __print_ns_without_secs
+#define __print_ns_without_secs(val) (val) % 1000000000UL
+
 #undef TP_printk
 #define TP_printk(fmt, args...) "\"" fmt "\", "  __stringify(args)
 

2.31.1

In the context of high-performance computing (HPC), the Operating System Noise (*osnoise*) refers to the interference experienced by an application due to activities inside the operating system. In the context of Linux, NMIs, IRQs, SoftIRQs, and any other system thread can cause noise to the system. Moreover, hardware-related jobs can also cause noise, for example, via SMIs.

The osnoise tracer leverages the hwlat_detector by running a similar loop with preemption, SoftIRQs and IRQs enabled, thus allowing all the sources of *osnoise* during its execution. Using the same approach of hwlat, osnoise takes note of the entry and exit point of any source of interferences, increasing a per-cpu interference counter. The osnoise tracer also saves an interference counter for each source of interference. The interference counter for NMI, IRQs, SoftIRQs, and threads is increased anytime the tool observes these interferences' entry events. When a noise happens without any interference from the operating system level, the hardware noise counter increases, pointing to a hardware-related noise. In this way, osnoise can account for any source of interference. At the end of the period, the osnoise tracer prints the sum of all noise, the max single noise, the percentage of CPU available for the thread, and the counters for the noise sources.

Usage

Write the ASCII text "osnoise" into the current_tracer file of the tracing system (generally mounted at /sys/kernel/tracing).

For example::

[root@f32 ~]# cd /sys/kernel/tracing/ [root@f32 tracing]# echo osnoise > current_tracer

It is possible to follow the trace by reading the trace trace file::

        [root@f32 tracing]# cat trace
        # tracer: osnoise
        #
        #                                _-----=> irqs-off
        #                               / _----=> need-resched
        #                              | / _---=> hardirq/softirq
        #                              || / _--=> preempt-depth                            MAX
        #                              || /                                             SINGLE     Interference counters:
        #                              ||||               RUNTIME      NOISE   % OF CPU  NOISE    +-----------------------------+
        #           TASK-PID      CPU# ||||   TIMESTAMP    IN US       IN US  AVAILABLE  IN US     HW    NMI    IRQ   SIRQ THREAD
        #              | |         |   ||||      |           |             |    |            |      |      |      |      |      |
                   <...>-859     [000] ....    81.637220: 1000000        190  99.98100       9     18      0   1007     18      1
                   <...>-860     [001] ....    81.638154: 1000000        656  99.93440      74     23      0   1006     16      3
                   <...>-861     [002] ....    81.638193: 1000000       5675  99.43250     202      6      0   1013     25     21
                   <...>-862     [003] ....    81.638242: 1000000        125  99.98750      45      1      0   1011     23      0
                   <...>-863     [004] ....    81.638260: 1000000       1721  99.82790     168      7      0   1002     49     41
                   <...>-864     [005] ....    81.638286: 1000000        263  99.97370      57      6      0   1006     26      2
                   <...>-865     [006] ....    81.638302: 1000000        109  99.98910      21      3      0   1006     18      1
                   <...>-866     [007] ....    81.638326: 1000000       7816  99.21840     107      8      0   1016     39     19

In addition to the regular trace fields (from TASK-PID to TIMESTAMP), the tracer prints a message at the end of each period for each CPU that is running an osnoise/CPU thread. The osnoise specific fields report:

- The RUNTIME IN USE reports the amount of time in microseconds that the osnoise thread kept looping reading the time.
- The NOISE IN US reports the sum of noise in microseconds observed by the osnoise tracer during the associated runtime.
- The % OF CPU AVAILABLE reports the percentage of CPU available for the osnoise thread during the runtime window.
- The MAX SINGLE NOISE IN US reports the maximum single noise observed during the runtime window.
- The Interference counters display how many each of the respective interference happened during the runtime window.

Note that the example above shows a high number of HW noise samples. The reason being is that this sample was taken on a virtual machine, and the host interference is detected as a hardware interference.

Tracer options

The tracer has a set of options inside the osnoise directory, they are:

- osnoise/cpus: CPUs at which a osnoise thread will execute.
- osnoise/period_us: the period of the osnoise thread.
- osnoise/runtime_us: how long an osnoise thread will look for noise.
- osnoise/stop_tracing_us: stop the system tracing if a single noise higher than the configured value happens. Writing 0 disables this option.
- osnoise/stop_tracing_total_us: stop the system tracing if total noise higher than the configured value happens. Writing 0 disables this option.
- tracing_threshold: the minimum delta between two time() reads to be considered as noise, in us. When set to 0, the minimum valid value will be used, which is currently 1 us.

Additional Tracing

In addition to the tracer, a set of tracepoints were added to facilitate the identification of the osnoise source.

- osnoise:sample_threshold: printed anytime a noise is higher than the configurable tolerance_ns.
- osnoise:nmi_noise: noise from NMI, including the duration.
- osnoise:irq_noise: noise from an IRQ, including the duration.
- osnoise:softirq_noise: noise from a SoftIRQ, including the duration.
- osnoise:thread_noise: noise from a thread, including the duration.

Note that all the values are *net values*. For example, if while osnoise is running, another thread preempts the osnoise thread, it will start a thread_noise duration at the start. Then, an IRQ takes place, preempting the thread_noise, starting a irq_noise. When the IRQ ends its execution, it will compute its duration, and this duration will be subtracted from the thread_noise, in such a way as to avoid the double accounting of the IRQ execution. This logic is valid for all sources of noise.

Here is one example of the usage of these tracepoints::

       osnoise/8-961     [008] d.h.  5789.857532: irq_noise: local_timer:236 start 5789.857529929 duration 1845 ns
       osnoise/8-961     [008] dNh.  5789.858408: irq_noise: local_timer:236 start 5789.858404871 duration 2848 ns
     migration/8-54      [008] d...  5789.858413: thread_noise: migration/8:54 start 5789.858409300 duration 3068 ns
       osnoise/8-961     [008] ....  5789.858413: sample_threshold: start 5789.858404555 duration 8723 ns interferences 2

In this example, a noise sample of 8 microseconds was reported in the last line, pointing to two interferences. Looking backward in the trace, the two previous entries were about the migration thread running after a timer IRQ execution. The first event is not part of the noise because it took place one millisecond before.

It is worth noticing that the sum of the duration reported in the tracepoints is smaller than eight us reported in the sample_threshold. The reason roots in the overhead of the entry and exit code that happens before and after any interference execution. This justifies the dual
approach: measuring thread and tracing.

---
 Documentation/trace/index.rst          |    1 +
 Documentation/trace/osnoise-tracer.rst |  152 +++
 arch/x86/kernel/Makefile               |    1 +
 arch/x86/kernel/trace.c                |  238 +++++
 include/linux/ftrace_irq.h             |   13 +
 include/trace/events/osnoise.h         |  142 +++
 kernel/trace/Kconfig                   |   34 +
 kernel/trace/Makefile                  |    1 +
 kernel/trace/trace.h                   |    9 +-
 kernel/trace/trace_entries.h           |   25 +
 kernel/trace/trace_osnoise.c           | 1367 ++++++++++++++++++++++++
 kernel/trace/trace_osnoise.h           |    9 +
 kernel/trace/trace_output.c            |   72 +-
 13 files changed, 2060 insertions(+), 4 deletions(-)
 create mode 100644 Documentation/trace/osnoise-tracer.rst
 create mode 100644 arch/x86/kernel/trace.c
 create mode 100644 include/trace/events/osnoise.h
 create mode 100644 kernel/trace/trace_osnoise.c
 create mode 100644 kernel/trace/trace_osnoise.h

index f634b36fd3aa..608107b27cc0 100644
@@ -23,6 +23,7 @@ Linux Tracing Technologies
    histogram-design
    boottime-trace
    hwlat_detector
+   osnoise-tracer
    intel_th
    ring-buffer-design
    stm

index 0f66682ac02a..3e625c61f008 100644
@@ -102,6 +102,7 @@ obj-$(CONFIG_FUNCTION_TRACER)	+= ftrace_$(BITS).o
 obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o
 obj-$(CONFIG_FTRACE_SYSCALLS)	+= ftrace.o
 obj-$(CONFIG_X86_TSC)		+= trace_clock.o
+obj-$(CONFIG_TRACING)		+= trace.o
 obj-$(CONFIG_CRASH_CORE)	+= crash_core_$(BITS).o
 obj-$(CONFIG_KEXEC_CORE)	+= machine_kexec_$(BITS).o
 obj-$(CONFIG_KEXEC_CORE)	+= relocate_kernel_$(BITS).o crash.o

index 0abd9a1d2852..f6faa31289ba 100644
@@ -7,12 +7,21 @@ extern bool trace_hwlat_callback_enabled;
 extern void trace_hwlat_callback(bool enter);
 #endif
 
+#ifdef CONFIG_OSNOISE_TRACER
+extern bool trace_osnoise_callback_enabled;
+extern void trace_osnoise_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
+#ifdef CONFIG_OSNOISE_TRACER
+	if (trace_osnoise_callback_enabled)
+		trace_osnoise_callback(true);
+#endif
 }
 
 static inline void ftrace_nmi_exit(void)

@@ -21,6 +30,10 @@ static inline void ftrace_nmi_exit(void)
 	if (trace_hwlat_callback_enabled)
 		trace_hwlat_callback(false);
 #endif
+#ifdef CONFIG_OSNOISE_TRACER
+	if (trace_osnoise_callback_enabled)
+		trace_osnoise_callback(false);
+#endif
 }
 
 #endif /* _LINUX_FTRACE_IRQ_H */

index 7fa82778c3e6..41582ae4682b 100644
@@ -356,6 +356,40 @@ config HWLAT_TRACER
 	 file. Every time a latency is greater than tracing_thresh, it will
 	 be recorded into the ring buffer.
 
+config OSNOISE_TRACER
+	bool "OS Noise tracer"
+	select GENERIC_TRACER
+	help
+	  In the context of high-performance computing (HPC), the Operating
+	  System Noise (osnoise) refers to the interference experienced by an
+	  application due to activities inside the operating system. In the
+	  context of Linux, NMIs, IRQs, SoftIRQs, and any other system thread
+	  can cause noise to the system. Moreover, hardware-related jobs can
+	  also cause noise, for example, via SMIs.
+
+	  The osnoise tracer leverages the hwlat_detector by running a similar
+	  loop with preemption, SoftIRQs and IRQs enabled, thus allowing all
+	  the sources of osnoise during its execution. The osnoise tracer takes
+	  note of the entry and exit point of any source of interferences,
+	  increasing a per-cpu interference counter. It saves an interference
+	  counter for each source of interference. The interference counter for
+	  NMI, IRQs, SoftIRQs, and threads is increased anytime the tool
+	  observes these interferences' entry events. When a noise happens
+	  without any interference from the operating system level, the
+	  hardware noise counter increases, pointing to a hardware-related
+	  noise. In this way, osnoise can account for any source of
+	  interference. At the end of the period, the osnoise tracer prints
+	  the sum of all noise, the max single noise, the percentage of CPU
+	  available for the thread, and the counters for the noise sources.
+
+	  In addition to the tracer, a set of tracepoints were added to
+	  facilitate the identification of the osnoise source.
+
+	  The output will appear in the trace and trace_pipe files.
+
+	  To enable this tracer, echo in "osnoise" into the current_tracer
+          file.
+
 config MMIOTRACE
 	bool "Memory mapped IO tracing"
 	depends on HAVE_MMIOTRACE_SUPPORT && PCI

index b28d3e5013cd..b1c47ccf4f73 100644
@@ -58,6 +58,7 @@ 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_OSNOISE_TRACER) += trace_osnoise.o
 obj-$(CONFIG_NOP_TRACER) += trace_nop.o
 obj-$(CONFIG_STACK_TRACER) += trace_stack.o
 obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o

index 7bfb50461d5e..760129d5f576 100644
@@ -44,6 +44,7 @@ enum trace_type {
 	TRACE_BLK,
 	TRACE_BPUTS,
 	TRACE_HWLAT,
+	TRACE_OSNOISE,
 	TRACE_RAW_DATA,
 	TRACE_FUNC_REPEATS,
 

@@ -297,7 +298,8 @@ struct trace_array {
 	struct array_buffer	max_buffer;
 	bool			allocated_snapshot;
 #endif
-#if defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)
+#if defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER) \
+	|| defined(CONFIG_OSNOISE_TRACER)
 	unsigned long		max_latency;
 #ifdef CONFIG_FSNOTIFY
 	struct dentry		*d_max_latency;

@@ -445,6 +447,7 @@ extern void __ftrace_bad_type(void);
 		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 osnoise_entry, TRACE_OSNOISE);\
 		IF_ASSIGN(var, ent, struct raw_data_entry, TRACE_RAW_DATA);\
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_rw,		\
 			  TRACE_MMIO_RW);				\

@@ -675,8 +678,8 @@ void update_max_tr_single(struct trace_array *tr,
 			  struct task_struct *tsk, int cpu);
 #endif /* CONFIG_TRACER_MAX_TRACE */
 
-#if (defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)) && \
-	defined(CONFIG_FSNOTIFY)
+#if (defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)) \
+	|| defined(CONFIG_OSNOISE_TRACER) && defined(CONFIG_FSNOTIFY)
 
 void latency_fsnotify(struct trace_array *tr);
 

index 251c819cf0c5..158c0984b59b 100644
@@ -360,3 +360,28 @@ FTRACE_ENTRY(func_repeats, func_repeats_entry,
 		 __entry->count,
 		 FUNC_REPEATS_GET_DELTA_TS(__entry))
 );
+
+FTRACE_ENTRY(osnoise, osnoise_entry,
+
+	TRACE_OSNOISE,
+
+	F_STRUCT(
+		__field(	u64,			noise		)
+		__field(	u64,			runtime		)
+		__field(	u64,			max_sample	)
+		__field(	unsigned int,		hw_count	)
+		__field(	unsigned int,		nmi_count	)
+		__field(	unsigned int,		irq_count	)
+		__field(	unsigned int,		softirq_count	)
+		__field(	unsigned int,		thread_count	)
+	),
+
+	F_printk("noise:%llu\tmax_sample:%llu\thw:%u\tnmi:%u\tirq:%u\tsoftirq:%u\tthread:%u\n",
+		 __entry->noise,
+		 __entry->max_sample,
+		 __entry->hw_count,
+		 __entry->nmi_count,
+		 __entry->irq_count,
+		 __entry->softirq_count,
+		 __entry->thread_count)
+);

new file mode 100644
index 000000000000..34c7b80f9e12
@@ -0,0 +1,9 @@
+int __weak osnoise_arch_register(void)
+{
+	return 0;
+}
+
+void __weak osnoise_arch_unregister(void)
+{
+	return;
+}

2.31.1

[..]

no...

It's not used.

I will do that!

-- Daniel

Ack!

-- Daniel

The timerlat tracer aims to help the preemptive kernel developers to found souces of wakeup latencies of real-time threads. Like cyclictest, the tracer sets a periodic timer that wakes up a thread. The thread then computes a *wakeup latency* value as the difference between the *current time* and the *absolute time* that the timer was set to expire. The main goal of timerlat is tracing in such a way to help kernel developers.

Usage

Write the ASCII text "timerlat" into the current_tracer file of the tracing system (generally mounted at /sys/kernel/tracing).

For example:

[root@f32 ~]# cd /sys/kernel/tracing/ [root@f32 tracing]# echo timerlat > current_tracer

It is possible to follow the trace by reading the trace trace file:

[root@f32 tracing]# cat trace
# tracer: timerlat
#
# _-----=> irqs-off
# / _----=> need-resched

  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            || /
  #                            ||||             ACTIVATION
  #         TASK-PID      CPU# ||||   TIMESTAMP    ID            CONTEXT                LATENCY
  #            | |         |   ||||      |         |                  |                       |
          <idle>-0       [000] d.h1    54.029328: #1     context    irq timer_latency       932 ns
           <...>-867     [000] ....    54.029339: #1     context thread timer_latency     11700 ns
          <idle>-0       [001] dNh1    54.029346: #1     context    irq timer_latency      2833 ns
           <...>-868     [001] ....    54.029353: #1     context thread timer_latency      9820 ns
          <idle>-0       [000] d.h1    54.030328: #2     context    irq timer_latency       769 ns
           <...>-867     [000] ....    54.030330: #2     context thread timer_latency      3070 ns
          <idle>-0       [001] d.h1    54.030344: #2     context    irq timer_latency       935 ns
           <...>-868     [001] ....    54.030347: #2     context thread timer_latency      4351 ns

The tracer creates a per-cpu kernel thread with real-time priority that prints two lines at every activation. The first is the *timer latency* observed at the *hardirq* context before the activation of the thread. The second is the *timer latency* observed by the thread, which is the same level that cyclictest reports. The ACTIVATION ID field serves to relate the *irq* execution to its respective *thread* execution.

The irq/thread splitting is important to clarify at which context the unexpected high value is coming from. The *irq* context can be delayed by hardware related actions, such as SMIs, NMIs, IRQs or by a thread masking interrupts. Once the timer happens, the delay can also be influenced by blocking caused by threads. For example, by postponing the scheduler execution via preempt_disable(), by the scheduler execution, or by masking interrupts. Threads can also be delayed by the interference from other threads and IRQs.

The timerlat can also take advantage of the osnoise: traceevents. For example:

        [root@f32 ~]# cd /sys/kernel/tracing/
        [root@f32 tracing]# echo timerlat > current_tracer
        [root@f32 tracing]# echo osnoise > set_event
        [root@f32 tracing]# echo 25 > osnoise/stop_tracing_out_us
        [root@f32 tracing]# tail -10 trace
             cc1-87882   [005] d..h...   548.771078: #402268 context    irq timer_latency      1585 ns
             cc1-87882   [005] dNLh1..   548.771082: irq_noise: local_timer:236 start 548.771077442 duration 4597 ns
             cc1-87882   [005] dNLh2..   548.771083: irq_noise: reschedule:253 start 548.771083017 duration 56 ns
             cc1-87882   [005] dNLh2..   548.771086: irq_noise: call_function_single:251 start 548.771083811 duration 2048 ns
             cc1-87882   [005] dNLh2..   548.771088: irq_noise: call_function_single:251 start 548.771086814 duration 1495 ns
             cc1-87882   [005] dNLh2..   548.771091: irq_noise: call_function_single:251 start 548.771089194 duration 1558 ns
             cc1-87882   [005] dNLh2..   548.771094: irq_noise: call_function_single:251 start 548.771091719 duration 1932 ns
             cc1-87882   [005] dNLh2..   548.771096: irq_noise: call_function_single:251 start 548.771094696 duration 1050 ns
             cc1-87882   [005] d...3..   548.771101: thread_noise:      cc1:87882 start 548.771078243 duration 10909 ns
      timerlat/5-1035    [005] .......   548.771103: #402268 context thread timer_latency     25960 ns

For further information see: Documentation/trace/timerlat-tracer.rst

---
 Documentation/trace/index.rst           |   1 +
 Documentation/trace/timerlat-tracer.rst | 181 +++++++
 kernel/trace/Kconfig                    |  28 ++
 kernel/trace/trace.h                    |   2 +
 kernel/trace/trace_entries.h            |  16 +
 kernel/trace/trace_osnoise.c            | 626 ++++++++++++++++++++++--
 kernel/trace/trace_output.c             |  47 ++
 7 files changed, 870 insertions(+), 31 deletions(-)
 create mode 100644 Documentation/trace/timerlat-tracer.rst

index 608107b27cc0..3769b9b7aed8 100644
@@ -24,6 +24,7 @@ Linux Tracing Technologies
    boottime-trace
    hwlat_detector
    osnoise-tracer
+   timerlat-tracer
    intel_th
    ring-buffer-design
    stm

index 41582ae4682b..d567b1717c4c 100644
@@ -390,6 +390,34 @@ config OSNOISE_TRACER
 	  To enable this tracer, echo in "osnoise" into the current_tracer
           file.
 
+config TIMERLAT_TRACER
+	bool "Timerlat tracer"
+	select OSNOISE_TRACER
+	select GENERIC_TRACER
+	help
+	  The timerlat tracer aims to help the preemptive kernel developers
+	  to find sources of wakeup latencies of real-time threads.
+
+	  The tracer creates a per-cpu kernel thread with real-time priority.
+	  The tracer thread sets a periodic timer to wakeup itself, and goes
+	  to sleep waiting for the timer to fire. At the wakeup, the thread
+	  then computes a wakeup latency value as the difference between
+	  the current time and the absolute time that the timer was set
+	  to expire.
+
+	  The tracer prints two lines at every activation. The first is the
+	  timer latency observed at the hardirq context before the
+	  activation of the thread. The second is the timer latency observed
+	  by the thread, which is the same level that cyclictest reports. The
+	  ACTIVATION ID field serves to relate the irq execution to its
+	  respective thread execution.
+
+	  The tracer is build on top of osnoise tracer, and the osnoise:
+	  events can be used to trace the source of interference from NMI,
+	  IRQs and other threads. It also enables the capture of the
+	  stacktrace at the IRQ context, which helps to identify the code
+	  path that can cause thread delay.
+
 config MMIOTRACE
 	bool "Memory mapped IO tracing"
 	depends on HAVE_MMIOTRACE_SUPPORT && PCI

index 760129d5f576..116d1b4c813a 100644
@@ -45,6 +45,7 @@ enum trace_type {
 	TRACE_BPUTS,
 	TRACE_HWLAT,
 	TRACE_OSNOISE,
+	TRACE_TIMERLAT,
 	TRACE_RAW_DATA,
 	TRACE_FUNC_REPEATS,
 

@@ -448,6 +449,7 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct bputs_entry, TRACE_BPUTS);	\
 		IF_ASSIGN(var, ent, struct hwlat_entry, TRACE_HWLAT);	\
 		IF_ASSIGN(var, ent, struct osnoise_entry, TRACE_OSNOISE);\
+		IF_ASSIGN(var, ent, struct timerlat_entry, TRACE_TIMERLAT);\
 		IF_ASSIGN(var, ent, struct raw_data_entry, TRACE_RAW_DATA);\
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_rw,		\
 			  TRACE_MMIO_RW);				\

index 158c0984b59b..cd41e863b51c 100644
@@ -385,3 +385,19 @@ FTRACE_ENTRY(osnoise, osnoise_entry,
 		 __entry->softirq_count,
 		 __entry->thread_count)
 );
+
+FTRACE_ENTRY(timerlat, timerlat_entry,
+
+	TRACE_TIMERLAT,
+
+	F_STRUCT(
+		__field(	unsigned int,		seqnum		)
+		__field(	int,			context		)
+		__field(	u64,			timer_latency	)
+	),
+
+	F_printk("seq:%u\tcontext:%d\ttimer_latency:%llu\n",
+		 __entry->seqnum,
+		 __entry->context,
+		 __entry->timer_latency)
+);

2.31.1

Enable and disable osnoise/timerlat thread during on CPU hotplug online and offline operations respectivelly.

---
 kernel/trace/trace_osnoise.c | 133 +++++++++++++++++++++++++++--------
 1 file changed, 103 insertions(+), 30 deletions(-)

index 2c1e2a074b1e..e8f057a3bdc3 100644
@@ -1399,22 +1399,67 @@ static int timerlat_main(void *data)
 #endif /* CONFIG_TIMERLAT_TRACER */
 
 /*
- * stop_per_cpu_kthread - stop per-cpu threads
+ * stop_kthread - stop a workload thread
+ */
+static void stop_kthread(unsigned int cpu)
+{
+	struct task_struct *kthread;
+
+	kthread = per_cpu(per_cpu_osnoise_var, cpu).kthread;
+	if (kthread)
+		kthread_stop(kthread);
+	per_cpu(per_cpu_osnoise_var, cpu).kthread = NULL;
+}
+
+/*
+ * stop_per_cpu_kthread - Stop per-cpu threads
  *
  * Stop the osnoise sampling htread. Use this on unload and at system
  * shutdown.
  */
 static void stop_per_cpu_kthreads(void)
 {
-	struct task_struct *kthread;
 	int cpu;
 
-	for_each_online_cpu(cpu) {
-		kthread = per_cpu(per_cpu_osnoise_var, cpu).kthread;
-		if (kthread)
-			kthread_stop(kthread);
-		per_cpu(per_cpu_osnoise_var, cpu).kthread = NULL;
+	get_online_cpus();
+
+	for_each_online_cpu(cpu)
+		stop_kthread(cpu);
+
+	put_online_cpus();
+}
+
+/*
+ * start_kthread - Start a workload tread
+ */
+static int start_kthread(unsigned int cpu)
+{
+	struct task_struct *kthread;
+	char comm[24];
+	void *main = osnoise_main;
+
+#ifdef CONFIG_TIMERLAT_TRACER
+	if (osnoise_data.timerlat_tracer) {
+		snprintf(comm, 24, "timerlat/%d", cpu);
+		main = timerlat_main;
+	} else {
+		snprintf(comm, 24, "osnoise/%d", cpu);
+	}
+#else
+	snprintf(comm, 24, "osnoise/%d", cpu);
+#endif
+	kthread = kthread_create_on_cpu(main, NULL, cpu, comm);
+
+	if (IS_ERR(kthread)) {
+		pr_err(BANNER "could not start sampling thread\n");
+		stop_per_cpu_kthreads();
+		return -ENOMEM;
 	}
+
+	per_cpu(per_cpu_osnoise_var, cpu).kthread = kthread;
+	wake_up_process(kthread);
+
+	return 0;
 }
 
 /*

@@ -1426,9 +1471,7 @@ static void stop_per_cpu_kthreads(void)
 static int start_per_cpu_kthreads(struct trace_array *tr)
 {
 	struct cpumask *current_mask = &save_cpumask;
-	struct task_struct *kthread;
-	char comm[24];
-	void *main = osnoise_main;
+	int retval;
 	int cpu;
 
 	get_online_cpus();

@@ -1440,34 +1483,52 @@ static int start_per_cpu_kthreads(struct trace_array *tr)
 	 * And the CPU is online.
 	 */
 	cpumask_and(current_mask, cpu_online_mask, current_mask);
-	put_online_cpus();
 
-	for_each_online_cpu(cpu)
+	for_each_possible_cpu(cpu)
 		per_cpu(per_cpu_osnoise_var, cpu).kthread = NULL;
 
 	for_each_cpu(cpu, current_mask) {
-#ifdef CONFIG_TIMERLAT_TRACER
-		if (osnoise_data.timerlat_tracer) {
-			snprintf(comm, 24, "timerlat/%d", cpu);
-			main = timerlat_main;
-		} else {
-			snprintf(comm, 24, "osnoise/%d", cpu);
-		}
-#else
-		snprintf(comm, 24, "osnoise/%d", cpu);
-#endif
-		kthread = kthread_create_on_cpu(main, NULL, cpu, comm);
-
-		if (IS_ERR(kthread)) {
-			pr_err(BANNER "could not start sampling thread\n");
+		retval = start_kthread(cpu);
+		if (retval) {
 			stop_per_cpu_kthreads();
-			return -ENOMEM;
+			return retval;
 		}
-
-		per_cpu(per_cpu_osnoise_var, cpu).kthread = kthread;
-		wake_up_process(kthread);
 	}
 
+	put_online_cpus();
+
+	return 0;
+}
+
+/*
+ * osnoise_cpu_init - CPU hotplug online callback function
+ */
+static int osnoise_cpu_init(unsigned int cpu)
+{
+	struct trace_array *tr = osnoise_trace;
+
+	if (!osnoise_busy)
+		return 0;
+
+	if (!cpumask_test_cpu(cpu, &osnoise_cpumask))
+		return 0;
+
+	if (!cpumask_test_cpu(cpu, tr->tracing_cpumask))
+		return 0;
+
+	return start_kthread(cpu);
+}
+
+/*
+ * osnoise_cpu_die - CPU hotplug offline callback function
+ */
+static int osnoise_cpu_die(unsigned int cpu)
+{
+	if (!osnoise_busy)
+		return 0;
+
+	stop_kthread(cpu);
+
 	return 0;
 }
 

@@ -1566,7 +1627,14 @@ osnoise_cpus_write(struct file *filp, const char __user *ubuf, size_t count,
 		osnoise_tracer_stop(tr);
 
 	mutex_lock(&interface_lock);
+	/*
+	 * osnoise_cpumask is ready by CPU hotplug operations.
+	 */
+	get_online_cpus();
+
 	cpumask_copy(&osnoise_cpumask, osnoise_cpumask_new);
+
+	put_online_cpus();
 	mutex_unlock(&interface_lock);
 
 	if (running)

@@ -1924,6 +1992,11 @@ __init static int init_osnoise_tracer(void)
 	}
 #endif
 
+	ret = cpuhp_setup_state(CPUHP_AP_ONLINE_DYN, "trace/osnoise:online",
+				osnoise_cpu_init, osnoise_cpu_die);
+	if (ret < 0)
+		pr_warn(BANNER "Error to init cpu hotplug support\n");
+
 	init_tracefs();
 
 	return 0;

2.31.1

I think I meant "read"... I will use your comment.

Thanks

-- Daniel