tracing: More fixes for 5.14
Subsystems (3)
Steven Rostedt
maintainercover tracing: More fixes for 5.14
Fixes and clean ups to tracing:
- Fix warning for use of "main" variable in osnoise tracer
- Fix header alignment when PREEMPT_RT is enabled for osnoise tracer
- Inject "stop" event to see where osnoise stopped the trace
- Define DYNAMIC_FTRACE_WITH_ARGS as some code had an #ifdef for it
- Fix erroneous message for bootconfig cmdline parameter
- Fix crash caused by not found variable in histograms
Daniel Bristot de Oliveira (4):
trace/osnoise: Rename main variable to tracer_main trace/osnoise: Add a header with PREEMPT_RT additional fields trace/timerlat: Add a header with PREEMPT_RT additional fields trace/osnoise: Print a stop tracing message
Lukas Bulwahn (1):
tracing: define needed config DYNAMIC_FTRACE_WITH_ARGS
Masami Hiramatsu (1):
init: Suppress wrong warning for bootconfig cmdline parameter
Steven Rostedt (VMware) (1):
tracing / histogram: Fix NULL pointer dereference on strcmp() on NULL event name
----
init/main.c | 9 ++++-- kernel/trace/Kconfig | 5 ++++ kernel/trace/trace_events_hist.c | 2 ++ kernel/trace/trace_osnoise.c | 62 +++++++++++++++++++++++++++++++++++++--- 4 files changed, 72 insertions(+), 6 deletions(-)
Steven Rostedt
maintainerPATCH 1/7 trace/osnoise: Rename main variable to tracer_main
From: Daniel Bristot de Oliveira <[email protected]>
The *main variable in start_kthread() is causing warnings in some compilers/analyzers. Although it is not necessarily a problem, it is not a problem changing the variable name too.
Rename the *main variable to *tracer_main.
No functional change.
--- kernel/trace/trace_osnoise.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-)
kernel/trace/trace_osnoise.c +3 -3
@@ -1458,20 +1458,20 @@ static void stop_per_cpu_kthreads(void)static int start_kthread (unsigned int cpu) {struct task_struct *kthread; -void *main = osnoise_main; +void *tracer_main = osnoise_main;char comm[24 ];#ifdef CONFIG_TIMERLAT_TRACER if (osnoise_data.timerlat_tracer) {snprintf (comm,24 ,"timerlat/%d" , cpu); - main = timerlat_main; + tracer_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); + kthread =kthread_create_on_cpu (tracer_main,NULL , cpu, comm);if (IS_ERR (kthread)) {pr_err (BANNER "could not start sampling thread\n" );
Signature · 1 line
2.30.2
Steven Rostedt
maintainerPATCH 2/7 trace/osnoise: Add a header with PREEMPT_RT additional fields
In reply to Steven RostedtFrom: Daniel Bristot de Oliveira <[email protected]>
Some extra flags are printed to the trace header when using the PREEMPT_RT config. The extra flags are: need-resched-lazy, preempt-lazy-depth, and migrate-disable.
Without printing these fields, the osnoise specific fields are shifted by three positions, for example:
# 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
# | | | |||| | | | | | | | | | |
<...>-741 [000] ....... 1105.690909: 1000000 234 99.97660 36 21 0 1001 22 3
<...>-742 [001] ....... 1105.691923: 1000000 281 99.97190 197 7 0 1012 35 14
<...>-743 [002] ....... 1105.691958: 1000000 1324 99.86760 118 11 0 1016 155 143
<...>-744 [003] ....... 1105.691998: 1000000 109 99.98910 21 4 0 1004 33 7
<...>-745 [004] ....... 1105.692015: 1000000 2023 99.79770 97 37 0 1023 52 18Add a new header for osnoise with the missing fields, to be used when the PREEMPT_RT is enabled.
--- kernel/trace/trace_osnoise.c | 31 +++++++++++++++++++++++++++++++ 1 file changed, 31 insertions(+)
kernel/trace/trace_osnoise.c +31 -0
@@ -253,10 +253,40 @@ static struct osnoise_data {*/ static bool osnoise_busy; +#ifdef CONFIG_PREEMPT_RT /* * Print the osnoise header info. */ static void print_osnoise_headers (struct seq_file *s) +{ +if (osnoise_data.tainted) +seq_puts (s,"# osnoise is tainted!\n" ); + +seq_puts (s,"# _-------=> irqs-off\n" ); +seq_puts (s,"# / _------=> need-resched\n" ); +seq_puts (s,"# | / _-----=> need-resched-lazy\n" ); +seq_puts (s,"# || / _----=> hardirq/softirq\n" ); +seq_puts (s,"# ||| / _---=> preempt-depth\n" ); +seq_puts (s,"# |||| / _--=> preempt-lazy-depth\n" ); +seq_puts (s,"# ||||| / _-=> migrate-disable\n" ); + +seq_puts (s,"# |||||| / " ); +seq_puts (s," MAX\n" ); + +seq_puts (s,"# ||||| / " ); +seq_puts (s," SINGLE Interference counters:\n" ); + +seq_puts (s,"# ||||||| RUNTIME " ); +seq_puts (s," NOISE %% OF CPU NOISE +-----------------------------+\n" ); + +seq_puts (s,"# TASK-PID CPU# ||||||| TIMESTAMP IN US " ); +seq_puts (s," IN US AVAILABLE IN US HW NMI IRQ SIRQ THREAD\n" ); + +seq_puts (s,"# | | | ||||||| | | " ); +seq_puts (s," | | | | | | | |\n" ); +} +#else /* CONFIG_PREEMPT_RT */ +static void print_osnoise_headers (struct seq_file *s) {if (osnoise_data.tainted)seq_puts (s,"# osnoise is tainted!\n" );
@@ -279,6 +309,7 @@ static void print_osnoise_headers(struct seq_file *s)seq_puts (s,"# | | | |||| | | " ); seq_puts(s, " | | | | | | | |\n"); } +#endif /* CONFIG_PREEMPT_RT */ /* * osnoise_taint - report an osnoise error.
Signature · 1 line
2.30.2
Steven Rostedt
maintainerPATCH 3/7 trace/timerlat: Add a header with PREEMPT_RT additional fields
In reply to Steven RostedtFrom: Daniel Bristot de Oliveira <[email protected]>
Some extra flags are printed to the trace header when using the PREEMPT_RT config. The extra flags are: need-resched-lazy, preempt-lazy-depth, and migrate-disable.
Without printing these fields, the timerlat specific fields are shifted by three positions, for example:
# tracer: timerlat
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# || /
# |||| ACTIVATION
# TASK-PID CPU# |||| TIMESTAMP ID CONTEXT LATENCY
# | | | |||| | | | |
<idle>-0 [000] d..h... 3279.798871: #1 context irq timer_latency 830 ns
<...>-807 [000] ....... 3279.798881: #1 context thread timer_latency 11301 nsAdd a new header for timerlat with the missing fields, to be used when the PREEMPT_RT is enabled.
--- kernel/trace/trace_osnoise.c | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+)
kernel/trace/trace_osnoise.c +19 -0
@@ -354,6 +354,24 @@ static void trace_osnoise_sample(struct osnoise_sample *sample)/* * Print the timerlat header info. */ +#ifdef CONFIG_PREEMPT_RT +static void print_timerlat_headers (struct seq_file *s) +{ +seq_puts (s,"# _-------=> irqs-off\n" ); +seq_puts (s,"# / _------=> need-resched\n" ); +seq_puts (s,"# | / _-----=> need-resched-lazy\n" ); +seq_puts (s,"# || / _----=> hardirq/softirq\n" ); +seq_puts (s,"# ||| / _---=> preempt-depth\n" ); +seq_puts (s,"# |||| / _--=> preempt-lazy-depth\n" ); +seq_puts (s,"# ||||| / _-=> migrate-disable\n" ); +seq_puts (s,"# |||||| /\n" ); +seq_puts (s,"# ||||||| ACTIVATION\n" ); +seq_puts (s,"# TASK-PID CPU# ||||||| TIMESTAMP ID " ); +seq_puts (s," CONTEXT LATENCY\n" ); +seq_puts (s,"# | | | ||||||| | | " ); +seq_puts (s," | |\n" ); +} +#else /* CONFIG_PREEMPT_RT */ static void print_timerlat_headers (struct seq_file *s) {seq_puts (s,"# _-----=> irqs-off\n" );
@@ -367,6 +385,7 @@ static void print_timerlat_headers(struct seq_file *s)seq_puts (s,"# | | | |||| | | " ); seq_puts(s, " | |\n"); } +#endif /* CONFIG_PREEMPT_RT */ /* * Record an timerlat_sample into the tracer buffer.
Signature · 1 line
2.30.2
Steven Rostedt
maintainerPATCH 4/7 trace/osnoise: Print a stop tracing message
In reply to Steven RostedtFrom: Daniel Bristot de Oliveira <[email protected]>
When using osnoise/timerlat with stop tracing, sometimes it is not clear in which CPU the stop condition was hit, mainly when using some extra events.
Print a message informing in which CPU the trace stopped, like in the example below:
<idle>-0 [006] d.h. 2932.676616: #1672599 context irq timer_latency 34689 ns
<idle>-0 [006] dNh. 2932.676618: irq_noise: local_timer:236 start 2932.676615639 duration 2391 ns
<idle>-0 [006] dNh. 2932.676620: irq_noise: virtio0-output.0:47 start 2932.676620180 duration 86 ns
<idle>-0 [003] d.h. 2932.676621: #1673374 context irq timer_latency 1200 ns
<idle>-0 [006] d... 2932.676623: thread_noise: swapper/6:0 start 2932.676615964 duration 4339 ns
<idle>-0 [003] dNh. 2932.676623: irq_noise: local_timer:236 start 2932.676620597 duration 1881 ns
<idle>-0 [006] d... 2932.676623: sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=timerlat/6 next_pid=852 next_prio=4
timerlat/6-852 [006] .... 2932.676623: #1672599 context thread timer_latency 41931 ns
<idle>-0 [003] d... 2932.676623: thread_noise: swapper/3:0 start 2932.676620854 duration 880 ns
<idle>-0 [003] d... 2932.676624: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=timerlat/3 next_pid=849 next_prio=4
timerlat/6-852 [006] .... 2932.676624: timerlat_main: stop tracing hit on cpu 6
timerlat/3-849 [003] .... 2932.676624: #1673374 context thread timer_latency 4310 ns--- kernel/trace/trace_osnoise.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-)
kernel/trace/trace_osnoise.c +5 -1
@@ -1075,9 +1075,13 @@ diff_osn_sample_stats(struct osnoise_variables *osn_var, struct osnoise_sample */* * osnoise_stop_tracing - Stop tracing and the tracer. */ -static void osnoise_stop_tracing (void ) +static __always_inline void osnoise_stop_tracing(void) {struct trace_array *tr = osnoise_trace; + +trace_array_printk_buf (tr->array_buffer.buffer, _THIS_IP_, +"stop tracing hit on cpu %d\n" ,smp_processor_id ()); +tracer_tracing_off (tr); }
Signature · 1 line
2.30.2
Steven Rostedt
maintainerPATCH 5/7 tracing: define needed config DYNAMIC_FTRACE_WITH_ARGS
In reply to Steven RostedtFrom: Lukas Bulwahn <[email protected]>
Commit 2860cd8a2353 ("livepatch: Use the default ftrace_ops instead of REGS when ARGS is available") intends to enable config LIVEPATCH when ftrace with ARGS is available. However, the chain of configs to enable LIVEPATCH is incomplete, as HAVE_DYNAMIC_FTRACE_WITH_ARGS is available, but the definition of DYNAMIC_FTRACE_WITH_ARGS, combining DYNAMIC_FTRACE and HAVE_DYNAMIC_FTRACE_WITH_ARGS, needed to enable LIVEPATCH, is missing in the commit.
Fortunately, ./scripts/checkkconfigsymbols.py detects this and warns:
DYNAMIC_FTRACE_WITH_ARGS
Referencing files: kernel/livepatch/Kconfig
So, define the config DYNAMIC_FTRACE_WITH_ARGS analogously to the already existing similar configs, DYNAMIC_FTRACE_WITH_REGS and DYNAMIC_FTRACE_WITH_DIRECT_CALLS, in ./kernel/trace/Kconfig to connect the chain of configs.
--- kernel/trace/Kconfig | 5 +++++ 1 file changed, 5 insertions(+)
kernel/trace/Kconfig +5 -0
@@ -219,6 +219,11 @@ config DYNAMIC_FTRACE_WITH_DIRECT_CALLS depends on DYNAMIC_FTRACE_WITH_REGS depends on HAVE_DYNAMIC_FTRACE_WITH_DIRECT_CALLS +config DYNAMIC_FTRACE_WITH_ARGS + def_bool y + depends on DYNAMIC_FTRACE + depends on HAVE_DYNAMIC_FTRACE_WITH_ARGS + config FUNCTION_PROFILER bool "Kernel function profiler" depends on FUNCTION_TRACER
Signature · 1 line
2.30.2
Steven Rostedt
maintainerPATCH 6/7 init: Suppress wrong warning for bootconfig cmdline parameter
In reply to Steven RostedtFrom: Masami Hiramatsu <[email protected]>
Since the 'bootconfig' command line parameter is handled before parsing the command line, it doesn't use early_param(). But in this case, kernel shows a wrong warning message about it.
[ 0.013714] Kernel command line: ro console=ttyS0 bootconfig console=tty0 [ 0.013741] Unknown command line parameters: bootconfig
To suppress this message, add a dummy handler for 'bootconfig'.
--- init/main.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-)
init/main.c +7 -2
@@ -397,6 +397,12 @@ static int __init bootconfig_params(char *param, char *val,return 0 ; } +static int __init warn_bootconfig (char *str) +{ +/* The 'bootconfig' has been handled by bootconfig_params(). */ +return 0 ; +} +static void __init setup_boot_config (void ) {static char tmp_cmdline[COMMAND_LINE_SIZE ]__initdata ;
@@ -475,9 +481,8 @@ static int __init warn_bootconfig(char *str)pr_warn ("WARNING: 'bootconfig' found on the kernel command line but CONFIG_BOOT_CONFIG is not set.\n" ); return 0; } -early_param ("bootconfig" , warn_bootconfig); -#endif +early_param ("bootconfig" , warn_bootconfig);/* Change NUL term back to "=", to make "param" the whole string. */ static void __init repair_env_string (char *param,char *val)
Signature · 1 line
2.30.2
Steven Rostedt
maintainerPATCH 7/7 tracing / histogram: Fix NULL pointer dereference on strcmp() on NULL event name
In reply to Steven RostedtFrom: "Steven Rostedt (VMware)" <[email protected]>
The following commands:
# echo 'read_max u64 size;' > synthetic_events # echo 'hist:keys=common_pid:count=count:onmax($count).trace(read_max,count)' > events/syscalls/sys_enter_read/trigger
Causes:
BUG: kernel NULL pointer dereference, address: 0000000000000000 #PF: supervisor read access in kernel mode #PF: error_code(0x0000) - not-present page PGD 0 P4D 0 Oops: 0000 [#1] PREEMPT SMP CPU: 4 PID: 1763 Comm: bash Not tainted 5.14.0-rc2-test+ #155 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016 RIP: 0010:strcmp+0xc/0x20 Code: 75 f7 31 c0 0f b6 0c 06 88 0c 02 48 83 c0 01 84 c9 75 f1 4c 89 c0
c3 0f 1f 80 00 00 00 00 31 c0 eb 08 48 83 c0 01 84 d2 74 0f <0f> b6 14 07 3a 14 06 74 ef 19 c0 83 c8 01 c3 31 c0 c3 66 90 48 89
RSP: 0018:ffffb5fdc0963ca8 EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffffffffb3a4e040 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffff9714c0d0b640 RDI: 0000000000000000
RBP: 0000000000000000 R08: 00000022986b7cde R09: ffffffffb3a4dff8
R10: 0000000000000000 R11: 0000000000000000 R12: ffff9714c50603c8
R13: 0000000000000000 R14: ffff97143fdf9e48 R15: ffff9714c01a2210
FS: 00007f1fa6785740(0000) GS:ffff9714da400000(0000)
knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 000000002d863004 CR4: 00000000001706e0
Call Trace: __find_event_file+0x4e/0x80 action_create+0x6b7/0xeb0 ? kstrdup+0x44/0x60 event_hist_trigger_func+0x1a07/0x2130 trigger_process_regex+0xbd/0x110 event_trigger_write+0x71/0xd0 vfs_write+0xe9/0x310 ksys_write+0x68/0xe0 do_syscall_64+0x3b/0x90 entry_SYSCALL_64_after_hwframe+0x44/0xae RIP: 0033:0x7f1fa6879e87
The problem was the "trace(read_max,count)" where the "count" should be "$count" as "onmax()" only handles variables (although it really should be able to figure out that "count" is a field of sys_enter_read). But there's a path that does not find the variable and ends up passing a NULL for the event, which ends up getting passed to "strcmp()".
Add a check for NULL to return and error on the command with:
# cat error_log
hist:syscalls:sys_enter_read: error: Couldn't create or find variable
Command: hist:keys=common_pid:count=count:onmax($count).trace(read_max,count)
^
Link: https://lkml.kernel.org/r/[email protected]--- kernel/trace/trace_events_hist.c | 2 ++ 1 file changed, 2 insertions(+)
kernel/trace/trace_events_hist.c +2 -0
@@ -3430,6 +3430,8 @@ trace_action_create_field_var(struct hist_trigger_data *hist_data, event = data->match_data.event; } +if (!event) + goto free;/* * At this point, we're looking at a field on another * event. Because we can't modify a hist trigger on
Signature · 1 line
2.30.2