linux-trace-devel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save'
@ 2021-08-13  2:16 Steven Rostedt
  2021-08-13  2:16 ` [PATCH 1/7] libtracefs: Move creating of onmatch handler and trace action into helper functions Steven Rostedt
                   ` (6 more replies)
  0 siblings, 7 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add the following APIs that now allow to perform 'onmax' and 'onchange'
handlers with the 'trace', 'snapshot' and 'save' actions for synthetic
events.

   tracefs_synth_trace()
   tracefs_synth_snapshot()
   tracefs_synth_save()

Also, update the sqlhist tool in the tracefs_sql(3) man page to have more
features, as well as give it its own man page!

With the above API sqlhist has been exapanded to customize latency tracing.

By using the full SQL language, synthetic events can be made and processed.
For example, using sqlhist along with trace-cmd, wake up latency can be
recorded by creating a synthetic event by attaching the sched_waking and the
sched_switch events.

 # sqlhist -n wakeup_lat -e -T -m lat 'SELECT end.next_comm AS comm, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM ' \
    'sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid WHERE end.next_prio < 100 && end.next_comm == "cyclictest"'

 # trace-cmd start -e all -e wakeup_lat -R stacktrace

 # cyclictest -l 1000 -p80 -i250  -a -t -q -m -d 0 -b 1000 --tracemark

 # trace-cmd show -s | tail -30
         <idle>-0       [002] dNh4 23454.902246: sched_wakeup: comm=cyclictest pid=12272 prio=120 target_cpu=002
         <idle>-0       [005] ...1 23454.902246: cpu_idle: state=4294967295 cpu_id=5
         <idle>-0       [007] d..1 23454.902246: cpu_idle: state=0 cpu_id=7
         <idle>-0       [002] dNh1 23454.902247: hrtimer_expire_exit: hrtimer=0000000037956dc2
         <idle>-0       [005] d..1 23454.902248: cpu_idle: state=0 cpu_id=5
         <idle>-0       [002] dNh1 23454.902248: write_msr: 6e0, value 4866ce957272
         <idle>-0       [006] ...1 23454.902248: cpu_idle: state=4294967295 cpu_id=6
         <idle>-0       [002] dNh1 23454.902249: local_timer_exit: vector=236
         <idle>-0       [006] d..1 23454.902250: cpu_idle: state=0 cpu_id=6
         <idle>-0       [002] .N.1 23454.902250: cpu_idle: state=4294967295 cpu_id=2
         <idle>-0       [002] dN.1 23454.902251: rcu_utilization: Start context switch
         <idle>-0       [002] dN.1 23454.902252: rcu_utilization: End context switch
         <idle>-0       [001] ...1 23454.902252: cpu_idle: state=4294967295 cpu_id=1
         <idle>-0       [002] dN.3 23454.902253: prandom_u32: ret=3692516021
         <idle>-0       [001] d..1 23454.902254: cpu_idle: state=0 cpu_id=1
         <idle>-0       [002] d..2 23454.902254: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=12275 next_prio=19
         <idle>-0       [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17
         <idle>-0       [002] d..5 23454.902258: <stack trace>
=> trace_event_raw_event_synth
=> action_trace
=> event_hist_trigger
=> event_triggers_call
=> trace_event_buffer_commit
=> trace_event_raw_event_sched_switch
=> __traceiter_sched_switch
=> __schedule
=> schedule_idle
=> do_idle
=> cpu_startup_entry
=> secondary_startup_64_no_verify

Here’s the options for sqlhist explained:

-n wakeup_lat
    Name the synthetic event to use wakeup_lat.

-e
    Execute the commands that are printed.

-T
    Perform both a trace action and then a snapshot action (swap the buffer
    into the static snapshot buffer).

-m lat
    Trigger the actions whenever lat hits a new maximum value.

Now a breakdown of the SQL statement:

     'SELECT end.next_comm AS comm, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM ' \
        'sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid WHERE end.next_prio < 100 && end.next_comm == "cyclictest"'

end.next_comm AS comm
    Save the sched_switch field next_comm and place it into the comm field
    of the wakeup_lat synthetic event.

(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat
    Take the delta of the time stamps from the sched_switch event and the
    sched_waking event. As time stamps are usually recorded in nanoseconds,
    TIMESTAMP would give the full nanosecond time stamp, but here, the
    TIMESTAMP_USECS will truncate it into microseconds. The value is saved in
    the variable lat, which will also be recorded in the synthetic event.

FROM sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid
    Create the synthetic event by joining sched_waking to sched_switch,
    matching the sched_waking pid field with the sched_switch next_pid field.
    Also make start an alias for sched_waking and end an alias for sched_switch
    which then an use start and end as a subsitute for sched_waking and
    sched_switch respectively through out the rest of the SQL statement.

WHERE end.next_prio < 100 && end.next_comm == "cyclictest"
    Filter the logic where it executes only if sched_waking next_prio field
    is less than 100. (Note, in the Kernel, priorities are inverse, and the
    real-time priorities are represented from 0-100 where 0 is the highest
    priority). Also only trace when the next_comm (the task scheduling in) of
    the sched_switch event has the name "cyclictest".

For the trace-cmd(3) command:

       trace-cmd start -e all -e wakeup_lat -R stacktrace

trace-cmd start
    Enables tracing (does not record to a file).

-e all
    Enable all events

-e wakeup_lat -R stacktrace
    have the "wakeup_lat" event (our synthetic event) enable the stacktrace
    trigger, were for every instance of the "wakeup_lat" event, a kernel stack
    trace will be recorded in the ring buffer.

After calling cyclictest (a real-time tool to measure wakeup latency), read
the snapshot buffer.

trace-cmd show -s
    trace-cmd show reads the kernel ring buffer, and the -s option will read
    the snapshot buffer instead of the normal one.

     <idle>-0       [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17

We see on the "wakeup_lat" event happened on CPU 2, with a wake up latency
17 microseconds.

This can be extracted into a trace.dat file that trace-cmd(3) can read and
do further analysis, as well as kernelshark.

        # trace-cmd extract -s
        # trace-cmd report --cpu 2 | tail -30
              <idle>-0     [002] 23454.902238: prandom_u32:          ret=1633425088
              <idle>-0     [002] 23454.902239: sched_wakeup:         cyclictest:12275 [19] CPU:002
              <idle>-0     [002] 23454.902241: hrtimer_expire_exit:  hrtimer=0xffffbbd68286fe60
              <idle>-0     [002] 23454.902241: hrtimer_cancel:       hrtimer=0xffffbbd6826efe70
              <idle>-0     [002] 23454.902242: hrtimer_expire_entry: hrtimer=0xffffbbd6826efe70 now=23455294430750 function=hrtimer_wakeup/0x0
              <idle>-0     [002] 23454.902243: sched_waking:         comm=cyclictest pid=12272 prio=120 target_cpu=002
              <idle>-0     [002] 23454.902244: prandom_u32:          ret=1102749734
              <idle>-0     [002] 23454.902246: sched_wakeup:         cyclictest:12272 [120] CPU:002
              <idle>-0     [002] 23454.902247: hrtimer_expire_exit:  hrtimer=0xffffbbd6826efe70
              <idle>-0     [002] 23454.902248: write_msr:            6e0, value 4866ce957272
              <idle>-0     [002] 23454.902249: local_timer_exit:     vector=236
              <idle>-0     [002] 23454.902250: cpu_idle:             state=4294967295 cpu_id=2
              <idle>-0     [002] 23454.902251: rcu_utilization:      Start context switch
              <idle>-0     [002] 23454.902252: rcu_utilization:      End context switch
              <idle>-0     [002] 23454.902253: prandom_u32:          ret=3692516021
              <idle>-0     [002] 23454.902254: sched_switch:         swapper/2:0 [120] R ==> cyclictest:12275 [19]
              <idle>-0     [002] 23454.902256: wakeup_lat:           next_comm=cyclictest lat=17
              <idle>-0     [002] 23454.902258: kernel_stack:         <stack trace >
    => trace_event_raw_event_synth (ffffffff8121a0db)
    => action_trace (ffffffff8121e9fb)
    => event_hist_trigger (ffffffff8121ca8d)
    => event_triggers_call (ffffffff81216c72)
    => trace_event_buffer_commit (ffffffff811f7618)
    => trace_event_raw_event_sched_switch (ffffffff8110fda4)
    => __traceiter_sched_switch (ffffffff8110d449)
    => __schedule (ffffffff81c02002)
    => schedule_idle (ffffffff81c02c86)
    => do_idle (ffffffff8111e898)
    => cpu_startup_entry (ffffffff8111eba9)
    => secondary_startup_64_no_verify (ffffffff81000107)

Steven Rostedt (VMware) (7):
  libtracefs: Move creating of onmatch handler and trace action into
    helper functions
  libtracefs: Add logic to apply actions to synthetic events
  libtracefs: Add API tracefs_synth_trace()
  libtracefs: Add API tracefs_synth_snapshot()
  libtracefs: Add API tracefs_synth_save()
  libtracefs: Update the libtracefs-sql man page for the new
    tracefs_synth APIs
  libtracefs: Make a man page for the sqlhist man page example

 Documentation/Makefile                 |  53 +++-
 Documentation/libtracefs-sql.txt       | 107 +++++++-
 Documentation/libtracefs-sqlhist.txt.1 | 351 +++++++++++++++++++++++++
 Documentation/libtracefs-synth2.txt    |  37 ++-
 include/tracefs.h                      |  14 +
 src/tracefs-hist.c                     | 304 ++++++++++++++++++++-
 6 files changed, 838 insertions(+), 28 deletions(-)
 create mode 100644 Documentation/libtracefs-sqlhist.txt.1

-- 
2.30.2


^ permalink raw reply	[flat|nested] 8+ messages in thread

* [PATCH 1/7] libtracefs: Move creating of onmatch handler and trace action into helper functions
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  2021-08-13  2:16 ` [PATCH 2/7] libtracefs: Add logic to apply actions to synthetic events Steven Rostedt
                   ` (5 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Have the creation of the onmatch handler and the trace action both be in
their own helper function. This will help when adding other handlers
like onmax and onchange as well as other actions like snapshot and save.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 src/tracefs-hist.c | 38 +++++++++++++++++++++++++-------------
 1 file changed, 25 insertions(+), 13 deletions(-)

diff --git a/src/tracefs-hist.c b/src/tracefs-hist.c
index fefe251995ba..7fffa6cc653d 100644
--- a/src/tracefs-hist.c
+++ b/src/tracefs-hist.c
@@ -1378,28 +1378,40 @@ static char *create_hist(char **keys, char **vars)
 	return hist;
 }
 
-static char *create_end_hist(struct tracefs_synth *synth)
+static char *create_onmatch(char *hist, struct tracefs_synth *synth)
 {
-	const char *name;
-	char *end_hist;
+	hist = append_string(hist, NULL, ":onmatch(");
+	hist = append_string(hist, NULL, synth->start_event->system);
+	hist = append_string(hist, NULL, ".");
+	hist = append_string(hist, NULL, synth->start_event->name);
+	return append_string(hist, NULL, ")");
+}
+
+static char *create_trace(char *hist, struct tracefs_synth *synth)
+{
+	char *name;
 	int i;
 
-	end_hist = create_hist(synth->end_keys, synth->end_vars);
-	end_hist = append_string(end_hist, NULL, ":onmatch(");
-	end_hist = append_string(end_hist, NULL, synth->start_event->system);
-	end_hist = append_string(end_hist, NULL, ".");
-	end_hist = append_string(end_hist, NULL, synth->start_event->name);
-	end_hist = append_string(end_hist, NULL, ").trace(");
-	end_hist = append_string(end_hist, NULL, synth->name);
+	hist = append_string(hist, NULL, ".trace(");
+	hist = append_string(hist, NULL, synth->name);
 
 	for (i = 0; synth->synthetic_args && synth->synthetic_args[i]; i++) {
 		name = synth->synthetic_args[i];
 
-		end_hist = append_string(end_hist, NULL, ",");
-		end_hist = append_string(end_hist, NULL, name);
+		hist = append_string(hist, NULL, ",");
+		hist = append_string(hist, NULL, name);
 	}
 
-	return append_string(end_hist, NULL, ")");
+	return append_string(hist, NULL, ")");
+}
+
+static char *create_end_hist(struct tracefs_synth *synth)
+{
+	char *end_hist;
+
+	end_hist = create_hist(synth->end_keys, synth->end_vars);
+	end_hist = create_onmatch(end_hist, synth);
+	return create_trace(end_hist, synth);
 }
 
 static char *append_filter(char *hist, char *filter, unsigned int parens)
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 2/7] libtracefs: Add logic to apply actions to synthetic events
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
  2021-08-13  2:16 ` [PATCH 1/7] libtracefs: Move creating of onmatch handler and trace action into helper functions Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  2021-08-13  2:16 ` [PATCH 3/7] libtracefs: Add API tracefs_synth_trace() Steven Rostedt
                   ` (4 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add an actions list to tracefs_synth, that if it is not empty then it will
be used to apply the handlers and actions to be taken. Otherwise the
default of "onmatch" and "trace" is used.

Currently nothing adds any actions and only the default is supported, but
this will allow for new handlers (onmax and onchange) as well as new
actions (snapshot and save).

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/tracefs.h  |  7 +++++
 src/tracefs-hist.c | 76 ++++++++++++++++++++++++++++++++++++++++++++--
 2 files changed, 81 insertions(+), 2 deletions(-)

diff --git a/include/tracefs.h b/include/tracefs.h
index 90994de97dda..d83c4e33c69a 100644
--- a/include/tracefs.h
+++ b/include/tracefs.h
@@ -435,6 +435,13 @@ int tracefs_event_verify_filter(struct tep_event *event, const char *filter,
 #define TRACEFS_TIMESTAMP "common_timestamp"
 #define TRACEFS_TIMESTAMP_USECS "common_timestamp.usecs"
 
+enum tracefs_synth_handler {
+	TRACEFS_SYNTH_HANDLE_NONE	= 0,
+	TRACEFS_SYNTH_HANDLE_MATCH,
+	TRACEFS_SYNTH_HANDLE_MAX,
+	TRACEFS_SYNTH_HANDLE_CHANGE,
+};
+
 struct tracefs_synth *tracefs_synth_init(struct tep_handle *tep,
 					 const char *name,
 					 const char *start_system,
diff --git a/src/tracefs-hist.c b/src/tracefs-hist.c
index 7fffa6cc653d..262db7fbb925 100644
--- a/src/tracefs-hist.c
+++ b/src/tracefs-hist.c
@@ -521,12 +521,25 @@ int tracefs_hist_append_filter(struct tracefs_hist *hist,
 				   type, field, compare, val);
 }
 
+enum action_type {
+	ACTION_NONE,
+	ACTION_TRACE,
+};
+
+struct action {
+	struct action			*next;
+	enum action_type		type;
+	enum tracefs_synth_handler	handler;
+	char				*handle_field;
+};
+
 /*
  * @name: name of the synthetic event
  * @start_system: system of the starting event
  * @start_event: the starting event
  * @end_system: system of the ending event
  * @end_event: the ending event
+ * @actions: List of actions to take
  * @match_names: If a match set is to be a synthetic field, it has a name
  * @start_match: list of keys in the start event that matches end event
  * @end_match: list of keys in the end event that matches the start event
@@ -545,6 +558,8 @@ struct tracefs_synth {
 	struct tep_handle	*tep;
 	struct tep_event	*start_event;
 	struct tep_event	*end_event;
+	struct action		*actions;
+	struct action		**next_action;
 	char			*name;
 	char			**synthetic_fields;
 	char			**synthetic_args;
@@ -575,6 +590,8 @@ struct tracefs_synth {
  */
 void tracefs_synth_free(struct tracefs_synth *synth)
 {
+	struct action *action;
+
 	if (!synth)
 		return;
 
@@ -590,6 +607,12 @@ void tracefs_synth_free(struct tracefs_synth *synth)
 
 	tep_unref(synth->tep);
 
+	while ((action = synth->actions)) {
+		synth->actions = action->next;
+		free(action->handle_field);
+		free(action);
+	}
+
 	free(synth);
 }
 
@@ -750,6 +773,7 @@ synth_init_from(struct tep_handle *tep, const char *start_system,
 		return NULL;
 
 	synth->start_event = start_event;
+	synth->next_action = &synth->actions;
 
 	/* Hold onto a reference to this handler */
 	tep_ref(tep);
@@ -1405,13 +1429,61 @@ static char *create_trace(char *hist, struct tracefs_synth *synth)
 	return append_string(hist, NULL, ")");
 }
 
+static char *create_max(char *hist, struct tracefs_synth *synth, char *field)
+{
+	hist = append_string(hist, NULL, ":onmax(");
+	hist = append_string(hist, NULL, field);
+	return append_string(hist, NULL, ")");
+}
+
+static char *create_change(char *hist, struct tracefs_synth *synth, char *field)
+{
+	hist = append_string(hist, NULL, ":onchange(");
+	hist = append_string(hist, NULL, field);
+	return append_string(hist, NULL, ")");
+}
+
+static char *create_actions(char *hist, struct tracefs_synth *synth)
+{
+	struct action *action;
+
+	if (!synth->actions) {
+		/* Default is "onmatch" and "trace" */
+		hist = create_onmatch(hist, synth);
+		return create_trace(hist, synth);
+	}
+
+	for (action = synth->actions; action; action = action->next) {
+		switch (action->handler) {
+		case TRACEFS_SYNTH_HANDLE_MATCH:
+			hist = create_onmatch(hist, synth);
+			break;
+		case TRACEFS_SYNTH_HANDLE_MAX:
+			hist = create_max(hist, synth, action->handle_field);
+			break;
+		case TRACEFS_SYNTH_HANDLE_CHANGE:
+			hist = create_change(hist, synth, action->handle_field);
+			break;
+		default:
+			continue;
+		}
+		switch (action->type) {
+		case ACTION_TRACE:
+			hist = create_trace(hist, synth);
+			break;
+		default:
+			continue;
+		}
+	}
+	return hist;
+}
+
 static char *create_end_hist(struct tracefs_synth *synth)
 {
 	char *end_hist;
 
 	end_hist = create_hist(synth->end_keys, synth->end_vars);
-	end_hist = create_onmatch(end_hist, synth);
-	return create_trace(end_hist, synth);
+	return create_actions(end_hist, synth);
 }
 
 static char *append_filter(char *hist, char *filter, unsigned int parens)
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 3/7] libtracefs: Add API tracefs_synth_trace()
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
  2021-08-13  2:16 ` [PATCH 1/7] libtracefs: Move creating of onmatch handler and trace action into helper functions Steven Rostedt
  2021-08-13  2:16 ` [PATCH 2/7] libtracefs: Add logic to apply actions to synthetic events Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  2021-08-13  2:16 ` [PATCH 4/7] libtracefs: Add API tracefs_synth_snapshot() Steven Rostedt
                   ` (3 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add the API tracefs_synth_trace() that adds a "trace" action that can be
attached to the onmax or the onchange handler. Note, this still can be
used for onmatch, but that's the default anyway.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/libtracefs-synth2.txt | 17 +++++-
 include/tracefs.h                   |  2 +
 src/tracefs-hist.c                  | 91 +++++++++++++++++++++++++++++
 3 files changed, 109 insertions(+), 1 deletion(-)

diff --git a/Documentation/libtracefs-synth2.txt b/Documentation/libtracefs-synth2.txt
index 44693b394f29..a74e88ec0eda 100644
--- a/Documentation/libtracefs-synth2.txt
+++ b/Documentation/libtracefs-synth2.txt
@@ -3,7 +3,8 @@ libtracefs(3)
 
 NAME
 ----
-tracefs_synth_create, tracefs_synth_destroy, tracefs_synth_show - Creation of synthetic events
+tracefs_synth_create, tracefs_synth_destroy, tracefs_synth_show,tracefs_synth_complete,
+tracefs_synth_get_start_hist,tracefs_synth_trace - Creation of synthetic events
 
 SYNOPSIS
 --------
@@ -20,6 +21,8 @@ int tracefs_synth_show(struct trace_seq pass:[*]seq, struct tracefs_instance pas
 bool tracefs_synth_complete(struct tracefs_synth pass:[*]synth);
 struct tracefs_hist pass:[*]tracefs_synth_get_start_hist(struct tracefs_synth pass:[*]synth);
 
+int tracefs_synth_trace(struct tracefs_synth pass:[*]synth,
+			enum tracefs_synth_handler type, const char pass:[*]var);
 --
 
 DESCRIPTION
@@ -60,6 +63,18 @@ a starting and ending event.
 *tracefs_synth_get_start_hist*() returns a struct tracefs_hist descriptor describing
 the histogram used to create the synthetic event.
 
+enum tracefs_synth_handler {
+	TRACEFS_SYNTH_HANDLE_MATCH,
+	TRACEFS_SYNTH_HANDLE_MAX,
+	TRACEFS_SYNTH_HANDLE_CHANGE,
+};
+
+*tracefs_synth_trace*() Instead of doing just a trace on matching of the start and
+end events, do the _type_ handler where *TRACEFS_SYNTH_HANDLE_MAX* will do a trace
+when the given variable _var_ hits a new max for the matching keys. Or
+*TRACEFS_SYNTH_HANDLE_CHANGE* for when the _var_ changes. _var_ must be one of
+the _name_ elements used in *tracefs_synth_add_end_field*(3).
+
 RETURN VALUE
 ------------
 Returns zero on success or -1 on error.
diff --git a/include/tracefs.h b/include/tracefs.h
index d83c4e33c69a..2faa564a860f 100644
--- a/include/tracefs.h
+++ b/include/tracefs.h
@@ -476,6 +476,8 @@ int tracefs_synth_append_end_filter(struct tracefs_synth *synth,
 				    const char *field,
 				    enum tracefs_compare compare,
 				    const char *val);
+int tracefs_synth_trace(struct tracefs_synth *synth,
+			enum tracefs_synth_handler type, const char *field);
 bool tracefs_synth_complete(struct tracefs_synth *synth);
 struct tracefs_hist *tracefs_synth_get_start_hist(struct tracefs_synth *synth);
 int tracefs_synth_create(struct tracefs_instance *instance,
diff --git a/src/tracefs-hist.c b/src/tracefs-hist.c
index 262db7fbb925..562ec65088a9 100644
--- a/src/tracefs-hist.c
+++ b/src/tracefs-hist.c
@@ -1323,6 +1323,97 @@ int tracefs_synth_append_end_filter(struct tracefs_synth *synth,
 				   type, field, compare, val);
 }
 
+static int test_max_var(struct tracefs_synth *synth, const char *var)
+{
+	char **vars = synth->end_vars;
+	char *p;
+	int len;
+	int i;
+
+	len = strlen(var);
+
+	/* Make sure the var is defined for the end event */
+	for (i = 0; vars[i]; i++) {
+		p = strchr(vars[i], '=');
+		if (!p)
+			continue;
+		if (p - vars[i] != len)
+			continue;
+		if (!strncmp(var, vars[i], len))
+			return 0;
+	}
+	errno = ENODEV;
+	return -1;
+}
+
+static struct action *create_action(enum tracefs_synth_handler type,
+				    struct tracefs_synth *synth,
+				    const char *var)
+{
+	struct action *action;
+	int ret;
+
+	switch (type) {
+	case TRACEFS_SYNTH_HANDLE_MAX:
+	case TRACEFS_SYNTH_HANDLE_CHANGE:
+		ret = test_max_var(synth, var);
+		if (ret < 0)
+			return NULL;
+		break;
+	default:
+		break;
+	}
+
+	action = calloc(1, sizeof(*action));
+	if (!action)
+		return NULL;
+
+	if (var) {
+		ret = asprintf(&action->handle_field, "$%s", var);
+		if (!action->handle_field) {
+			free(action);
+			return NULL;
+		}
+	}
+	return action;
+}
+
+static void add_action(struct tracefs_synth *synth, struct action *action)
+{
+	*synth->next_action = action;
+	synth->next_action = &action->next;
+}
+
+/**
+ * tracefs_synth_trace - Execute the trace option
+ * @synth: The tracefs_synth descriptor
+ * @type: The type of handler to attach the trace action with
+ * @field: The field for handlers onmax and onchange (ignored otherwise)
+ *
+ * Add the action 'trace' for handlers onmatch, onmax and onchange.
+ *
+ * Returns 0 on succes, -1 on error.
+ */
+int tracefs_synth_trace(struct tracefs_synth *synth,
+			enum tracefs_synth_handler type, const char *field)
+{
+	struct action *action;
+
+	if (!synth || (!field && (type != TRACEFS_SYNTH_HANDLE_MATCH))) {
+		errno = EINVAL;
+		return -1;
+	}
+
+	action = create_action(type, synth, field);
+	if (!action)
+		return -1;
+
+	action->type = ACTION_TRACE;
+	action->handler = type;
+	add_action(synth, action);
+	return 0;
+}
+
 static char *create_synthetic_event(struct tracefs_synth *synth)
 {
 	char *synthetic_event;
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 4/7] libtracefs: Add API tracefs_synth_snapshot()
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
                   ` (2 preceding siblings ...)
  2021-08-13  2:16 ` [PATCH 3/7] libtracefs: Add API tracefs_synth_trace() Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  2021-08-13  2:16 ` [PATCH 5/7] libtracefs: Add API tracefs_synth_save() Steven Rostedt
                   ` (2 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add new API tracefs_synth_snapshot()

Where this will add "actions" to the synthetic event descriptor and also
add other features besides "onmatch()" such that the output can be:

  onmax($lat).trace(latency,$lat):onmax($lat).snapshot

That will trace the latency when it hits a maximum, and also take a
snapshot of the buffer.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/libtracefs-synth2.txt | 11 +++++++++-
 include/tracefs.h                   |  2 ++
 src/tracefs-hist.c                  | 34 +++++++++++++++++++++++++++++
 3 files changed, 46 insertions(+), 1 deletion(-)

diff --git a/Documentation/libtracefs-synth2.txt b/Documentation/libtracefs-synth2.txt
index a74e88ec0eda..194a4e021f62 100644
--- a/Documentation/libtracefs-synth2.txt
+++ b/Documentation/libtracefs-synth2.txt
@@ -4,7 +4,7 @@ libtracefs(3)
 NAME
 ----
 tracefs_synth_create, tracefs_synth_destroy, tracefs_synth_show,tracefs_synth_complete,
-tracefs_synth_get_start_hist,tracefs_synth_trace - Creation of synthetic events
+tracefs_synth_get_start_hist,tracefs_synth_trace,tracefs_synth_snapshot - Creation of synthetic events
 
 SYNOPSIS
 --------
@@ -23,6 +23,8 @@ struct tracefs_hist pass:[*]tracefs_synth_get_start_hist(struct tracefs_synth pa
 
 int tracefs_synth_trace(struct tracefs_synth pass:[*]synth,
 			enum tracefs_synth_handler type, const char pass:[*]var);
+int tracefs_synth_snapshot(struct tracefs_synth pass:[*]synth,
+			   enum tracefs_synth_handler type, const char pass:[*]var);
 --
 
 DESCRIPTION
@@ -75,6 +77,13 @@ when the given variable _var_ hits a new max for the matching keys. Or
 *TRACEFS_SYNTH_HANDLE_CHANGE* for when the _var_ changes. _var_ must be one of
 the _name_ elements used in *tracefs_synth_add_end_field*(3).
 
+*tracefs_synth_snapshot*() When the given variable _var_ is either a new max if
+_handler_ is TRACEFS_SYNTH_HANDLE_MAX_ or simpy changed if TRACEFS_SYNTH_HANDLE_CHANGE_
+then take a "snapshot" of the buffer. The snapshot moves the normal "trace" buffer
+into a "snapshot" buffer, that can be accessed via the "snapshot" file in the
+top level tracefs directory, or one of the instances.  _var_ changes. _var_ must be one of
+the _name_ elements used in *tracefs_synth_add_end_field*(3).
+
 RETURN VALUE
 ------------
 Returns zero on success or -1 on error.
diff --git a/include/tracefs.h b/include/tracefs.h
index 2faa564a860f..45a5bb2df2de 100644
--- a/include/tracefs.h
+++ b/include/tracefs.h
@@ -478,6 +478,8 @@ int tracefs_synth_append_end_filter(struct tracefs_synth *synth,
 				    const char *val);
 int tracefs_synth_trace(struct tracefs_synth *synth,
 			enum tracefs_synth_handler type, const char *field);
+int tracefs_synth_snapshot(struct tracefs_synth *synth,
+			   enum tracefs_synth_handler type, const char *field);
 bool tracefs_synth_complete(struct tracefs_synth *synth);
 struct tracefs_hist *tracefs_synth_get_start_hist(struct tracefs_synth *synth);
 int tracefs_synth_create(struct tracefs_instance *instance,
diff --git a/src/tracefs-hist.c b/src/tracefs-hist.c
index 562ec65088a9..2c9c37b8ec23 100644
--- a/src/tracefs-hist.c
+++ b/src/tracefs-hist.c
@@ -524,6 +524,7 @@ int tracefs_hist_append_filter(struct tracefs_hist *hist,
 enum action_type {
 	ACTION_NONE,
 	ACTION_TRACE,
+	ACTION_SNAPSHOT,
 };
 
 struct action {
@@ -1414,6 +1415,36 @@ int tracefs_synth_trace(struct tracefs_synth *synth,
 	return 0;
 }
 
+/**
+ * tracefs_synth_snapshot - create a snapshot command to the histogram
+ * @synth: The tracefs_synth descriptor
+ * @type: The type of handler to attach the snapshot action with
+ * @field: The field for handlers onmax and onchange
+ *
+ * Add the action to do a snapshot for handlers onmax and onchange.
+ *
+ * Returns 0 on succes, -1 on error.
+ */
+int tracefs_synth_snapshot(struct tracefs_synth *synth,
+			   enum tracefs_synth_handler type, const char *field)
+{
+	struct action *action;
+
+	if (!synth || !field || (type == TRACEFS_SYNTH_HANDLE_MATCH)) {
+		errno = EINVAL;
+		return -1;
+	}
+
+	action = create_action(type, synth, field);
+	if (!action)
+		return -1;
+
+	action->type = ACTION_SNAPSHOT;
+	action->handler = type;
+	add_action(synth, action);
+	return 0;
+}
+
 static char *create_synthetic_event(struct tracefs_synth *synth)
 {
 	char *synthetic_event;
@@ -1562,6 +1593,9 @@ static char *create_actions(char *hist, struct tracefs_synth *synth)
 		case ACTION_TRACE:
 			hist = create_trace(hist, synth);
 			break;
+		case ACTION_SNAPSHOT:
+			hist = append_string(hist, NULL, ".snapshot()");
+			break;
 		default:
 			continue;
 		}
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 5/7] libtracefs: Add API tracefs_synth_save()
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
                   ` (3 preceding siblings ...)
  2021-08-13  2:16 ` [PATCH 4/7] libtracefs: Add API tracefs_synth_snapshot() Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  2021-08-13  2:16 ` [PATCH 6/7] libtracefs: Update the libtracefs-sql man page for the new tracefs_synth APIs Steven Rostedt
  2021-08-13  2:16 ` [PATCH 7/7] libtracefs: Make a man page for the sqlhist man page example Steven Rostedt
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add an API tracefs_synth_save() that will save fields when onmax() or
onchange() handlers are executed.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/libtracefs-synth2.txt |  9 ++++
 include/tracefs.h                   |  3 ++
 src/tracefs-hist.c                  | 73 ++++++++++++++++++++++++++++-
 3 files changed, 83 insertions(+), 2 deletions(-)

diff --git a/Documentation/libtracefs-synth2.txt b/Documentation/libtracefs-synth2.txt
index 194a4e021f62..cfcae7411f58 100644
--- a/Documentation/libtracefs-synth2.txt
+++ b/Documentation/libtracefs-synth2.txt
@@ -25,6 +25,9 @@ int tracefs_synth_trace(struct tracefs_synth pass:[*]synth,
 			enum tracefs_synth_handler type, const char pass:[*]var);
 int tracefs_synth_snapshot(struct tracefs_synth pass:[*]synth,
 			   enum tracefs_synth_handler type, const char pass:[*]var);
+int tracefs_synth_save(struct tracefs_synth pass:[*]synth,
+		       enum tracefs_synth_handler type, const char pass:[*]var,
+		       char pass:[**]save_fields);
 --
 
 DESCRIPTION
@@ -84,6 +87,12 @@ into a "snapshot" buffer, that can be accessed via the "snapshot" file in the
 top level tracefs directory, or one of the instances.  _var_ changes. _var_ must be one of
 the _name_ elements used in *tracefs_synth_add_end_field*(3).
 
+*tracefs_synth_save*() When the given variable _var_ is either a new max if
+_handler_ is TRACEFS_SYNTH_HANDLE_MAX_ or simpy changed if TRACEFS_SYNTH_HANDLE_CHANGE_
+then saven the given _save_fields_ list. The fields will be stored in the histogram
+"hist" file of the event that can be retrieved with *tracefs_event_file_read*(3).
+_var_ changes. _var_ must be one of the _name_ elements used in *tracefs_synth_add_end_field*(3).
+
 RETURN VALUE
 ------------
 Returns zero on success or -1 on error.
diff --git a/include/tracefs.h b/include/tracefs.h
index 45a5bb2df2de..25abbdc10ebf 100644
--- a/include/tracefs.h
+++ b/include/tracefs.h
@@ -480,6 +480,9 @@ int tracefs_synth_trace(struct tracefs_synth *synth,
 			enum tracefs_synth_handler type, const char *field);
 int tracefs_synth_snapshot(struct tracefs_synth *synth,
 			   enum tracefs_synth_handler type, const char *field);
+int tracefs_synth_save(struct tracefs_synth *synth,
+		       enum tracefs_synth_handler type, const char *field,
+		       char **save_fields);
 bool tracefs_synth_complete(struct tracefs_synth *synth);
 struct tracefs_hist *tracefs_synth_get_start_hist(struct tracefs_synth *synth);
 int tracefs_synth_create(struct tracefs_instance *instance,
diff --git a/src/tracefs-hist.c b/src/tracefs-hist.c
index 2c9c37b8ec23..003715fa693c 100644
--- a/src/tracefs-hist.c
+++ b/src/tracefs-hist.c
@@ -525,6 +525,7 @@ enum action_type {
 	ACTION_NONE,
 	ACTION_TRACE,
 	ACTION_SNAPSHOT,
+	ACTION_SAVE,
 };
 
 struct action {
@@ -532,6 +533,7 @@ struct action {
 	enum action_type		type;
 	enum tracefs_synth_handler	handler;
 	char				*handle_field;
+	char				*save;
 };
 
 /*
@@ -580,6 +582,13 @@ struct tracefs_synth {
 	int			arg_cnt;
 };
 
+static void action_free(struct action *action)
+{
+	free(action->handle_field);
+	free(action->save);
+	free(action);
+}
+
 /**
  * tracefs_synth_free - free the resources alloced to a synth
  * @synth: The tracefs_synth descriptor
@@ -610,8 +619,7 @@ void tracefs_synth_free(struct tracefs_synth *synth)
 
 	while ((action = synth->actions)) {
 		synth->actions = action->next;
-		free(action->handle_field);
-		free(action);
+		action_free(action);
 	}
 
 	free(synth);
@@ -1445,6 +1453,64 @@ int tracefs_synth_snapshot(struct tracefs_synth *synth,
 	return 0;
 }
 
+/**
+ * tracefs_synth_save - create a save command to the histogram
+ * @synth: The tracefs_synth descriptor
+ * @type: The type of handler to attach the save action
+ * @max_field: The field for handlers onmax and onchange
+ * @fields: The fields to save for the end variable
+ *
+ * Add the action to save fields for handlers onmax and onchange.
+ *
+ * Returns 0 on succes, -1 on error.
+ */
+int tracefs_synth_save(struct tracefs_synth *synth,
+		       enum tracefs_synth_handler type, const char *max_field,
+		       char **fields)
+{
+	struct action *action;
+	char *save;
+	int i;
+
+	if (!synth || !max_field || (type == TRACEFS_SYNTH_HANDLE_MATCH)) {
+		errno = EINVAL;
+		return -1;
+	}
+
+	action = create_action(type, synth, max_field);
+	if (!action)
+		return -1;
+
+	action->type = ACTION_SAVE;
+	action->handler = type;
+	*synth->next_action = action;
+	synth->next_action = &action->next;
+
+	save = strdup(".save(");
+	if (!save)
+		goto error;
+
+	for (i = 0; fields[i]; i++) {
+		char *delim = i ? "," : NULL;
+
+		if (!trace_verify_event_field(synth->end_event, fields[i], NULL))
+			goto error;
+		save = append_string(save, delim, fields[i]);
+	}
+	save = append_string(save, NULL, ")");
+	if (!save)
+		goto error;
+
+	action->save = save;
+	add_action(synth, action);
+	return 0;
+ error:
+	action_free(action);
+	free(save);
+	return -1;
+	return 0;
+}
+
 static char *create_synthetic_event(struct tracefs_synth *synth)
 {
 	char *synthetic_event;
@@ -1596,6 +1662,9 @@ static char *create_actions(char *hist, struct tracefs_synth *synth)
 		case ACTION_SNAPSHOT:
 			hist = append_string(hist, NULL, ".snapshot()");
 			break;
+		case ACTION_SAVE:
+			hist = append_string(hist, NULL, action->save);
+			break;
 		default:
 			continue;
 		}
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 6/7] libtracefs: Update the libtracefs-sql man page for the new tracefs_synth APIs
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
                   ` (4 preceding siblings ...)
  2021-08-13  2:16 ` [PATCH 5/7] libtracefs: Add API tracefs_synth_save() Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  2021-08-13  2:16 ` [PATCH 7/7] libtracefs: Make a man page for the sqlhist man page example Steven Rostedt
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Update the libtracfes-sql man page to have the sqlhist program utilize the
new APIs:

  tracefs_synth_trace()
  tracefs_synth_snapshot()
  tracefs_synth_save()

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/libtracefs-sql.txt    | 105 ++++++++++++++++++++++++++--
 Documentation/libtracefs-synth2.txt |   2 +
 2 files changed, 102 insertions(+), 5 deletions(-)

diff --git a/Documentation/libtracefs-sql.txt b/Documentation/libtracefs-sql.txt
index 35ccaf5cd1a5..95625157590e 100644
--- a/Documentation/libtracefs-sql.txt
+++ b/Documentation/libtracefs-sql.txt
@@ -305,23 +305,47 @@ EXAMPLE
 
 static void usage(char **argv)
 {
-	fprintf(stderr, "usage: %s [-ed][-n name][-t dir][-f file | sql-command-line]\n"
+	fprintf(stderr, "usage: %s [-ed][-n name][-s][-S fields][-m var][-c var][-T][-t dir][-f file | sql-command-line]\n"
 		"  -n name - name of synthetic event 'Anonymous' if left off\n"
 		"  -t dir - use dir instead of /sys/kernel/tracing\n"
 		"  -e - execute the commands to create the synthetic event\n"
+		"  -m - trigger the action when var is a new max.\n"
+		"  -c - trigger the action when var changes.\n"
+		"  -s - used with -m or -c to do a snapshot of the tracing buffer\n"
+		"  -S - used with -m or -c to save fields of the end event (comma deliminated)\n"
+		"  -T - used with -m or -c to do both a snapshot and a trace\n"
 		"  -f file - read sql lines from file otherwise from the command line\n"
 		"            if file is '-' then read from standard input.\n",
 		argv[0]);
 	exit(-1);
 }
 
-static int do_sql(const char *buffer, const char *name,
-		  const char *trace_dir, bool execute)
+enum action {
+	ACTION_DEFAULT		= 0,
+	ACTION_SNAPSHOT		= (1 << 0),
+	ACTION_TRACE		= (1 << 1),
+	ACTION_SAVE		= (1 << 2),
+	ACTION_MAX		= (1 << 3),
+	ACTION_CHANGE		= (1 << 4),
+};
+
+#define ACTIONS ((ACTION_MAX - 1))
+
+static int do_sql(const char *buffer, const char *name, const char *var,
+		  const char *trace_dir, bool execute, int action,
+		  char **save_fields)
 {
 	struct tracefs_synth *synth;
 	struct tep_handle *tep;
 	struct trace_seq seq;
+	enum tracefs_synth_handler handler;
 	char *err;
+	int ret;
+
+	if ((action & ACTIONS) && !var) {
+		fprintf(stderr, "Error: -s, -S and -T not supported without -m or -c");
+		exit(-1);
+	}
 
 	if (!name)
 		name = "Anonymous";
@@ -345,6 +369,43 @@ static int do_sql(const char *buffer, const char *name,
 	}
 
 	if (tracefs_synth_complete(synth)) {
+		if (var) {
+			if (action & ACTION_MAX)
+				handler = TRACEFS_SYNTH_HANDLE_MAX;
+			else
+				handler = TRACEFS_SYNTH_HANDLE_CHANGE;
+
+			if (action & ACTION_SAVE) {
+				ret = tracefs_synth_save(synth, handler, var, save_fields);
+				if (ret < 0) {
+					err = "adding save";
+					goto failed_action;
+				}
+			}
+			if (action & ACTION_TRACE) {
+				/*
+				 * By doing the trace before snapshot, it will be included
+				 * in the snapshot.
+				 */
+				ret = tracefs_synth_trace(synth, handler, var);
+				if (ret < 0) {
+					err = "adding trace";
+					goto failed_action;
+				}
+			}
+			if (action & ACTION_SNAPSHOT) {
+				ret = tracefs_synth_snapshot(synth, handler, var);
+				if (ret < 0) {
+					err = "adding snapshot";
+ failed_action:
+					perror(err);
+					if (errno == ENODEV)
+						fprintf(stderr, "ERROR: '%s' is not a variable\n",
+							var);
+					exit(-1);
+				}
+			}
+		}
 		tracefs_synth_show(&seq, NULL, synth);
 		if (execute)
 			tracefs_synth_create(NULL, synth);
@@ -375,14 +436,18 @@ int main (int argc, char **argv)
 	int buffer_size = 0;
 	const char *file = NULL;
 	bool execute = false;
+	char **save_fields = NULL;
 	const char *name;
+	const char *var;
+	int action = 0;
+	char *tok;
 	FILE *fp;
 	size_t r;
 	int c;
 	int i;
 
 	for (;;) {
-		c = getopt(argc, argv, "ht:f:en:");
+		c = getopt(argc, argv, "ht:f:en:m:c:sS:T");
 		if (c == -1)
 			break;
 
@@ -398,12 +463,42 @@ int main (int argc, char **argv)
 		case 'e':
 			execute = true;
 			break;
+		case 'm':
+			action |= ACTION_MAX;
+			var = optarg;
+			break;
+		case 'c':
+			action |= ACTION_CHANGE;
+			var = optarg;
+			break;
+		case 's':
+			action |= ACTION_SNAPSHOT;
+			break;
+		case 'S':
+			action |= ACTION_SAVE;
+			tok = strtok(optarg, ",");
+			while (tok) {
+				save_fields = tracefs_list_add(save_fields, tok);
+				tok = strtok(NULL, ",");
+			}
+			if (!save_fields) {
+				perror(optarg);
+				exit(-1);
+			}
+			break;
+		case 'T':
+			action |= ACTION_TRACE | ACTION_SNAPSHOT;
+			break;
 		case 'n':
 			name = optarg;
 			break;
 		}
 	}
 
+	if ((action & (ACTION_MAX|ACTION_CHANGE)) == (ACTION_MAX|ACTION_CHANGE)) {
+		fprintf(stderr, "Can not use both -m and -c together\n");
+		exit(-1);
+	}
 	if (file) {
 		if (!strcmp(file, "-"))
 			fp = stdin;
@@ -434,7 +529,7 @@ int main (int argc, char **argv)
 		}
 	}
 
-	do_sql(buffer, name, trace_dir, execute);
+	do_sql(buffer, name, var, trace_dir, execute, action, save_fields);
 	free(buffer);
 
 	return 0;
diff --git a/Documentation/libtracefs-synth2.txt b/Documentation/libtracefs-synth2.txt
index cfcae7411f58..4c4425325393 100644
--- a/Documentation/libtracefs-synth2.txt
+++ b/Documentation/libtracefs-synth2.txt
@@ -117,6 +117,8 @@ And more errors may have happened from the system calls to the system.
 
 EXAMPLE
 -------
+See *tracefs_sql*(3) for a more indepth use of some of this code.
+
 [source,c]
 --
 #include <stdlib.h>
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

* [PATCH 7/7] libtracefs: Make a man page for the sqlhist man page example
  2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
                   ` (5 preceding siblings ...)
  2021-08-13  2:16 ` [PATCH 6/7] libtracefs: Update the libtracefs-sql man page for the new tracefs_synth APIs Steven Rostedt
@ 2021-08-13  2:16 ` Steven Rostedt
  6 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-08-13  2:16 UTC (permalink / raw)
  To: linux-trace-devel
  Cc: linux-kernel, Tom Zanussi, Daniel Bristot de Oliveira,
	Masami Hiramatsu, Namhyung Kim, linux-rt-users, Clark Williams,
	Steven Rostedt (VMware)

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

As the sqlhist example in the tracefs_sql(3) man page is becoming quite
the tool to use, give it its own man page!

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/Makefile                 |  53 +++-
 Documentation/libtracefs-sql.txt       |   2 +-
 Documentation/libtracefs-sqlhist.txt.1 | 351 +++++++++++++++++++++++++
 3 files changed, 397 insertions(+), 9 deletions(-)
 create mode 100644 Documentation/libtracefs-sqlhist.txt.1

diff --git a/Documentation/Makefile b/Documentation/Makefile
index efe7b09d4e68..0c00505852b5 100644
--- a/Documentation/Makefile
+++ b/Documentation/Makefile
@@ -10,6 +10,9 @@ MAN3_TXT= \
 	$(wildcard libtracefs-*.txt) \
 	libtracefs.txt
 
+MAN1_TEXT= \
+	$(wildcard libtracefs-*.txt.1)
+
 MAN_TXT = $(MAN3_TXT)
 _MAN_XML=$(patsubst %.txt,%.xml,$(MAN_TXT))
 _MAN_HTML=$(patsubst %.txt,%.html,$(MAN_TXT))
@@ -19,6 +22,15 @@ MAN_XML=$(addprefix $(OUTPUT),$(_MAN_XML))
 MAN_HTML=$(addprefix $(OUTPUT),$(_MAN_HTML))
 DOC_MAN3=$(addprefix $(OUTPUT),$(_DOC_MAN3))
 
+_MAN1_XML=$(patsubst %.txt.1,%.xml,$(MAN1_TEXT))
+_MAN1_HTML=$(patsubst %.txt.1,%.html,$(MAN1_TEXT))
+_DOC_MAN1=$(patsubst %.txt.1,%.m,$(MAN1_TEXT))
+
+MAN1_XML=$(addprefix $(OUTPUT),$(_MAN1_XML))
+MAN1_HTML=$(addprefix $(OUTPUT),$(_MAN1_HTML))
+DOC_MAN1=$(addprefix $(OUTPUT),$(_DOC_MAN1))
+
+
 # Make the path relative to DESTDIR, not prefix
 ifndef DESTDIR
 prefix?=$(HOME)
@@ -28,6 +40,7 @@ htmldir?=$(prefix)/share/doc/libtracefs-doc
 pdfdir?=$(prefix)/share/doc/libtracefs-doc
 mandir?=$(prefix)/share/man
 man3dir=$(mandir)/man3
+man1dir=$(mandir)/man1
 
 ASCIIDOC=asciidoc
 ASCIIDOC_EXTRA = --unsafe -f asciidoc.conf
@@ -131,12 +144,13 @@ endif
 
 all: check-man-tools html man
 
-man: man3
+man: man3 man1
 man3: $(DOC_MAN3)
+man1: $(DOC_MAN1)
 
-html: $(MAN_HTML)
+html: $(MAN_HTML) $(MAN1_HTML)
 
-$(MAN_HTML) $(DOC_MAN3): asciidoc.conf
+$(MAN_HTML) $(MAN1_HTML) $(DOC_MAN3) $(DOC_MAN1): asciidoc.conf
 
 install: check-man-tools install-man install-html
 
@@ -148,7 +162,10 @@ endif
 install-%.3: $(OUTPUT)%.3
 	$(Q)$(call do_install,$<,$(man3dir),644);
 
-do-install-man: man $(addprefix install-,$(wildcard $(OUTPUT)*.3))
+install-%.1: $(OUTPUT)%.1
+	$(Q)$(call do_install,$<,$(man1dir),644);
+
+do-install-man: man $(addprefix install-,$(wildcard $(OUTPUT)*.3)) $(addprefix install-,$(wildcard $(OUTPUT)*.1))
 
 install-man: man
 	$(Q)$(MAKE) -C . do-install-man
@@ -156,17 +173,20 @@ install-man: man
 install-%.txt: $(OUTPUT)%.html
 	$(Q)$(call do_install,$<,$(htmldir),644);
 
-do-install-html: html $(addprefix install-,$(wildcard *.txt))
+install-%.txt.1: $(OUTPUT)%.html
+	$(Q)$(call do_install,$<,$(htmldir),644);
+
+do-install-html: html $(addprefix install-,$(wildcard *.txt)) $(addprefix install-,$(wildcard *.txt.1))
 
 install-html: html do-install-html
 
 uninstall: uninstall-man uninstall-html
 
 uninstall-man:
-	$(Q)$(RM) $(addprefix $(DESTDIR)$(man3dir)/,$(DOC_MAN3))
+	$(Q)$(RM) $(addprefix $(DESTDIR)$(man3dir)/,$(DOC_MAN3)) $(addprefix $(DESTDIR)$(man1dir)/,$(DOC_MAN1))
 
 uninstall-html:
-	$(Q)$(RM) $(addprefix $(DESTDIR)$(htmldir)/,$(MAN_HTML))
+	$(Q)$(RM) $(addprefix $(DESTDIR)$(htmldir)/,$(MAN_HTML)) $(addprefix $(DESTDIR)$(htmldir)/,$(MAN1_HTML))
 
 ifdef missing_tools
   DO_INSTALL_MAN = $(warning Please install $(missing_tools) to have the man pages installed)
@@ -177,7 +197,7 @@ endif
 CLEAN_FILES =					\
 	$(MAN_XML) $(addsuffix +,$(MAN_XML))	\
 	$(MAN_HTML) $(addsuffix +,$(MAN_HTML))	\
-	$(DOC_MAN3) *.3 *.m
+	$(DOC_MAN3) *.3 *.1 *.m
 
 clean:
 	$(Q) $(RM) $(CLEAN_FILES)
@@ -188,6 +208,11 @@ $(OUTPUT)%.3 : $(OUTPUT)%.txt
 	$(ASCIIDOC) -b manpage -d manpage \
 		$(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \
 	mv $@+ $@
+$(OUTPUT)%.1 : $(OUTPUT)%.txt.1
+	$(QUIET_ASCIIDOC)$(RM) $@+ $@ && \
+	$(ASCIIDOC) -b manpage -d manpage \
+		$(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \
+	mv $@+ $@
 endif
 
 $(OUTPUT)%.m : $(OUTPUT)%.xml
@@ -201,8 +226,20 @@ $(OUTPUT)%.xml : %.txt
 		$(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \
 	mv $@+ $@
 
+$(OUTPUT)%.xml : %.txt.1
+	$(QUIET_ASCIIDOC)$(RM) $@+ $@ && \
+	$(ASCIIDOC) -b docbook -d manpage \
+		$(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \
+	mv $@+ $@
+
 $(MAN_HTML): $(OUTPUT)%.html : %.txt
 	$(QUIET_ASCIIDOC)$(RM) $@+ $@ && \
 	$(ASCIIDOC) -b $(ASCIIDOC_HTML) -d manpage \
 		$(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \
 	mv $@+ $@
+
+$(MAN1_HTML): $(OUTPUT)%.html : %.txt.1
+	$(QUIET_ASCIIDOC)$(RM) $@+ $@ && \
+	$(ASCIIDOC) -b $(ASCIIDOC_HTML) -d manpage \
+		$(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \
+	mv $@+ $@
diff --git a/Documentation/libtracefs-sql.txt b/Documentation/libtracefs-sql.txt
index 95625157590e..e762eaea28c2 100644
--- a/Documentation/libtracefs-sql.txt
+++ b/Documentation/libtracefs-sql.txt
@@ -290,7 +290,6 @@ Then you can run the above examples:
                   JOIN sched_switch as end ON start.pid = end.next_pid
                   WHERE start.prio < 100 || end.prev_prio < 100'
 --
-
 EXAMPLE
 -------
 [source,c]
@@ -548,6 +547,7 @@ FILES
 
 SEE ALSO
 --------
+_sqlhist(1)_,
 _libtracefs(3)_,
 _libtraceevent(3)_,
 _trace-cmd(1)_,
diff --git a/Documentation/libtracefs-sqlhist.txt.1 b/Documentation/libtracefs-sqlhist.txt.1
new file mode 100644
index 000000000000..1e94ea4cd138
--- /dev/null
+++ b/Documentation/libtracefs-sqlhist.txt.1
@@ -0,0 +1,351 @@
+SQLHIST(1)
+==========
+
+NAME
+----
+sqlhist - Tool that uses SQL language to create / show creation of tracefs histograms and synthetic events.
+
+SYNOPSIS
+--------
+*sqlhist* ['OPTIONS'] ['SQL-select-command']
+
+DESCRIPTION
+-----------
+The sqlhist(1) will take an SQL like statement to create tracefs histograms and
+synthetic events that can perform various actions for various handling of the
+data.
+
+The tracefs file system interfaces with the Linux tracing infrastructure that
+has various dynamic and static events through out the kernel. Each of these
+events can have a "histogram" attached to it, where the fields of the event
+will define the buckets of the histogram.
+
+A synthetic event is a way to attach two separate events and use the fields
+and time stamps of those events to create a new dynamic event. This new
+dynamic event is call a synthetic event. The fields of each event can have
+simple calculations done on them where, for example, the delta between
+a field of one event to a field of the other event can be taken. This also
+works for the time stamps of the events where the time delta between the
+two events can also be extracted and placed into the synthetic event.
+
+Other actions can be done from the fields of the events. A snapshot can
+be taken of the kernel ring buffer a variable used in the synthetic
+event creating hits a max, or simply changes.
+
+The commands to create histograms and synthetic events are complex and
+not easy to remember. *sqlhist* is used to convert SQL syntax into the
+commands needed to create the histogram or synthetic event.
+
+The *SQL-select-command* is a SQL string defined by *tracefs_sql*(3).
+
+Note, this must be run as root (or sudo) as interacting with the tracefs
+directory requires root privilege, unless the *-t* option is given with
+a copy of the _tracefs_ directory and its events.
+
+The *sqlhist* is a simple program where its code actual exists in the
+*tracefs_sql*(3) man page.
+
+OPTIONS
+-------
+*-n* 'name'::
+    The name of the synthetic event to create. This event can then be
+    used like any other event, and enabled via *trace-cmd*(1).
+
+*-t* 'tracefs-dir'::
+    In order to test this out as non root user, a copy of the tracefs directory
+    can be used, and passing that directory with this option will allow
+    the program to work. Obviously, *-e* will not work as non-root because
+    it will not be able to execute.
+
+    # mkdir /tmp/tracing
+    # cp -r /sys/kernel/tracing/events /tmp/tracing
+    # exit
+    $ ./sqlhist -t /tmp/tracing ...
+
+*-e*::
+    Not only display the commands to create the histogram, but also execute them.
+    This requires root privilege.
+
+*-f* 'file'::
+    Instead of reading the SQL commands from the command line, read them from
+    _file_. If _file_ is '-' then read from standard input.
+
+*-m* 'var'::
+    Do the given action when the variable _var_ hits a new maximum. This can
+    not be used with *-c*.
+
+*-c* 'var'::
+    Do the given action when the variable _var_ changes its value. This can
+    not be used with *-m*.
+
+*-s*::
+    Perform a snapshot instead of calling the synthetic event.
+
+*-T*::
+    Perform both a snapshot and trace the synthetic event.
+
+*-S* 'fields[,fields]'::
+    Save the given fields. The fields must be fields of the "end" event given
+    in the *SQL-select-command*
+
+
+EXAMPLES
+--------
+
+Create the sqlhist executable:
+
+[source, c]
+--
+   man tracefs_sql | sed -ne '/^EXAMPLE/,/FILES/ { /EXAMPLE/d ; /FILES/d ; p}' > sqlhist.c
+   gcc -o sqlhist sqlhist.c `pkg-config --cflags --libs libtracefs`
+--
+
+As described above, for testing purposes, make a copy of the event directory:
+[source, c]
+--
+   $ mkdir /tmp/tracing
+   $ sudo cp -r /sys/kernel/tracing/events /tmp/tracing/
+   $ sudo chmod -R 0644 /tmp/tracing/
+--
+
+For an example of simple histogram output using the copy of the tracefs directory.
+[source, c]
+--
+   $ ./sqlhist -t /tmp/tracing/ 'SELECT CAST(call_site as SYM-OFFSET), bytes_req, CAST(bytes_alloc AS _COUNTER_) FROM kmalloc'
+--
+
+Produces the output:
+[source, c]
+--
+   echo 'hist:keys=call_site.sym-offset,bytes_req:vals=bytes_alloc' > /sys/kernel/tracing/events/kmem/kmalloc/trigger
+--
+
+Which could be used by root:
+[source, c]
+--
+   # echo 'hist:keys=call_site.sym-offset,bytes_req:vals=bytes_alloc' > /sys/kernel/tracing/events/kmem/kmalloc/trigger
+   # cat /sys/kernel/tracing/events/kmem/kmalloc/hist
+# event histogram
+#
+# trigger info: hist:keys=call_site.sym-offset,bytes_req:vals=hitcount,bytes_alloc:sort=hitcount:size=2048 [active]
+#
+
+{ call_site: [ffffffff813f8d8a] load_elf_phdrs+0x4a/0xb0                               , bytes_req:        728 } hitcount:          1  bytes_alloc:       1024
+{ call_site: [ffffffffc0c69e74] nf_ct_ext_add+0xd4/0x1d0 [nf_conntrack]                , bytes_req:        128 } hitcount:          1  bytes_alloc:        128
+{ call_site: [ffffffff818355e6] dma_resv_get_fences+0xf6/0x440                         , bytes_req:          8 } hitcount:          1  bytes_alloc:          8
+{ call_site: [ffffffffc06dc73f] intel_gt_get_buffer_pool+0x15f/0x290 [i915]            , bytes_req:        424 } hitcount:          1  bytes_alloc:        512
+{ call_site: [ffffffff813f8d8a] load_elf_phdrs+0x4a/0xb0                               , bytes_req:        616 } hitcount:          1  bytes_alloc:       1024
+{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180                           , bytes_req:         32 } hitcount:          1  bytes_alloc:         32
+{ call_site: [ffffffffc070749d] shmem_get_pages+0xad/0x5d0 [i915]                      , bytes_req:         16 } hitcount:          1  bytes_alloc:         16
+{ call_site: [ffffffffc07507f5] intel_framebuffer_create+0x25/0x60 [i915]              , bytes_req:        408 } hitcount:          1  bytes_alloc:        512
+{ call_site: [ffffffffc06fc20f] eb_parse+0x34f/0x910 [i915]                            , bytes_req:        408 } hitcount:          1  bytes_alloc:        512
+{ call_site: [ffffffffc0700ebd] i915_gem_object_get_pages_internal+0x5d/0x270 [i915]   , bytes_req:         16 } hitcount:          1  bytes_alloc:         16
+{ call_site: [ffffffffc0771188] intel_frontbuffer_get+0x38/0x220 [i915]                , bytes_req:        400 } hitcount:          1  bytes_alloc:        512
+{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180                           , bytes_req:        128 } hitcount:          1  bytes_alloc:        128
+{ call_site: [ffffffff813f8f45] load_elf_binary+0x155/0x1680                           , bytes_req:         28 } hitcount:          1  bytes_alloc:         32
+{ call_site: [ffffffffc07038c8] __assign_mmap_offset+0x208/0x3d0 [i915]                , bytes_req:        288 } hitcount:          1  bytes_alloc:        512
+{ call_site: [ffffffff813737b2] alloc_bprm+0x32/0x2f0                                  , bytes_req:        416 } hitcount:          1  bytes_alloc:        512
+{ call_site: [ffffffff813f9027] load_elf_binary+0x237/0x1680                           , bytes_req:         64 } hitcount:          1  bytes_alloc:         64
+{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180                           , bytes_req:         64 } hitcount:          1  bytes_alloc:         64
+{ call_site: [ffffffffc040ffe7] drm_vma_node_allow+0x27/0xe0 [drm]                     , bytes_req:         40 } hitcount:          2  bytes_alloc:        128
+{ call_site: [ffffffff813cda98] __do_sys_timerfd_create+0x58/0x1c0                     , bytes_req:        336 } hitcount:          2  bytes_alloc:       1024
+{ call_site: [ffffffff818355e6] dma_resv_get_fences+0xf6/0x440                         , bytes_req:         40 } hitcount:          2  bytes_alloc:        128
+{ call_site: [ffffffff8139b75a] single_open+0x2a/0xa0                                  , bytes_req:         32 } hitcount:          2  bytes_alloc:         64
+{ call_site: [ffffffff815df715] bio_kmalloc+0x25/0x80                                  , bytes_req:        136 } hitcount:          2  bytes_alloc:        384
+{ call_site: [ffffffffc071e5cd] i915_vma_work+0x1d/0x50 [i915]                         , bytes_req:        416 } hitcount:          3  bytes_alloc:       1536
+{ call_site: [ffffffff81390d0d] alloc_fdtable+0x4d/0x100                               , bytes_req:         56 } hitcount:          3  bytes_alloc:        192
+{ call_site: [ffffffffc06ff65f] i915_gem_do_execbuffer+0x158f/0x2440 [i915]            , bytes_req:         16 } hitcount:          4  bytes_alloc:         64
+{ call_site: [ffffffff8137713c] alloc_pipe_info+0x5c/0x230                             , bytes_req:        384 } hitcount:          5  bytes_alloc:       2560
+{ call_site: [ffffffff813771b4] alloc_pipe_info+0xd4/0x230                             , bytes_req:        640 } hitcount:          5  bytes_alloc:       5120
+{ call_site: [ffffffff81834cdb] dma_resv_list_alloc+0x1b/0x40                          , bytes_req:         40 } hitcount:          6  bytes_alloc:        384
+{ call_site: [ffffffff81834cdb] dma_resv_list_alloc+0x1b/0x40                          , bytes_req:         56 } hitcount:          9  bytes_alloc:        576
+{ call_site: [ffffffff8120086e] tracing_map_sort_entries+0x9e/0x3e0                    , bytes_req:         24 } hitcount:         60  bytes_alloc:       1920
+
+Totals:
+    Hits: 122
+    Entries: 30
+    Dropped: 0
+--
+
+Note, although the examples use uppercase for the SQL keywords, they do not have
+to be. 'SELECT' could also be 'select' or even 'sElEcT'.
+
+By using the full SQL language, synthetic events can be made and processed.
+For example, using *sqlhist* along with *trace-cmd*(1), wake up latency can
+be recorded by creating a synthetic event by attaching the _sched_waking_
+and the _sched_switch_ events.
+
+[source, c]
+--
+  # sqlhist -n wakeup_lat -e -T -m lat 'SELECT end.next_comm AS comm, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM ' \
+    'sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid WHERE end.next_prio < 100 && end.next_comm == "cyclictest"'
+  # trace-cmd start -e all -e wakeup_lat -R stacktrace
+  # cyclictest -l 1000 -p80 -i250  -a -t -q -m -d 0 -b 1000 --tracemark
+  # trace-cmd show -s | tail -30
+          <idle>-0       [002] dNh4 23454.902246: sched_wakeup: comm=cyclictest pid=12272 prio=120 target_cpu=002
+          <idle>-0       [005] ...1 23454.902246: cpu_idle: state=4294967295 cpu_id=5
+          <idle>-0       [007] d..1 23454.902246: cpu_idle: state=0 cpu_id=7
+          <idle>-0       [002] dNh1 23454.902247: hrtimer_expire_exit: hrtimer=0000000037956dc2
+          <idle>-0       [005] d..1 23454.902248: cpu_idle: state=0 cpu_id=5
+          <idle>-0       [002] dNh1 23454.902248: write_msr: 6e0, value 4866ce957272
+          <idle>-0       [006] ...1 23454.902248: cpu_idle: state=4294967295 cpu_id=6
+          <idle>-0       [002] dNh1 23454.902249: local_timer_exit: vector=236
+          <idle>-0       [006] d..1 23454.902250: cpu_idle: state=0 cpu_id=6
+          <idle>-0       [002] .N.1 23454.902250: cpu_idle: state=4294967295 cpu_id=2
+          <idle>-0       [002] dN.1 23454.902251: rcu_utilization: Start context switch
+          <idle>-0       [002] dN.1 23454.902252: rcu_utilization: End context switch
+          <idle>-0       [001] ...1 23454.902252: cpu_idle: state=4294967295 cpu_id=1
+          <idle>-0       [002] dN.3 23454.902253: prandom_u32: ret=3692516021
+          <idle>-0       [001] d..1 23454.902254: cpu_idle: state=0 cpu_id=1
+          <idle>-0       [002] d..2 23454.902254: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=12275 next_prio=19
+          <idle>-0       [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17
+          <idle>-0       [002] d..5 23454.902258: <stack trace>
+ => trace_event_raw_event_synth
+ => action_trace
+ => event_hist_trigger
+ => event_triggers_call
+ => trace_event_buffer_commit
+ => trace_event_raw_event_sched_switch
+ => __traceiter_sched_switch
+ => __schedule
+ => schedule_idle
+ => do_idle
+ => cpu_startup_entry
+ => secondary_startup_64_no_verify
+--
+
+Here's the options for *sqlhist* explained:
+
+ *-n wakeup_lat* ::
+     Name the synthetic event to use *wakeup_lat*.
+
+ *-e*::
+     Execute the commands that are printed.
+
+ *-T*::
+     Perform both a trace action and then a snapshot action (swap the buffer into the static 'snapshot' buffer).
+
+ *-m lat*::
+     Trigger the actions whenever 'lat' hits a new maximum value.
+
+Now a breakdown of the SQL statement:
+[source, c]
+--
+ 'SELECT end.next_comm AS comm, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM ' \
+    'sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid WHERE end.next_prio < 100 && end.next_comm == "cyclictest"'
+--
+ *end.next_comm AS comm*::
+   Save the 'sched_switch' field *next_comm* and place it into the *comm* field of the 'wakeup_lat' synthetic event.
+
+ *(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat*::
+   Take the delta of the time stamps from the 'sched_switch' event and the 'sched_waking' event.
+   As time stamps are usually recorded in nanoseconds, *TIMESTAMP* would give the full nanosecond time stamp,
+   but here, the *TIMESTAMP_USECS* will truncate it into microseconds. The value is saved in the
+   variable *lat*, which will also be recorded in the synthetic event.
+
+ *FROM 'sched_waking' AS start JOIN sched_switch AS end ON start.pid = end.next_pid*::
+   Create the synthetic event by joining _sched_waking_ to _sched_switch_, matching
+   the _sched_waking_ 'pid' field with the _sched_switch_ 'next_pid' field.
+   Also make *start* an alias for _sched_waking_ and *end* an alias for _sched_switch_
+   which then an use *start* and *end* as a subsitute for _sched_waking_ and _sched_switch_
+   respectively through out the rest of the SQL statement.
+
+ *WHERE end.next_prio < 100 && end.next_comm == "cyclictest"*::
+   Filter the logic where it executes only if _sched_waking_ 'next_prio' field
+   is less than 100. (Note, in the Kernel, priorities are inverse, and the real-time
+   priorities are represented from 0-100 where 0 is the highest priority).
+   Also only trace when the 'next_comm' (the task scheduling in) of the _sched_switch_
+   event has the name "cyclictest".
+
+For the *trace-cmd*(3) command:
+[source, c]
+--
+   trace-cmd start -e all -e wakeup_lat -R stacktrace
+--
+
+ *trace-cmd start*::
+   Enables tracing (does not record to a file).
+
+ *-e all*::
+   Enable all events
+
+ *-e wakeup_lat -R stacktrace*::
+   have the "wakeup_lat" event (our synthetic event) enable the *stacktrace* trigger, were
+   for every instance of the "wakeup_lat" event, a kernel stack trace will be recorded
+   in the ring buffer.
+
+After calling *cyclictest* (a real-time tool to measure wakeup latency), read the snapshot
+buffer.
+
+ *trace-cmd show -s*::
+   *trace-cmd show* reads the kernel ring buffer, and the *-s* option will read the *snapshot*
+   buffer instead of the normal one.
+
+[source, c]
+--
+ <idle>-0       [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17
+--
+  We see on the "wakeup_lat" event happened on CPU 2, with a wake up latency 17 microseconds.
+
+This can be extracted into a *trace.dat* file that *trace-cmd*(3) can read and do further
+analysis, as well as *kernelshark*.
+
+[source, c]
+--
+    # trace-cmd extract -s
+    # trace-cmd report --cpu 2 | tail -30
+          <idle>-0     [002] 23454.902238: prandom_u32:          ret=1633425088
+          <idle>-0     [002] 23454.902239: sched_wakeup:         cyclictest:12275 [19] CPU:002
+          <idle>-0     [002] 23454.902241: hrtimer_expire_exit:  hrtimer=0xffffbbd68286fe60
+          <idle>-0     [002] 23454.902241: hrtimer_cancel:       hrtimer=0xffffbbd6826efe70
+          <idle>-0     [002] 23454.902242: hrtimer_expire_entry: hrtimer=0xffffbbd6826efe70 now=23455294430750 function=hrtimer_wakeup/0x0
+          <idle>-0     [002] 23454.902243: sched_waking:         comm=cyclictest pid=12272 prio=120 target_cpu=002
+          <idle>-0     [002] 23454.902244: prandom_u32:          ret=1102749734
+          <idle>-0     [002] 23454.902246: sched_wakeup:         cyclictest:12272 [120] CPU:002
+          <idle>-0     [002] 23454.902247: hrtimer_expire_exit:  hrtimer=0xffffbbd6826efe70
+          <idle>-0     [002] 23454.902248: write_msr:            6e0, value 4866ce957272
+          <idle>-0     [002] 23454.902249: local_timer_exit:     vector=236
+          <idle>-0     [002] 23454.902250: cpu_idle:             state=4294967295 cpu_id=2
+          <idle>-0     [002] 23454.902251: rcu_utilization:      Start context switch
+          <idle>-0     [002] 23454.902252: rcu_utilization:      End context switch
+          <idle>-0     [002] 23454.902253: prandom_u32:          ret=3692516021
+          <idle>-0     [002] 23454.902254: sched_switch:         swapper/2:0 [120] R ==> cyclictest:12275 [19]
+          <idle>-0     [002] 23454.902256: wakeup_lat:           next_comm=cyclictest lat=17
+          <idle>-0     [002] 23454.902258: kernel_stack:         <stack trace >
+=> trace_event_raw_event_synth (ffffffff8121a0db)
+=> action_trace (ffffffff8121e9fb)
+=> event_hist_trigger (ffffffff8121ca8d)
+=> event_triggers_call (ffffffff81216c72)
+=> trace_event_buffer_commit (ffffffff811f7618)
+=> trace_event_raw_event_sched_switch (ffffffff8110fda4)
+=> __traceiter_sched_switch (ffffffff8110d449)
+=> __schedule (ffffffff81c02002)
+=> schedule_idle (ffffffff81c02c86)
+=> do_idle (ffffffff8111e898)
+=> cpu_startup_entry (ffffffff8111eba9)
+=> secondary_startup_64_no_verify (ffffffff81000107)
+--
+
+BUGS
+----
+
+As *sqlhist* is just example code from a man page, it is guaranteed to contain
+lots of bugs. For one thing, not all error paths are covered properly.
+
+SEE ALSO
+--------
+trace-cmd(1), tracefs_sql(3)
+
+AUTHOR
+------
+Written by Steven Rostedt, <rostedt@goodmis.org>
+
+RESOURCES
+---------
+https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
+
+COPYING
+-------
+Copyright \(C) 2021 , Inc. Free use of this software is granted under
+the terms of the GNU Public License (GPL).
+
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2021-08-13  2:17 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-08-13  2:16 [PATCH 0/7] libtracefs: Add handlers 'onmax' and 'onchange' and actions 'snapshot' and 'save' Steven Rostedt
2021-08-13  2:16 ` [PATCH 1/7] libtracefs: Move creating of onmatch handler and trace action into helper functions Steven Rostedt
2021-08-13  2:16 ` [PATCH 2/7] libtracefs: Add logic to apply actions to synthetic events Steven Rostedt
2021-08-13  2:16 ` [PATCH 3/7] libtracefs: Add API tracefs_synth_trace() Steven Rostedt
2021-08-13  2:16 ` [PATCH 4/7] libtracefs: Add API tracefs_synth_snapshot() Steven Rostedt
2021-08-13  2:16 ` [PATCH 5/7] libtracefs: Add API tracefs_synth_save() Steven Rostedt
2021-08-13  2:16 ` [PATCH 6/7] libtracefs: Update the libtracefs-sql man page for the new tracefs_synth APIs Steven Rostedt
2021-08-13  2:16 ` [PATCH 7/7] libtracefs: Make a man page for the sqlhist man page example Steven Rostedt

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).