tracing: Have show_event_trigger/filter format a bit more in columns

[PATCH] tracing: Have show_event_trigger/filter format a bit more in columns

Posted by Steven Rostedt 3 weeks, 5 days ago

From: Steven Rostedt <rostedt@goodmis.org>

By doing:

 # trace-cmd sqlhist -e -n futex_wait select TIMESTAMP_DELTA_USECS as lat from sys_enter_futex as start join sys_exit_futex as end on start.common_pid = end.common_pid

and

 # trace-cmd start -e futex_wait -f 'lat > 100' -e page_pool_state_release -f 'pfn == 1'

The output of the show_event_trigger and show_event_filter files are well
aligned because of the inconsistent 'tab' spacing:

 ~# cat /sys/kernel/tracing/show_event_triggers
syscalls:sys_exit_futex	hist:keys=common_pid:vals=hitcount:__lat_12046_2=common_timestamp.usecs-$__arg_12046_1:sort=hitcount:size=2048:clock=global:onmatch(syscalls.sys_enter_futex).trace(futex_wait,$__lat_12046_2) [active]
syscalls:sys_enter_futex	hist:keys=common_pid:vals=hitcount:__arg_12046_1=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]

 ~# cat /sys/kernel/tracing/show_event_filters
synthetic:futex_wait	(lat > 100)
page_pool:page_pool_state_release	(pfn == 1)

This makes it not so easy to read. Instead, force the spacing to be at
least 32 bytes from the beginning (one space if the system:event is longer
than 30 bytes):

 ~# cat /sys/kernel/tracing/show_event_triggers
syscalls:sys_exit_futex          hist:keys=common_pid:vals=hitcount:__lat_8125_2=common_timestamp.usecs-$__arg_8125_1:sort=hitcount:size=2048:clock=global:onmatch(syscalls.sys_enter_futex).trace(futex_wait,$__lat_8125_2) [active]
syscalls:sys_enter_futex         hist:keys=common_pid:vals=hitcount:__arg_8125_1=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]

 ~# cat /sys/kernel/tracing/show_event_filters
synthetic:futex_wait             (lat > 100)
page_pool:page_pool_state_release (pfn == 1)

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
[
  This is based on top of these patches:
    https://lore.kernel.org/linux-trace-kernel/20260105142939.2655342-1-atomlin@atomlin.com/
]
 kernel/trace/trace_events.c | 26 ++++++++++++++++++++++----
 1 file changed, 22 insertions(+), 4 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 36936697fa2a..f372a6374164 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1662,6 +1662,18 @@ static void t_stop(struct seq_file *m, void *p)
 	mutex_unlock(&event_mutex);
 }
 
+static int get_call_len(struct trace_event_call *call)
+{
+	int len;
+
+	/* Get the length of "<system>:<event>" */
+	len = strlen(call->class->system) + 1;
+	len += strlen(trace_event_name(call));
+
+	/* Set the index to 32 bytes to separate event from data */
+	return len >= 32 ? 1 : 32 - len;
+}
+
 /**
  * t_show_filters - seq_file callback to display active event filters
  * @m: The seq_file interface for formatted output
@@ -1676,14 +1688,17 @@ static int t_show_filters(struct seq_file *m, void *v)
 	struct trace_event_file *file = v;
 	struct trace_event_call *call = file->event_call;
 	struct event_filter *filter;
+	int len;
 
 	guard(rcu)();
 	filter = rcu_dereference(file->filter);
 	if (!filter || !filter->filter_string)
 		return 0;
 
-	seq_printf(m, "%s:%s\t%s\n", call->class->system,
-		   trace_event_name(call), filter->filter_string);
+	len = get_call_len(call);
+
+	seq_printf(m, "%s:%s%*.s%s\n", call->class->system,
+		   trace_event_name(call), len, "", filter->filter_string);
 
 	return 0;
 }
@@ -1702,6 +1717,7 @@ static int t_show_triggers(struct seq_file *m, void *v)
 	struct trace_event_file *file = v;
 	struct trace_event_call *call = file->event_call;
 	struct event_trigger_data *data;
+	int len;
 
 	/*
 	 * The event_mutex is held by t_start(), protecting the
@@ -1710,9 +1726,11 @@ static int t_show_triggers(struct seq_file *m, void *v)
 	if (list_empty(&file->triggers))
 		return 0;
 
+	len = get_call_len(call);
+
 	list_for_each_entry_rcu(data, &file->triggers, list) {
-		seq_printf(m, "%s:%s\t", call->class->system,
-			   trace_event_name(call));
+		seq_printf(m, "%s:%s%*.s", call->class->system,
+			   trace_event_name(call), len, "");
 
 		data->cmd_ops->print(m, data);
 	}
-- 
2.51.0

Re: [PATCH] tracing: Have show_event_trigger/filter format a bit more in columns

Posted by Masami Hiramatsu (Google) 3 weeks, 4 days ago

On Mon, 12 Jan 2026 15:34:08 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: Steven Rostedt <rostedt@goodmis.org>
> 
> By doing:
> 
>  # trace-cmd sqlhist -e -n futex_wait select TIMESTAMP_DELTA_USECS as lat from sys_enter_futex as start join sys_exit_futex as end on start.common_pid = end.common_pid
> 
> and
> 
>  # trace-cmd start -e futex_wait -f 'lat > 100' -e page_pool_state_release -f 'pfn == 1'
> 
> The output of the show_event_trigger and show_event_filter files are well
> aligned because of the inconsistent 'tab' spacing:
> 
>  ~# cat /sys/kernel/tracing/show_event_triggers
> syscalls:sys_exit_futex	hist:keys=common_pid:vals=hitcount:__lat_12046_2=common_timestamp.usecs-$__arg_12046_1:sort=hitcount:size=2048:clock=global:onmatch(syscalls.sys_enter_futex).trace(futex_wait,$__lat_12046_2) [active]
> syscalls:sys_enter_futex	hist:keys=common_pid:vals=hitcount:__arg_12046_1=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
> 
>  ~# cat /sys/kernel/tracing/show_event_filters
> synthetic:futex_wait	(lat > 100)
> page_pool:page_pool_state_release	(pfn == 1)
> 
> This makes it not so easy to read. Instead, force the spacing to be at
> least 32 bytes from the beginning (one space if the system:event is longer
> than 30 bytes):
> 
>  ~# cat /sys/kernel/tracing/show_event_triggers
> syscalls:sys_exit_futex          hist:keys=common_pid:vals=hitcount:__lat_8125_2=common_timestamp.usecs-$__arg_8125_1:sort=hitcount:size=2048:clock=global:onmatch(syscalls.sys_enter_futex).trace(futex_wait,$__lat_8125_2) [active]
> syscalls:sys_enter_futex         hist:keys=common_pid:vals=hitcount:__arg_8125_1=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
> 
>  ~# cat /sys/kernel/tracing/show_event_filters
> synthetic:futex_wait             (lat > 100)
> page_pool:page_pool_state_release (pfn == 1)
> 
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Looks good to me.

Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Thanks,

> ---
> [
>   This is based on top of these patches:
>     https://lore.kernel.org/linux-trace-kernel/20260105142939.2655342-1-atomlin@atomlin.com/
> ]
>  kernel/trace/trace_events.c | 26 ++++++++++++++++++++++----
>  1 file changed, 22 insertions(+), 4 deletions(-)
> 
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 36936697fa2a..f372a6374164 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -1662,6 +1662,18 @@ static void t_stop(struct seq_file *m, void *p)
>  	mutex_unlock(&event_mutex);
>  }
>  
> +static int get_call_len(struct trace_event_call *call)
> +{
> +	int len;
> +
> +	/* Get the length of "<system>:<event>" */
> +	len = strlen(call->class->system) + 1;
> +	len += strlen(trace_event_name(call));
> +
> +	/* Set the index to 32 bytes to separate event from data */
> +	return len >= 32 ? 1 : 32 - len;
> +}
> +
>  /**
>   * t_show_filters - seq_file callback to display active event filters
>   * @m: The seq_file interface for formatted output
> @@ -1676,14 +1688,17 @@ static int t_show_filters(struct seq_file *m, void *v)
>  	struct trace_event_file *file = v;
>  	struct trace_event_call *call = file->event_call;
>  	struct event_filter *filter;
> +	int len;
>  
>  	guard(rcu)();
>  	filter = rcu_dereference(file->filter);
>  	if (!filter || !filter->filter_string)
>  		return 0;
>  
> -	seq_printf(m, "%s:%s\t%s\n", call->class->system,
> -		   trace_event_name(call), filter->filter_string);
> +	len = get_call_len(call);
> +
> +	seq_printf(m, "%s:%s%*.s%s\n", call->class->system,
> +		   trace_event_name(call), len, "", filter->filter_string);
>  
>  	return 0;
>  }
> @@ -1702,6 +1717,7 @@ static int t_show_triggers(struct seq_file *m, void *v)
>  	struct trace_event_file *file = v;
>  	struct trace_event_call *call = file->event_call;
>  	struct event_trigger_data *data;
> +	int len;
>  
>  	/*
>  	 * The event_mutex is held by t_start(), protecting the
> @@ -1710,9 +1726,11 @@ static int t_show_triggers(struct seq_file *m, void *v)
>  	if (list_empty(&file->triggers))
>  		return 0;
>  
> +	len = get_call_len(call);
> +
>  	list_for_each_entry_rcu(data, &file->triggers, list) {
> -		seq_printf(m, "%s:%s\t", call->class->system,
> -			   trace_event_name(call));
> +		seq_printf(m, "%s:%s%*.s", call->class->system,
> +			   trace_event_name(call), len, "");
>  
>  		data->cmd_ops->print(m, data);
>  	}
> -- 
> 2.51.0
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH] tracing: Have show_event_trigger/filter format a bit more in columns

Posted by Aaron Tomlin 3 weeks, 5 days ago

On Mon, Jan 12, 2026 at 03:34:08PM -0500, Steven Rostedt wrote:
> From: Steven Rostedt <rostedt@goodmis.org>
> 
> By doing:
> 
>  # trace-cmd sqlhist -e -n futex_wait select TIMESTAMP_DELTA_USECS as lat from sys_enter_futex as start join sys_exit_futex as end on start.common_pid = end.common_pid
> 
> and
> 
>  # trace-cmd start -e futex_wait -f 'lat > 100' -e page_pool_state_release -f 'pfn == 1'
> 
> The output of the show_event_trigger and show_event_filter files are well
> aligned because of the inconsistent 'tab' spacing:
> 
>  ~# cat /sys/kernel/tracing/show_event_triggers
> syscalls:sys_exit_futex	hist:keys=common_pid:vals=hitcount:__lat_12046_2=common_timestamp.usecs-$__arg_12046_1:sort=hitcount:size=2048:clock=global:onmatch(syscalls.sys_enter_futex).trace(futex_wait,$__lat_12046_2) [active]
> syscalls:sys_enter_futex	hist:keys=common_pid:vals=hitcount:__arg_12046_1=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
> 
>  ~# cat /sys/kernel/tracing/show_event_filters
> synthetic:futex_wait	(lat > 100)
> page_pool:page_pool_state_release	(pfn == 1)
> 
> This makes it not so easy to read. Instead, force the spacing to be at
> least 32 bytes from the beginning (one space if the system:event is longer
> than 30 bytes):
> 
>  ~# cat /sys/kernel/tracing/show_event_triggers
> syscalls:sys_exit_futex          hist:keys=common_pid:vals=hitcount:__lat_8125_2=common_timestamp.usecs-$__arg_8125_1:sort=hitcount:size=2048:clock=global:onmatch(syscalls.sys_enter_futex).trace(futex_wait,$__lat_8125_2) [active]
> syscalls:sys_enter_futex         hist:keys=common_pid:vals=hitcount:__arg_8125_1=common_timestamp.usecs:sort=hitcount:size=2048:clock=global [active]
> 
>  ~# cat /sys/kernel/tracing/show_event_filters
> synthetic:futex_wait             (lat > 100)
> page_pool:page_pool_state_release (pfn == 1)
> 
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> ---
> [
>   This is based on top of these patches:
>     https://lore.kernel.org/linux-trace-kernel/20260105142939.2655342-1-atomlin@atomlin.com/
> ]
>  kernel/trace/trace_events.c | 26 ++++++++++++++++++++++----
>  1 file changed, 22 insertions(+), 4 deletions(-)
> 
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 36936697fa2a..f372a6374164 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -1662,6 +1662,18 @@ static void t_stop(struct seq_file *m, void *p)
>  	mutex_unlock(&event_mutex);
>  }
>  
> +static int get_call_len(struct trace_event_call *call)
> +{
> +	int len;
> +
> +	/* Get the length of "<system>:<event>" */
> +	len = strlen(call->class->system) + 1;
> +	len += strlen(trace_event_name(call));
> +
> +	/* Set the index to 32 bytes to separate event from data */
> +	return len >= 32 ? 1 : 32 - len;
> +}
> +
>  /**
>   * t_show_filters - seq_file callback to display active event filters
>   * @m: The seq_file interface for formatted output
> @@ -1676,14 +1688,17 @@ static int t_show_filters(struct seq_file *m, void *v)
>  	struct trace_event_file *file = v;
>  	struct trace_event_call *call = file->event_call;
>  	struct event_filter *filter;
> +	int len;
>  
>  	guard(rcu)();
>  	filter = rcu_dereference(file->filter);
>  	if (!filter || !filter->filter_string)
>  		return 0;
>  
> -	seq_printf(m, "%s:%s\t%s\n", call->class->system,
> -		   trace_event_name(call), filter->filter_string);
> +	len = get_call_len(call);
> +
> +	seq_printf(m, "%s:%s%*.s%s\n", call->class->system,
> +		   trace_event_name(call), len, "", filter->filter_string);
>  
>  	return 0;
>  }
> @@ -1702,6 +1717,7 @@ static int t_show_triggers(struct seq_file *m, void *v)
>  	struct trace_event_file *file = v;
>  	struct trace_event_call *call = file->event_call;
>  	struct event_trigger_data *data;
> +	int len;
>  
>  	/*
>  	 * The event_mutex is held by t_start(), protecting the
> @@ -1710,9 +1726,11 @@ static int t_show_triggers(struct seq_file *m, void *v)
>  	if (list_empty(&file->triggers))
>  		return 0;
>  
> +	len = get_call_len(call);
> +
>  	list_for_each_entry_rcu(data, &file->triggers, list) {
> -		seq_printf(m, "%s:%s\t", call->class->system,
> -			   trace_event_name(call));
> +		seq_printf(m, "%s:%s%*.s", call->class->system,
> +			   trace_event_name(call), len, "");
>  
>  		data->cmd_ops->print(m, data);
>  	}
> -- 
> 2.51.0
> 

Nice!

Reviewed-by: Aaron Tomlin <atomlin@atomlin.com>

-- 
Aaron Tomlin