hwlat improvements and osnoise/timerlat tracers
Subsystems (4)
v2 cover 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 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)
Daniel Bristot de Oliveira (8):
tracing/hwlat: Fix Clark's email
tracing/hwlat: Implement the mode config option tracing/hwlat: Switch disable_migrate to mode none tracing/hwlat: Implement the per-cpu mode
tracing/trace: Add a generic function to read/write u64 values from
tracefs
trace/hwlat: Use the generic function to read/write width and window
tracing: Add osnoise tracer
tracing: Add timerlat tracer
Steven Rostedt (1):
tracing: 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 | 158 ++ 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 | 88 +- kernel/trace/trace.h | 31 +- kernel/trace/trace_entries.h | 41 + kernel/trace/trace_hwlat.c | 410 +++-- kernel/trace/trace_osnoise.c | 2118 +++++++++++++++++++++++ kernel/trace/trace_output.c | 119 +- 15 files changed, 3227 insertions(+), 148 deletions(-) create mode 100644 Documentation/trace/osnoise-tracer.rst create mode 100644 Documentation/trace/timerlat-tracer.rst create mode 100644 include/trace/events/osnoise.h create mode 100644 kernel/trace/trace_osnoise.c
Signature · 1 line
2.26.3
RFC PATCH v2 1/9 tracing/hwlat: Fix Clark's email
Clark's email is [email protected]
No functional change.
--- kernel/trace/trace_hwlat.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/trace/trace_hwlat.c +1 -1
@@ -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>
Signature · 1 line
2.26.3
RFC PATCH v2 2/9 tracing/hwlat: Implement the mode config option
In reply to Daniel Bristot de OliveiraProvides 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 | 171 +++++++++++++++++++++++-- 2 files changed, 169 insertions(+), 14 deletions(-)
Documentation/trace/hwlat_detector.rst +8 -4
@@ -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]
kernel/trace/trace_hwlat.c +161 -10
230 lines not on this page · raw message
Signature · 1 line
2.26.3
RFC PATCH v2 3/9 tracing/hwlat: Switch disable_migrate to mode none
In reply to Daniel Bristot de OliveiraWhen 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(-)
kernel/trace/trace_hwlat.c +5 -8
@@ -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" ); }/*
@@ -740,7 +738,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;
Signature · 1 line
2.26.3
RFC PATCH v2 4/9 tracing/hwlat: Implement the per-cpu mode
In reply to Daniel Bristot de OliveiraImplements 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 | 165 +++++++++++++++++++------ 2 files changed, 130 insertions(+), 38 deletions(-)
Documentation/trace/hwlat_detector.rst +2 -1
@@ -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
kernel/trace/trace_hwlat.c +128 -37
286 lines not on this page · raw message
Signature · 1 line
2.26.3
kernel test robot
build botRe: [RFC PATCH V2 4/9] tracing/hwlat: Implement the per-cpu mode
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch]
Hi Daniel,
[FYI, it's a private test report for your RFC patch.]
[auto build test ERROR on tip/perf/core]
[also build test ERROR on linux/master linus/master v5.12-rc8] [cannot apply to trace/for-next next-20210423]
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]
url: https://github.com/0day-ci/linux/commits/Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 base: https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git ed8e50800bf4c2d904db9c75408a67085e6cca3d config: um-allmodconfig (attached as .config) compiler: gcc-9 (Debian 9.3.0-22) 9.3.0
reproduce (this is a W=1 build):
# https://github.com/0day-ci/linux/commit/cc67db26b537dd444a86c595fdb56a6cb020f79c
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 git checkout cc67db26b537dd444a86c595fdb56a6cb020f79c
# save the attached .config to linux build tree
make W=1 W=1 ARCH=um
If you fix the issue, kindly add following tag as appropriate
All errors (new ones prefixed by >>):
cc1: warning: arch/um/include/uapi: No such file or directory [-Wmissing-include-dirs] kernel/trace/trace_hwlat.c:120:28: warning: no previous prototype for 'get_cpu_data' [-Wmissing-prototypes]
120 | struct hwlat_kthread_data *get_cpu_data(void)
| ^~~~~~~~~~~~
kernel/trace/trace_hwlat.c: In function 'start_per_cpu_kthreads':
>> kernel/trace/trace_hwlat.c:477:25: error: passing argument 1 of 'alloc_cpumask_var' from incompatible pointer type [-Werror=incompatible-pointer-types]
477 | if (!alloc_cpumask_var(&this_cpumask, GFP_KERNEL))
| ^~~~~~~~~~~~~
| |
| struct cpumask ** In file included from include/linux/smp.h:13,
from include/linux/lockdep.h:14,
from include/linux/rcupdate.h:29,
from include/linux/rculist.h:11,
from include/linux/pid.h:5,
from include/linux/sched.h:14,
from include/linux/kthread.h:6,
from kernel/trace/trace_hwlat.c:40:
include/linux/cpumask.h:767:53: note: expected 'struct cpumask (*)[1]' but argument is of type 'struct cpumask **'
767 | static inline bool alloc_cpumask_var(cpumask_var_t *mask, gfp_t flags)
| ~~~~~~~~~~~~~~~^~~~
cc1: some warnings being treated as errors
vim +/alloc_cpumask_var +477 kernel/trace/trace_hwlat.c
461
462 /**
463 * start_per_cpu_kthread - Kick off the hardware latency sampling/detector kthreads
464 *
465 * This starts the kernel threads that will sit on potentially all cpus and
466 * sample the CPU timestamp counter (TSC or similar) and look for potential
467 * hardware latencies.
468 */
469 static int start_per_cpu_kthreads(struct trace_array *tr)
470 {
471 struct cpumask *current_mask = &save_cpumask;
472 struct cpumask *this_cpumask;
473 struct task_struct *kthread;
474 char comm[24];
475 int cpu;
476
> 477 if (!alloc_cpumask_var(&this_cpumask, GFP_KERNEL))
478 return -ENOMEM;
479
480 /*
481 * Run only on CPUs in which hwlat is allowed to run.
482 */
483 get_online_cpus();
484 cpumask_and(current_mask, cpu_online_mask, tr->tracing_cpumask);
485 put_online_cpus();
486
487 for_each_online_cpu(cpu)
488 per_cpu(hwlat_per_cpu_data, cpu).kthread = NULL;
489
490 for_each_cpu(cpu, current_mask) {
491 snprintf(comm, 24, "hwlatd/%d", cpu);
492
493 kthread = kthread_create_on_cpu(kthread_fn, NULL, cpu, comm);
494 if (IS_ERR(kthread)) {
495 pr_err(BANNER "could not start sampling thread\n");
496 stop_per_cpu_kthreads();
497 return -ENOMEM;
498 }
499
500 per_cpu(hwlat_per_cpu_data, cpu).kthread = kthread;
501 wake_up_process(kthread);
502 }
503
504 return 0;
505 }
506
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all(a)lists.01.org
RFC PATCH v2 5/9 tracing/trace: Add a generic function to read/write u64 values from tracefs
In reply to Daniel Bristot de OliveiraProvides a generic read and write implementation to save/read u64 values from a file on tracefs. The trace_ull_config structure defines where to read/write the value, the min and the max acceptable values, and a lock to protect the write.
--- kernel/trace/trace.c | 88 +++++++++++++++++++++++++++++++++++++++++++- kernel/trace/trace.h | 20 ++++++++++ 2 files changed, 107 insertions(+), 1 deletion(-)
kernel/trace/trace.c +87 -1
@@ -7185,7 +7185,6 @@ static int snapshot_raw_open(struct inode *inode, struct file *filp)#endif /* CONFIG_TRACER_SNAPSHOT */ -static const struct file_operations tracing_thresh_fops = { .open = tracing_open_generic, .read = tracing_thresh_read,
@@ -7287,6 +7286,93 @@ static const struct file_operations snapshot_raw_fops = {#endif /* CONFIG_TRACER_SNAPSHOT */ +/* +* trace_ull_config_write - Generic write function to save u64 value +* @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 write implementation to save u64 values +* from a file on tracefs. The filp->private_data must point to a +* trace_ull_config structure that defines where to write the value, the +* min and the max acceptable values, and a lock to protect the write. +*/ +ssize_t +trace_ull_config_write (struct file *filp,const char __user *ubuf,size_t cnt, +loff_t *ppos) +{ +struct trace_ull_config *config = filp->private_data; +u64 val; +int err; + +if (!config) +return -EFAULT ; + + err =kstrtoull_from_user (ubuf, cnt,10 , &val); +if (err) +return err; + +if (config->lock) +mutex_lock (config->lock); + +if (config->min && val < *config->min) + err = -EINVAL ; + +if (config->max && val > *config->max) + err = -EINVAL ; + +if (!err) + *config->val = val; + +if (config->lock) +mutex_unlock (config->lock); + +if (err) +return err; + +return cnt; +} + +/* +* trace_ull_config_read - Generic write function to read u64 value via tracefs +* @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 to read a u64 value +* from a file on tracefs. The filp->private_data must point to a +* trace_ull_config structure with valid data. +*/ +ssize_t +trace_ull_config_read (struct file *filp,char __user *ubuf,size_t cnt, +loff_t *ppos) +{ +struct trace_ull_config *config = filp->private_data; +char buf[ULL_STR_SIZE ]; +u64 val; +int len; + +if (!config) +return -EFAULT ; + + val = *config->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_ull_config_fops = { + .open = tracing_open_generic, + .read = trace_ull_config_read, + .write = trace_ull_config_write, +}; +#define TRACING_LOG_ERRS_MAX 8#define TRACING_LOG_LOC_MAX 128
kernel/trace/trace.h +20 -0
@@ -1929,4 +1929,24 @@ static inline bool is_good_name(const char *name) return true; } +/* +* This is a generic way to read and write a u64 config 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_ull_config { +struct mutex *lock; +u64 *val; +u64 *min; +u64 *max; +}; + +#define ULL_STR_SIZE 22/* 20 digits max */ + +extern const struct file_operations trace_ull_config_fops; + +#endif /* _LINUX_KERNEL_TRACE_H */
Signature · 1 line
2.26.3
kernel test robot
build botRe: [RFC PATCH V2 5/9] tracing/trace: Add a generic function to read/write u64 values from tracefs
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch]
Hi Daniel,
[FYI, it's a private test report for your RFC patch.]
[auto build test WARNING on tip/perf/core]
[also build test WARNING on linux/master linus/master v5.12-rc8] [cannot apply to trace/for-next next-20210423]
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]
url: https://github.com/0day-ci/linux/commits/Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 base: https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git ed8e50800bf4c2d904db9c75408a67085e6cca3d config: arc-allyesconfig (attached as .config) compiler: arceb-elf-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross chmod +x ~/bin/make.cross
# https://github.com/0day-ci/linux/commit/21b6c7475ccbd8c3dd5a0cb291166b7c54366243
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 git checkout 21b6c7475ccbd8c3dd5a0cb291166b7c54366243
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross W=1 ARCH=arc
If you fix the issue, kindly add following tag as appropriate
All warnings (new ones prefixed by >>):
>> kernel/trace/trace.c:7301:1: warning: no previous prototype for 'trace_ull_config_write' [-Wmissing-prototypes]
7301 | trace_ull_config_write(struct file *filp, const char __user *ubuf, size_t cnt,
| ^~~~~~~~~~~~~~~~~~~~~~
>> kernel/trace/trace.c:7348:1: warning: no previous prototype for 'trace_ull_config_read' [-Wmissing-prototypes]
7348 | trace_ull_config_read(struct file *filp, char __user *ubuf, size_t cnt,
| ^~~~~~~~~~~~~~~~~~~~~
In file included from include/linux/perf_event.h:25,
from include/linux/hw_breakpoint.h:5,
from kernel/trace/trace.h:15,
from kernel/trace/trace.c:52:
arch/arc/include/asm/perf_event.h:126:23: warning: 'arc_pmu_cache_map' defined but not used [-Wunused-const-variable=]
126 | static const unsigned arc_pmu_cache_map[C(MAX)][C(OP_MAX)][C(RESULT_MAX)] = {
| ^~~~~~~~~~~~~~~~~
arch/arc/include/asm/perf_event.h:91:27: warning: 'arc_pmu_ev_hw_map' defined but not used [-Wunused-const-variable=]
91 | static const char * const arc_pmu_ev_hw_map[] = {
| ^~~~~~~~~~~~~~~~~vim +/trace_ull_config_write +7301 kernel/trace/trace.c
7287
7288 /*
7289 * trace_ull_config_write - Generic write function to save u64 value
7290 * @filp: The active open file structure
7291 * @ubuf: The userspace provided buffer to read value into
7292 * @cnt: The maximum number of bytes to read
7293 * @ppos: The current "file" position
7294 *
7295 * This function provides a generic write implementation to save u64 values
7296 * from a file on tracefs. The filp->private_data must point to a
7297 * trace_ull_config structure that defines where to write the value, the
7298 * min and the max acceptable values, and a lock to protect the write.
7299 */
7300 ssize_t
> 7301 trace_ull_config_write(struct file *filp, const char __user *ubuf, size_t cnt,
7302 loff_t *ppos)
7303 {
7304 struct trace_ull_config *config = filp->private_data;
7305 u64 val;
7306 int err;
7307
7308 if (!config)
7309 return -EFAULT;
7310
7311 err = kstrtoull_from_user(ubuf, cnt, 10, &val);
7312 if (err)
7313 return err;
7314
7315 if (config->lock)
7316 mutex_lock(config->lock);
7317
7318 if (config->min && val < *config->min)
7319 err = -EINVAL;
7320
7321 if (config->max && val > *config->max)
7322 err = -EINVAL;
7323
7324 if (!err)
7325 *config->val = val;
7326
7327 if (config->lock)
7328 mutex_unlock(config->lock);
7329
7330 if (err)
7331 return err;
7332
7333 return cnt;
7334 }
7335
7336 /*
7337 * trace_ull_config_read - Generic write function to read u64 value via tracefs
7338 * @filp: The active open file structure
7339 * @ubuf: The userspace provided buffer to read value into
7340 * @cnt: The maximum number of bytes to read
7341 * @ppos: The current "file" position
7342 *
7343 * This function provides a generic read implementation to read a u64 value
7344 * from a file on tracefs. The filp->private_data must point to a
7345 * trace_ull_config structure with valid data.
7346 */
7347 ssize_t
> 7348 trace_ull_config_read(struct file *filp, char __user *ubuf, size_t cnt, 7349 loff_t *ppos)
7350 {
7351 struct trace_ull_config *config = filp->private_data;
7352 char buf[ULL_STR_SIZE];
7353 u64 val;
7354 int len;
7355
7356 if (!config)
7357 return -EFAULT;
7358
7359 val = *config->val;
7360
7361 if (cnt > sizeof(buf))
7362 cnt = sizeof(buf);
7363
7364 len = snprintf(buf, sizeof(buf), "%llu\n", val);
7365
7366 return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
7367 }
7368
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all(a)lists.01.org
kernel test robot
build botRe: [RFC PATCH V2 5/9] tracing/trace: Add a generic function to read/write u64 values from tracefs
In reply to Daniel Bristot de Oliveira[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch]
Hi Daniel,
[FYI, it's a private test report for your RFC patch.]
[auto build test WARNING on tip/perf/core]
[also build test WARNING on linux/master linus/master v5.12-rc8] [cannot apply to trace/for-next next-20210423]
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]
url: https://github.com/0day-ci/linux/commits/Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 base: https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git ed8e50800bf4c2d904db9c75408a67085e6cca3d config: x86_64-randconfig-s022-20210423 (attached as .config) compiler: gcc-9 (Debian 9.3.0-22) 9.3.0 reproduce: # apt-get install sparse # sparse version: v0.6.3-341-g8af24329-dirty # https://github.com/0day-ci/linux/commit/21b6c7475ccbd8c3dd5a0cb291166b7c54366243 git remote add linux-review https://github.com/0day-ci/linux git fetch --no-tags linux-review Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 git checkout 21b6c7475ccbd8c3dd5a0cb291166b7c54366243 # save the attached .config to linux build tree make W=1 C=1 CF='-fdiagnostic-prefix -D__CHECK_ENDIAN__' W=1 ARCH=x86_64
If you fix the issue, kindly add following tag as appropriate
sparse warnings: (new ones prefixed by >>)
kernel/trace/trace.c:383:28: sparse: sparse: incorrect type in argument 1 (different address spaces) @@ expected struct trace_export **list @@ got struct trace_export [noderef] __rcu ** @@
kernel/trace/trace.c:383:28: sparse: expected struct trace_export **list
kernel/trace/trace.c:383:28: sparse: got struct trace_export [noderef] __rcu **
kernel/trace/trace.c:397:33: sparse: sparse: incorrect type in argument 1 (different address spaces) @@ expected struct trace_export **list @@ got struct trace_export [noderef] __rcu ** @@
kernel/trace/trace.c:397:33: sparse: expected struct trace_export **list
kernel/trace/trace.c:397:33: sparse: got struct trace_export [noderef] __rcu **
kernel/trace/trace.c:2797:38: sparse: sparse: incorrect type in argument 1 (different address spaces) @@ expected struct event_filter *filter @@ got struct event_filter [noderef] __rcu *filter @@
kernel/trace/trace.c:2797:38: sparse: expected struct event_filter *filter
kernel/trace/trace.c:2797:38: sparse: got struct event_filter [noderef] __rcu *filter
kernel/trace/trace.c:3132:46: sparse: sparse: incorrect type in initializer (different address spaces) @@ expected void const [noderef] __percpu *__vpp_verify @@ got struct trace_buffer_struct * @@
kernel/trace/trace.c:3132:46: sparse: expected void const [noderef] __percpu *__vpp_verify
kernel/trace/trace.c:3132:46: sparse: got struct trace_buffer_struct *
kernel/trace/trace.c:3148:9: sparse: sparse: incorrect type in initializer (different address spaces) @@ expected void const [noderef] __percpu *__vpp_verify @@ got int * @@
kernel/trace/trace.c:3148:9: sparse: expected void const [noderef] __percpu *__vpp_verify
kernel/trace/trace.c:3148:9: sparse: got int *
kernel/trace/trace.c:3158:17: sparse: sparse: incorrect type in assignment (different address spaces) @@ expected struct trace_buffer_struct *buffers @@ got struct trace_buffer_struct [noderef] __percpu * @@
kernel/trace/trace.c:3158:17: sparse: expected struct trace_buffer_struct *buffers
kernel/trace/trace.c:3158:17: sparse: got struct trace_buffer_struct [noderef] __percpu *
>> kernel/trace/trace.c:7301:1: sparse: sparse: symbol 'trace_ull_config_write' was not declared. Should it be static? >> kernel/trace/trace.c:7348:1: sparse: sparse: symbol 'trace_ull_config_read' was not declared. Should it be static?
kernel/trace/trace.c:337:9: sparse: sparse: incompatible types in comparison expression (different address spaces):
kernel/trace/trace.c:337:9: sparse: struct trace_export [noderef] __rcu *
kernel/trace/trace.c:337:9: sparse: struct trace_export *
kernel/trace/trace.c:352:9: sparse: sparse: incompatible types in comparison expression (different address spaces):
kernel/trace/trace.c:352:9: sparse: struct trace_export [noderef] __rcu *
kernel/trace/trace.c:352:9: sparse: struct trace_export *
Please review and possibly fold the followup patch.
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all(a)lists.01.org
kernel test robot
build bot[RFC PATCH] tracing/trace: trace_ull_config_write can be static
In reply to Daniel Bristot de OliveiraReported-by: kernel test robot <[email protected]>
--- trace.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace.c +2 -2
@@ -7297,7 +7297,7 @@ static const struct file_operations snapshot_raw_fops = {* trace_ull_config structure that defines where to write the value, the * min and the max acceptable values, and a lock to protect the write. */ -ssize_t +static ssize_t trace_ull_config_write (struct file *filp,const char __user *ubuf,size_t cnt,loff_t *ppos) {
@@ -7344,7 +7344,7 @@ trace_ull_config_write(struct file *filp, const char __user *ubuf, size_t cnt,* from a file on tracefs. The filp->private_data must point to a * trace_ull_config structure with valid data. */ -ssize_t +static ssize_t trace_ull_config_read (struct file *filp,char __user *ubuf,size_t cnt,loff_t *ppos) {
kernel test robot
build botRe: [RFC PATCH V2 5/9] tracing/trace: Add a generic function to read/write u64 values from tracefs
In reply to Daniel Bristot de Oliveira[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch]
Hi Daniel,
[FYI, it's a private test report for your RFC patch.]
[auto build test WARNING on tip/perf/core]
[also build test WARNING on linux/master linus/master v5.12-rc8] [cannot apply to trace/for-next next-20210423]
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]
url: https://github.com/0day-ci/linux/commits/Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 base: https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git ed8e50800bf4c2d904db9c75408a67085e6cca3d config: powerpc64-randconfig-r014-20210423 (attached as .config) compiler: clang version 13.0.0 (https://github.com/llvm/llvm-project 06234f758e1945084582cf80450b396f75a9c06e)
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross chmod +x ~/bin/make.cross
# install powerpc64 cross compiling tool for clang build
# apt-get install binutils-powerpc64-linux-gnu
# https://github.com/0day-ci/linux/commit/21b6c7475ccbd8c3dd5a0cb291166b7c54366243
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 git checkout 21b6c7475ccbd8c3dd5a0cb291166b7c54366243
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 ARCH=powerpc64
If you fix the issue, kindly add following tag as appropriate
All warnings (new ones prefixed by >>):
__do_##name al; \
^~~~~~~~~~~~~~
<scratch space>:58:1: note: expanded from here
__do_insw
^
arch/powerpc/include/asm/io.h:557:56: note: expanded from macro '__do_insw'
#define __do_insw(p, b, n) readsw((PCI_IO_ADDR)_IO_BASE+(p), (b), (n))
~~~~~~~~~~~~~~~~~~~~~^
In file included from kernel/trace/trace.c:18:
In file included from include/linux/writeback.h:14:
In file included from include/linux/blk-cgroup.h:17:
In file included from include/linux/cgroup.h:26:
In file included from include/linux/kernel_stat.h:9:
In file included from include/linux/interrupt.h:11:
In file included from include/linux/hardirq.h:10:
In file included from arch/powerpc/include/asm/hardirq.h:6:
In file included from include/linux/irq.h:20:
In file included from include/linux/io.h:13:
In file included from arch/powerpc/include/asm/io.h:619:
arch/powerpc/include/asm/io-defs.h:47:1: warning: performing pointer arithmetic on a null pointer has undefined behavior [-Wnull-pointer-arithmetic]
DEF_PCI_AC_NORET(insl, (unsigned long p, void *b, unsigned long c),
^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
arch/powerpc/include/asm/io.h:616:3: note: expanded from macro 'DEF_PCI_AC_NORET'
__do_##name al; \
^~~~~~~~~~~~~~
<scratch space>:60:1: note: expanded from here
__do_insl
^
arch/powerpc/include/asm/io.h:558:56: note: expanded from macro '__do_insl'
#define __do_insl(p, b, n) readsl((PCI_IO_ADDR)_IO_BASE+(p), (b), (n))
~~~~~~~~~~~~~~~~~~~~~^
In file included from kernel/trace/trace.c:18:
In file included from include/linux/writeback.h:14:
In file included from include/linux/blk-cgroup.h:17:
In file included from include/linux/cgroup.h:26:
In file included from include/linux/kernel_stat.h:9:
In file included from include/linux/interrupt.h:11:
In file included from include/linux/hardirq.h:10:
In file included from arch/powerpc/include/asm/hardirq.h:6:
In file included from include/linux/irq.h:20:
In file included from include/linux/io.h:13:
In file included from arch/powerpc/include/asm/io.h:619:
arch/powerpc/include/asm/io-defs.h:49:1: warning: performing pointer arithmetic on a null pointer has undefined behavior [-Wnull-pointer-arithmetic]
DEF_PCI_AC_NORET(outsb, (unsigned long p, const void *b, unsigned long c),
^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
arch/powerpc/include/asm/io.h:616:3: note: expanded from macro 'DEF_PCI_AC_NORET'
__do_##name al; \
^~~~~~~~~~~~~~
<scratch space>:62:1: note: expanded from here
__do_outsb
^
arch/powerpc/include/asm/io.h:559:58: note: expanded from macro '__do_outsb'
#define __do_outsb(p, b, n) writesb((PCI_IO_ADDR)_IO_BASE+(p),(b),(n))
~~~~~~~~~~~~~~~~~~~~~^
In file included from kernel/trace/trace.c:18:
In file included from include/linux/writeback.h:14:
In file included from include/linux/blk-cgroup.h:17:
In file included from include/linux/cgroup.h:26:
In file included from include/linux/kernel_stat.h:9:
In file included from include/linux/interrupt.h:11:
In file included from include/linux/hardirq.h:10:
In file included from arch/powerpc/include/asm/hardirq.h:6:
In file included from include/linux/irq.h:20:
In file included from include/linux/io.h:13:
In file included from arch/powerpc/include/asm/io.h:619:
arch/powerpc/include/asm/io-defs.h:51:1: warning: performing pointer arithmetic on a null pointer has undefined behavior [-Wnull-pointer-arithmetic]
DEF_PCI_AC_NORET(outsw, (unsigned long p, const void *b, unsigned long c),
^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
arch/powerpc/include/asm/io.h:616:3: note: expanded from macro 'DEF_PCI_AC_NORET'
__do_##name al; \
^~~~~~~~~~~~~~
<scratch space>:64:1: note: expanded from here
__do_outsw
^
arch/powerpc/include/asm/io.h:560:58: note: expanded from macro '__do_outsw'
#define __do_outsw(p, b, n) writesw((PCI_IO_ADDR)_IO_BASE+(p),(b),(n))
~~~~~~~~~~~~~~~~~~~~~^
In file included from kernel/trace/trace.c:18:
In file included from include/linux/writeback.h:14:
In file included from include/linux/blk-cgroup.h:17:
In file included from include/linux/cgroup.h:26:
In file included from include/linux/kernel_stat.h:9:
In file included from include/linux/interrupt.h:11:
In file included from include/linux/hardirq.h:10:
In file included from arch/powerpc/include/asm/hardirq.h:6:
In file included from include/linux/irq.h:20:
In file included from include/linux/io.h:13:
In file included from arch/powerpc/include/asm/io.h:619:
arch/powerpc/include/asm/io-defs.h:53:1: warning: performing pointer arithmetic on a null pointer has undefined behavior [-Wnull-pointer-arithmetic]
DEF_PCI_AC_NORET(outsl, (unsigned long p, const void *b, unsigned long c),
^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
arch/powerpc/include/asm/io.h:616:3: note: expanded from macro 'DEF_PCI_AC_NORET'
__do_##name al; \
^~~~~~~~~~~~~~
<scratch space>:66:1: note: expanded from here
__do_outsl
^
arch/powerpc/include/asm/io.h:561:58: note: expanded from macro '__do_outsl'
#define __do_outsl(p, b, n) writesl((PCI_IO_ADDR)_IO_BASE+(p),(b),(n))
~~~~~~~~~~~~~~~~~~~~~^
>> kernel/trace/trace.c:7301:1: warning: no previous prototype for function 'trace_ull_config_write' [-Wmissing-prototypes]
trace_ull_config_write(struct file *filp, const char __user *ubuf, size_t cnt,
^
kernel/trace/trace.c:7300:1: note: declare 'static' if the function is not intended to be used outside of this translation unit
ssize_t
^
static
>> kernel/trace/trace.c:7348:1: warning: no previous prototype for function 'trace_ull_config_read' [-Wmissing-prototypes] trace_ull_config_read(struct file *filp, char __user *ubuf, size_t cnt,
^
kernel/trace/trace.c:7347:1: note: declare 'static' if the function is not intended to be used outside of this translation unit ssize_t
^
static
8 warnings generated.
vim +/trace_ull_config_write +7301 kernel/trace/trace.c
7287
7288 /*
7289 * trace_ull_config_write - Generic write function to save u64 value
7290 * @filp: The active open file structure
7291 * @ubuf: The userspace provided buffer to read value into
7292 * @cnt: The maximum number of bytes to read
7293 * @ppos: The current "file" position
7294 *
7295 * This function provides a generic write implementation to save u64 values
7296 * from a file on tracefs. The filp->private_data must point to a
7297 * trace_ull_config structure that defines where to write the value, the
7298 * min and the max acceptable values, and a lock to protect the write.
7299 */
7300 ssize_t
> 7301 trace_ull_config_write(struct file *filp, const char __user *ubuf, size_t cnt,
7302 loff_t *ppos)
7303 {
7304 struct trace_ull_config *config = filp->private_data;
7305 u64 val;
7306 int err;
7307
7308 if (!config)
7309 return -EFAULT;
7310
7311 err = kstrtoull_from_user(ubuf, cnt, 10, &val);
7312 if (err)
7313 return err;
7314
7315 if (config->lock)
7316 mutex_lock(config->lock);
7317
7318 if (config->min && val < *config->min)
7319 err = -EINVAL;
7320
7321 if (config->max && val > *config->max)
7322 err = -EINVAL;
7323
7324 if (!err)
7325 *config->val = val;
7326
7327 if (config->lock)
7328 mutex_unlock(config->lock);
7329
7330 if (err)
7331 return err;
7332
7333 return cnt;
7334 }
7335
7336 /*
7337 * trace_ull_config_read - Generic write function to read u64 value via tracefs
7338 * @filp: The active open file structure
7339 * @ubuf: The userspace provided buffer to read value into
7340 * @cnt: The maximum number of bytes to read
7341 * @ppos: The current "file" position
7342 *
7343 * This function provides a generic read implementation to read a u64 value
7344 * from a file on tracefs. The filp->private_data must point to a
7345 * trace_ull_config structure with valid data.
7346 */
7347 ssize_t
> 7348 trace_ull_config_read(struct file *filp, char __user *ubuf, size_t cnt, 7349 loff_t *ppos)
7350 {
7351 struct trace_ull_config *config = filp->private_data;
7352 char buf[ULL_STR_SIZE];
7353 u64 val;
7354 int len;
7355
7356 if (!config)
7357 return -EFAULT;
7358
7359 val = *config->val;
7360
7361 if (cnt > sizeof(buf))
7362 cnt = sizeof(buf);
7363
7364 len = snprintf(buf, sizeof(buf), "%llu\n", val);
7365
7366 return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
7367 }
7368
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all(a)lists.01.org
RFC PATCH v2 6/9 tracing/hwlat: Use the generic function to read/write width and window
In reply to Daniel Bristot de OliveiraUse the trace_ull_config generic implementation to reducing the code of hwlat detector.
--- kernel/trace/trace_hwlat.c | 135 ++++--------------------------------- 1 file changed, 14 insertions(+), 121 deletions(-)
kernel/trace/trace_hwlat.c +14 -121
@@ -504,115 +504,6 @@ static int start_per_cpu_kthreads(struct trace_array *tr)return 0 ; } -/* -* 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;
@@ -733,16 +624,18 @@ 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, +static struct trace_ull_config 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, +static struct trace_ull_config 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 = {
@@ -775,15 +668,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_ull_config_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_ull_config_fops);if (!hwlat_sample_width) goto err;
Signature · 1 line
2.26.3
RFC PATCH v2 7/9 tracing: Add __print_ns_to_secs() and __print_ns_without_secs() helpers
In reply to Daniel Bristot de OliveiraFrom: 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(+)
include/trace/trace_events.h +25 -0
@@ -33,6 +33,21 @@static const char TRACE_SYSTEM_STRING [] = \ __stringify(TRACE_SYSTEM) +#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); \ + }) +TRACE_MAKE_SYSTEM_STR ();#undef TRACE_DEFINE_ENUM
@@ -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)
Signature · 1 line
2.26.3
RFC PATCH v2 8/9 tracing: Add osnoise tracer
In reply to Daniel Bristot de OliveiraIn 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 19In 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_in_us: stop the system tracing if a single noise higher than the configured value happens. Writing 0 disables this option.
- osnoise/stop_tracing_out_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 8 us interferences 2In 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 +++ 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 | 1555 ++++++++++++++++++++++++ kernel/trace/trace_output.c | 72 +- 10 files changed, 2000 insertions(+), 4 deletions(-) create mode 100644 Documentation/trace/osnoise-tracer.rst create mode 100644 include/trace/events/osnoise.h create mode 100644 kernel/trace/trace_osnoise.c
Documentation/trace/index.rst +1 -0
@@ -23,6 +23,7 @@ Linux Tracing Technologies histogram-design boottime-trace hwlat_detector + osnoise-tracer intel_th ring-buffer-design stm
Documentation/trace/osnoise-tracer.rst new file +152 -0
152 lines not on this page · raw message
include/linux/ftrace_irq.h +13 -0
@@ -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 */
include/trace/events/osnoise.h new file +142 -0
142 lines not on this page · raw message
kernel/trace/Kconfig +34 -0
@@ -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
kernel/trace/Makefile +1 -0
@@ -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
kernel/trace/trace.h +6 -3
@@ -44,6 +44,7 @@ enum trace_type {TRACE_BLK ,TRACE_BPUTS ,TRACE_HWLAT , +TRACE_OSNOISE ,TRACE_RAW_DATA , __TRACE_LAST_TYPE,
@@ -285,7 +286,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;
@@ -431,6 +433,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 ); \
@@ -656,8 +659,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);
kernel/trace/trace_entries.h +25 -0
@@ -338,3 +338,28 @@ FTRACE_ENTRY(hwlat, hwlat_entry, __entry->nmi_total_ts, __entry->nmi_count) ); + +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) +);
kernel/trace/trace_osnoise.c new file +1555 -0
1,555 lines not on this page · raw message
kernel/trace/trace_output.c +71 -1
90 lines not on this page · raw message
Signature · 1 line
2.26.3
kernel test robot
build botRe: [RFC PATCH V2 8/9] tracing: Add osnoise tracer
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch]
Hi Daniel,
[FYI, it's a private test report for your RFC patch.]
[auto build test ERROR on tip/perf/core]
[also build test ERROR on linux/master linus/master v5.12-rc8] [cannot apply to trace/for-next next-20210423]
[If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]
url: https://github.com/0day-ci/linux/commits/Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 base: https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git ed8e50800bf4c2d904db9c75408a67085e6cca3d config: arc-allyesconfig (attached as .config) compiler: arceb-elf-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross chmod +x ~/bin/make.cross
# https://github.com/0day-ci/linux/commit/50221100b4543f80df7e29c829d55a7965cccfc2
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review Daniel-Bristot-de-Oliveira/hwlat-improvements-and-osnoise-timerlat-tracers/20210424-050958 git checkout 50221100b4543f80df7e29c829d55a7965cccfc2
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross W=1 ARCH=arc
If you fix the issue, kindly add following tag as appropriate
All errors (new ones prefixed by >>):
kernel/trace/trace_osnoise.c:466:6: warning: no previous prototype for 'trace_irqentry_callback' [-Wmissing-prototypes]
466 | void trace_irqentry_callback(void *data, int irq, struct irqaction *action)
| ^~~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:476:6: warning: no previous prototype for 'trace_irqexit_callback' [-Wmissing-prototypes]
476 | void trace_irqexit_callback(void *data, int irq, struct irqaction *action, int ret)
| ^~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:723:5: warning: no previous prototype for 'hook_irq_events' [-Wmissing-prototypes]
723 | int hook_irq_events(void)
| ^~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c: In function 'hook_irq_events':
>> kernel/trace/trace_osnoise.c:713:33: error: expected expression before 'do'
713 | #define register_intel_irq_tp() do {} while (0)
| ^~
kernel/trace/trace_osnoise.c:735:8: note: in expansion of macro 'register_intel_irq_tp'
735 | ret = register_intel_irq_tp();
| ^~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c: At top level:
kernel/trace/trace_osnoise.c:755:6: warning: no previous prototype for 'unhook_irq_events' [-Wmissing-prototypes]
755 | void unhook_irq_events(void)
| ^~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:772:6: warning: no previous prototype for 'trace_softirq_entry_callback' [-Wmissing-prototypes]
772 | void trace_softirq_entry_callback(void *data, unsigned int vec_nr)
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:795:6: warning: no previous prototype for 'trace_softirq_exit_callback' [-Wmissing-prototypes]
795 | void trace_softirq_exit_callback(void *data, unsigned int vec_nr)
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:909:1: warning: no previous prototype for 'trace_sched_switch_callback' [-Wmissing-prototypes]
909 | trace_sched_switch_callback(void *data, bool preempt, struct task_struct *p,
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:927:5: warning: no previous prototype for 'hook_thread_events' [-Wmissing-prototypes]
927 | int hook_thread_events(void)
| ^~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:944:6: warning: no previous prototype for 'unhook_thread_events' [-Wmissing-prototypes]
944 | void unhook_thread_events(void)
| ^~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:956:6: warning: no previous prototype for 'save_osn_sample_stats' [-Wmissing-prototypes]
956 | void save_osn_sample_stats(struct osnoise_variables *osn_var, struct osnoise_sample *s)
| ^~~~~~~~~~~~~~~~~~~~~
kernel/trace/trace_osnoise.c:971:6: warning: no previous prototype for 'diff_osn_sample_stats' [-Wmissing-prototypes]
971 | void diff_osn_sample_stats(struct osnoise_variables *osn_var, struct osnoise_sample *s)
| ^~~~~~~~~~~~~~~~~~~~~
In file included from ./arch/arc/include/generated/asm/div64.h:1,
from include/linux/math.h:5,
from include/linux/kernel.h:13,
from include/linux/list.h:9,
from include/linux/rculist.h:10,
from include/linux/pid.h:5,
from include/linux/sched.h:14,
from include/linux/kthread.h:6,
from kernel/trace/trace_osnoise.c:17:
kernel/trace/trace_osnoise.c: In function 'kthread_fn':
include/asm-generic/div64.h:226:28: warning: comparison of distinct pointer types lacks a cast
226 | (void)(((typeof((n)) *)0) == ((uint64_t *)0)); \
| ^~
kernel/trace/trace_osnoise.c:1161:3: note: in expansion of macro 'do_div'
1161 | do_div(interval, USEC_PER_MSEC);
| ^~~~~~
In file included from include/linux/perf_event.h:25,
from include/linux/hw_breakpoint.h:5,
from kernel/trace/trace.h:15,
from kernel/trace/trace_osnoise.c:24:
At top level:
arch/arc/include/asm/perf_event.h:126:23: warning: 'arc_pmu_cache_map' defined but not used [-Wunused-const-variable=]
126 | static const unsigned arc_pmu_cache_map[C(MAX)][C(OP_MAX)][C(RESULT_MAX)] = {
| ^~~~~~~~~~~~~~~~~
arch/arc/include/asm/perf_event.h:91:27: warning: 'arc_pmu_ev_hw_map' defined but not used [-Wunused-const-variable=]
91 | static const char * const arc_pmu_ev_hw_map[] = {
| ^~~~~~~~~~~~~~~~~vim +/do +713 kernel/trace/trace_osnoise.c
711
712 #else /* CONFIG_X86_LOCAL_APIC */
> 713 #define register_intel_irq_tp() do {} while (0) 714 #define unregister_intel_irq_tp() do {} while (0)
715 #endif /* CONFIG_X86_LOCAL_APIC */
716
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all(a)lists.01.org
RFC PATCH v2 9/9 tracing: Add timerlat tracer
In reply to Daniel Bristot de OliveiraThe 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 nsThe 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 nsFor further information see: Documentation/trace/timerlat-tracer.rst
--- Documentation/trace/index.rst | 1 + Documentation/trace/timerlat-tracer.rst | 158 ++++++ kernel/trace/Kconfig | 28 ++ kernel/trace/trace.h | 2 + kernel/trace/trace_entries.h | 16 + kernel/trace/trace_osnoise.c | 627 ++++++++++++++++++++++-- kernel/trace/trace_output.c | 47 ++ 7 files changed, 847 insertions(+), 32 deletions(-) create mode 100644 Documentation/trace/timerlat-tracer.rst
Documentation/trace/index.rst +1 -0
@@ -24,6 +24,7 @@ Linux Tracing Technologies boottime-trace hwlat_detector osnoise-tracer + timerlat-tracer intel_th ring-buffer-design stm
Documentation/trace/timerlat-tracer.rst new file +158 -0
158 lines not on this page · raw message
kernel/trace/Kconfig +28 -0
@@ -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
kernel/trace/trace.h +2 -0
@@ -45,6 +45,7 @@ enum trace_type {TRACE_BPUTS ,TRACE_HWLAT ,TRACE_OSNOISE , +TRACE_TIMERLAT ,TRACE_RAW_DATA , __TRACE_LAST_TYPE,
@@ -434,6 +435,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 ); \
kernel/trace/trace_entries.h +16 -0
@@ -363,3 +363,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) +);
kernel/trace/trace_osnoise.c +595 -32
806 lines not on this page · raw message
kernel/trace/trace_output.c +47 -0
59 lines not on this page · raw message
Signature · 1 line
2.26.3
Re: [RFC PATCH V2 9/9] tracing: Add timerlat tracer
Hi Daniel,
Just a couple of things I noticed while playing with this nice additon.
On 23/04/21 23:05, Daniel Bristot de Oliveira wrote:
...
Quoted 5 lines
kernel/trace/trace_osnoise.c +5
-0+/** +* tlat_var_reset - Reset the values of the given timerlat_variables +*/ +static inline void tlat_var_reset (void ) +{
kernel/trace/trace_osnoise.c static inline struct osnoise_variables *this_cpu_osn_var(void) · line 153
Quoted 10 lines
kernel/trace/trace_osnoise.c +5
-1+struct timerlat_variables *tlat_var; +int cpu;/* * So far, all the values are initialized as 0, so * zeroing the structure is perfect. */ -memset (osn_var,0 ,sizeof (struct osnoise_variables )); +for_each_cpu (cpu, cpu_online_mask) { +memset (tlat_var,0 ,sizeof (struct timerlat_variables )); + tlat_var =per_cpu_ptr (&per_cpu_timerlat_var, cpu);
Think these two above want to be the other way around?
Quoted 2 lines
(quoted diff) +1
-0+ } }
...
kernel/trace/trace_osnoise.c static struct tracer osnoise_tracer __read_mostly = { · line 2039
Quoted 13 lines
kernel/trace/trace_osnoise.c +13
-0+#ifdef CONFIG_TIMERLAT_TRACER +static void timerlat_tracer_start (struct trace_array *tr) +{ +int retval; + +if (osnoise_busy) +return ; + + retval =__osnoise_tracer_start (tr); +if (retval) + goto out_err; + + osnoise_data.timerlat_tracer =1 ;
It seems this needs to be set before calling __osnoise_tracer_start()?
Thanks!
Juri
Re: [RFC PATCH V2 9/9] tracing: Add timerlat tracer
Quoted 17 lines · Juri Lelli
Hi Daniel,
Just a couple of things I noticed while playing with this nice additon.
On 23/04/21 23:05, Daniel Bristot de Oliveira wrote:
...
Quoted 9 lines
kernel/trace/trace_osnoise.c +7
-0+/** +* tlat_var_reset - Reset the values of the given timerlat_variables +*/ +static inline void tlat_var_reset (void ) +{ +struct timerlat_variables *tlat_var; +int cpu;/* * So far, all the values are initialized as 0, so
Quoted 8 lines
kernel/trace/trace_osnoise.c static inline struct osnoise_variables *this_cpu_osn_var(void) · line 153
Quoted 6 lines
kernel/trace/trace_osnoise.c +3
-1* zeroing the structure is perfect. */ -memset (osn_var,0 ,sizeof (struct osnoise_variables )); +for_each_cpu (cpu, cpu_online_mask) { +memset (tlat_var,0 ,sizeof (struct timerlat_variables )); + tlat_var =per_cpu_ptr (&per_cpu_timerlat_var, cpu);Think these two above want to be the other way around?
Arrrggg! :-) you are right...
Quoted 5 lines
Quoted 2 lines
(quoted diff) +1
-0+ } }...
Quoted 15 lines
kernel/trace/trace_osnoise.c static struct tracer osnoise_tracer __read_mostly = { · line 2039
Quoted 13 lines
kernel/trace/trace_osnoise.c +13
-0+#ifdef CONFIG_TIMERLAT_TRACER +static void timerlat_tracer_start (struct trace_array *tr) +{ +int retval; + +if (osnoise_busy) +return ; + + retval =__osnoise_tracer_start (tr); +if (retval) + goto out_err; + + osnoise_data.timerlat_tracer =1 ;It seems this needs to be set before calling
__osnoise_tracer_start()?
Yep, my bad! two last minute cleanups that broke things...
I will change these two things in the v3.
Thanks!
-- Daniel
Quoted 4 lines
Thanks!
Juri