[PATCH 0/5] trace-cmd: Update for the new trace_print_event() logic

[PATCH 0/5] trace-cmd: Update for the new trace_print_event() logic

[Steven Rostedt]

Porting over Tzvetomir's trace_print_event() logic to trace-cmd, I found
that it required some restructuring of the code. This was a quick work to
get it working. Please take a look at it as I probably screwed something up
(while jetlag and also doing this along with other things in parallel).

Steven Rostedt (VMware) (4):
      trace-cmd: Move extract trace_clock into trace-input.c
      trace-cmd: Separate out time diff code in trace_show_data()
      trace-cmd: Add check for trace_clock using usecs into tracecmd_parse_trace_clock()
      tools/lib/traceevent: Round up in tep_print_event() time precision

Tzvetomir Stoyanov (1):
      libtraceevent, perf tools: Changes in tep_print_event_* APIs

----
 include/trace-cmd/trace-cmd.h      |   4 +-
 include/traceevent/event-parse.h   |  29 ++--
 lib/trace-cmd/trace-input.c        |  41 ++++-
 lib/trace-cmd/trace-util.c         |  27 ----
 lib/traceevent/event-parse-api.c   |  40 -----
 lib/traceevent/event-parse-local.h |   4 -
 lib/traceevent/event-parse.c       | 324 +++++++++++++++++++++----------------
 tracecmd/trace-read.c              |  85 ++++++----
 8 files changed, 298 insertions(+), 256 deletions(-)

[PATCH 1/5] trace-cmd: Move extract trace_clock into trace-input.c

[Steven Rostedt]

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

Move the extracting of the trace_clock logic into trace-input.c from
trace-util.c, and store it locally in the tracecmd_input handler. This will
allow us to remove the trace_clock logic from event_parse.c as it doesn't
belong there.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/trace-cmd/trace-cmd.h |  3 ++-
 lib/trace-cmd/trace-input.c   | 33 +++++++++++++++++++++++++++++++--
 lib/trace-cmd/trace-util.c    | 27 ---------------------------
 3 files changed, 33 insertions(+), 30 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 092bd896fb09..eb36a1f20c30 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -18,7 +18,6 @@
 #define TRACECMD_PTR2ERR(ptr)	((unisgned long)(ptr) & ~TRACECMD_ERR_MSK)
 
 void tracecmd_parse_cmdlines(struct tep_handle *pevent, char *file, int size);
-void tracecmd_parse_trace_clock(struct tep_handle *pevent, char *file, int size);
 void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent, char *file, unsigned int size);
 void tracecmd_parse_ftrace_printk(struct tep_handle *pevent, char *file, unsigned int size);
 
@@ -124,6 +123,8 @@ void tracecmd_set_flag(struct tracecmd_input *handle, int flag);
 void tracecmd_clear_flag(struct tracecmd_input *handle, int flag);
 unsigned long tracecmd_get_flags(struct tracecmd_input *handle);
 
+void tracecmd_parse_trace_clock(struct tracecmd_input *handle, char *file, int size);
+
 int tracecmd_make_pipe(struct tracecmd_input *handle, int cpu, int fd, int cpus);
 
 int tracecmd_buffer_instances(struct tracecmd_input *handle);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 8cceb31cefef..5533d42fd7c2 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -95,6 +95,7 @@ struct tracecmd_input {
 	char *			cpustats;
 	char *			uname;
 	char *			version;
+	char *			trace_clock;
 	struct input_buffer_instance	*buffers;
 	int			parsing_failures;
 
@@ -2571,6 +2572,33 @@ static int read_and_parse_cmdlines(struct tracecmd_input *handle)
 	return 0;
 }
 
+static void extract_trace_clock(struct tracecmd_input *handle, char *line)
+{
+	char *data;
+	char *clock;
+	char *next = NULL;
+
+	data = strtok_r(line, "[]", &next);
+	sscanf(data, "%ms", &clock);
+	/* TODO: report if it fails to allocate */
+	handle->trace_clock = clock;
+}
+
+void tracecmd_parse_trace_clock(struct tracecmd_input *handle,
+				char *file, int size __maybe_unused)
+{
+	char *line;
+	char *next = NULL;
+
+	line = strtok_r(file, " ", &next);
+	while (line) {
+		/* current trace_clock is shown as "[local]". */
+		if (*line == '[')
+			return extract_trace_clock(handle, line);
+		line = strtok_r(NULL, " ", &next);
+	}
+}
+
 static int read_and_parse_trace_clock(struct tracecmd_input *handle,
 							struct tep_handle *pevent)
 {
@@ -2580,7 +2608,7 @@ static int read_and_parse_trace_clock(struct tracecmd_input *handle,
 	if (read_data_and_size(handle, &trace_clock, &size) < 0)
 		return -1;
 	trace_clock[size] = 0;
-	tracecmd_parse_trace_clock(pevent, trace_clock, size);
+	tracecmd_parse_trace_clock(handle, trace_clock, size);
 	free(trace_clock);
 	return 0;
 }
@@ -2618,7 +2646,7 @@ int tracecmd_init_data(struct tracecmd_input *handle)
 		if (read_and_parse_trace_clock(handle, pevent) < 0) {
 			char clock[] = "[local]";
 			warning("File has trace_clock bug, using local clock");
-			tracecmd_parse_trace_clock(pevent, clock, 8);
+			tracecmd_parse_trace_clock(handle, clock, 8);
 		}
 	}
 
@@ -3011,6 +3039,7 @@ void tracecmd_close(struct tracecmd_input *handle)
 	free(handle->cpustats);
 	free(handle->cpu_data);
 	free(handle->uname);
+	free(handle->trace_clock);
 	close(handle->fd);
 
 	tracecmd_free_hooks(handle->hooks);
diff --git a/lib/trace-cmd/trace-util.c b/lib/trace-cmd/trace-util.c
index b08e377c61ba..38584c200fa1 100644
--- a/lib/trace-cmd/trace-util.c
+++ b/lib/trace-cmd/trace-util.c
@@ -70,33 +70,6 @@ void tracecmd_parse_cmdlines(struct tep_handle *pevent,
 	}
 }
 
-static void extract_trace_clock(struct tep_handle *pevent, char *line)
-{
-	char *data;
-	char *clock;
-	char *next = NULL;
-
-	data = strtok_r(line, "[]", &next);
-	sscanf(data, "%ms", &clock);
-	tep_register_trace_clock(pevent, clock);
-	free(clock);
-}
-
-void tracecmd_parse_trace_clock(struct tep_handle *pevent,
-				char *file, int size __maybe_unused)
-{
-	char *line;
-	char *next = NULL;
-
-	line = strtok_r(file, " ", &next);
-	while (line) {
-		/* current trace_clock is shown as "[local]". */
-		if (*line == '[')
-			return extract_trace_clock(pevent, line);
-		line = strtok_r(NULL, " ", &next);
-	}
-}
-
 void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent,
 			 char *file, unsigned int size __maybe_unused)
 {
-- 
2.20.1

Re: [PATCH 1/5] trace-cmd: Move extract trace_clock into trace-input.c

[Tzvetomir Stoyanov]

On Wed, Sep 18, 2019 at 5:03 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
> Move the extracting of the trace_clock logic into trace-input.c from
> trace-util.c, and store it locally in the tracecmd_input handler. This will
> allow us to remove the trace_clock logic from event_parse.c as it doesn't
> belong there.
>
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  include/trace-cmd/trace-cmd.h |  3 ++-
>  lib/trace-cmd/trace-input.c   | 33 +++++++++++++++++++++++++++++++--
>  lib/trace-cmd/trace-util.c    | 27 ---------------------------
>  3 files changed, 33 insertions(+), 30 deletions(-)
>
> diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
> index 092bd896fb09..eb36a1f20c30 100644
> --- a/include/trace-cmd/trace-cmd.h
> +++ b/include/trace-cmd/trace-cmd.h
> @@ -18,7 +18,6 @@
>  #define TRACECMD_PTR2ERR(ptr)  ((unisgned long)(ptr) & ~TRACECMD_ERR_MSK)
>
>  void tracecmd_parse_cmdlines(struct tep_handle *pevent, char *file, int size);
> -void tracecmd_parse_trace_clock(struct tep_handle *pevent, char *file, int size);
>  void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent, char *file, unsigned int size);
>  void tracecmd_parse_ftrace_printk(struct tep_handle *pevent, char *file, unsigned int size);
>
> @@ -124,6 +123,8 @@ void tracecmd_set_flag(struct tracecmd_input *handle, int flag);
>  void tracecmd_clear_flag(struct tracecmd_input *handle, int flag);
>  unsigned long tracecmd_get_flags(struct tracecmd_input *handle);
>
> +void tracecmd_parse_trace_clock(struct tracecmd_input *handle, char *file, int size);
> +
>  int tracecmd_make_pipe(struct tracecmd_input *handle, int cpu, int fd, int cpus);
>
>  int tracecmd_buffer_instances(struct tracecmd_input *handle);
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index 8cceb31cefef..5533d42fd7c2 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -95,6 +95,7 @@ struct tracecmd_input {
>         char *                  cpustats;
>         char *                  uname;
>         char *                  version;
> +       char *                  trace_clock;
>         struct input_buffer_instance    *buffers;
>         int                     parsing_failures;
>
> @@ -2571,6 +2572,33 @@ static int read_and_parse_cmdlines(struct tracecmd_input *handle)
>         return 0;
>  }
>
> +static void extract_trace_clock(struct tracecmd_input *handle, char *line)
> +{
> +       char *data;
> +       char *clock;

I would recommend to initialize clock with NULL, so in case sscanf fails due to
broken line or mem alloc, handle->trace_clock will not point to random memory.

> +       char *next = NULL;
> +
> +       data = strtok_r(line, "[]", &next);
> +       sscanf(data, "%ms", &clock);
> +       /* TODO: report if it fails to allocate */
> +       handle->trace_clock = clock;
> +}
> +
> +void tracecmd_parse_trace_clock(struct tracecmd_input *handle,
> +                               char *file, int size __maybe_unused)
> +{
> +       char *line;
> +       char *next = NULL;
> +
> +       line = strtok_r(file, " ", &next);
> +       while (line) {
> +               /* current trace_clock is shown as "[local]". */
> +               if (*line == '[')
> +                       return extract_trace_clock(handle, line);
> +               line = strtok_r(NULL, " ", &next);
> +       }
> +}
> +
>  static int read_and_parse_trace_clock(struct tracecmd_input *handle,
>                                                         struct tep_handle *pevent)
>  {
> @@ -2580,7 +2608,7 @@ static int read_and_parse_trace_clock(struct tracecmd_input *handle,
>         if (read_data_and_size(handle, &trace_clock, &size) < 0)
>                 return -1;
>         trace_clock[size] = 0;
> -       tracecmd_parse_trace_clock(pevent, trace_clock, size);
> +       tracecmd_parse_trace_clock(handle, trace_clock, size);
>         free(trace_clock);
>         return 0;
>  }
> @@ -2618,7 +2646,7 @@ int tracecmd_init_data(struct tracecmd_input *handle)
>                 if (read_and_parse_trace_clock(handle, pevent) < 0) {
>                         char clock[] = "[local]";
>                         warning("File has trace_clock bug, using local clock");
> -                       tracecmd_parse_trace_clock(pevent, clock, 8);
> +                       tracecmd_parse_trace_clock(handle, clock, 8);
>                 }
>         }
>
> @@ -3011,6 +3039,7 @@ void tracecmd_close(struct tracecmd_input *handle)
>         free(handle->cpustats);
>         free(handle->cpu_data);
>         free(handle->uname);
> +       free(handle->trace_clock);
>         close(handle->fd);
>
>         tracecmd_free_hooks(handle->hooks);
> diff --git a/lib/trace-cmd/trace-util.c b/lib/trace-cmd/trace-util.c
> index b08e377c61ba..38584c200fa1 100644
> --- a/lib/trace-cmd/trace-util.c
> +++ b/lib/trace-cmd/trace-util.c
> @@ -70,33 +70,6 @@ void tracecmd_parse_cmdlines(struct tep_handle *pevent,
>         }
>  }
>
> -static void extract_trace_clock(struct tep_handle *pevent, char *line)
> -{
> -       char *data;
> -       char *clock;
> -       char *next = NULL;
> -
> -       data = strtok_r(line, "[]", &next);
> -       sscanf(data, "%ms", &clock);
> -       tep_register_trace_clock(pevent, clock);
> -       free(clock);
> -}
> -
> -void tracecmd_parse_trace_clock(struct tep_handle *pevent,
> -                               char *file, int size __maybe_unused)
> -{
> -       char *line;
> -       char *next = NULL;
> -
> -       line = strtok_r(file, " ", &next);
> -       while (line) {
> -               /* current trace_clock is shown as "[local]". */
> -               if (*line == '[')
> -                       return extract_trace_clock(pevent, line);
> -               line = strtok_r(NULL, " ", &next);
> -       }
> -}
> -
>  void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent,
>                          char *file, unsigned int size __maybe_unused)
>  {
> --
> 2.20.1
>
>


-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: [PATCH 1/5] trace-cmd: Move extract trace_clock into trace-input.c

[Steven Rostedt]

On Fri, 20 Sep 2019 14:55:21 +0000
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:


> >
> > +static void extract_trace_clock(struct tracecmd_input *handle, char *line)
> > +{
> > +       char *data;
> > +       char *clock;  
> 
> I would recommend to initialize clock with NULL, so in case sscanf fails due to
> broken line or mem alloc, handle->trace_clock will not point to random memory.

Good catch! Thanks, I'll update.

-- Steve

> 
> > +       char *next = NULL;
> > +
> > +       data = strtok_r(line, "[]", &next);
> > +       sscanf(data, "%ms", &clock);
> > +       /* TODO: report if it fails to allocate */
> > +       handle->trace_clock = clock;
> > +}
> > +

[PATCH 1/5 v2] trace-cmd: Move extract trace_clock into trace-input.c

[Steven Rostedt]

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

Move the extracting of the trace_clock logic into trace-input.c from
trace-util.c, and store it locally in the tracecmd_input handler. This will
allow us to remove the trace_clock logic from event_parse.c as it doesn't
belong there.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
Changes since v1:

 - Initialized clock to NULL in case scanf failed (Tzvetomir Stoyanov)

 include/trace-cmd/trace-cmd.h |  3 ++-
 lib/trace-cmd/trace-input.c   | 33 +++++++++++++++++++++++++++++++--
 lib/trace-cmd/trace-util.c    | 27 ---------------------------
 3 files changed, 33 insertions(+), 30 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 7a9fbc5f..2d4c6e8f 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -18,7 +18,6 @@
 #define TRACECMD_PTR2ERR(ptr)	((unisgned long)(ptr) & ~TRACECMD_ERR_MSK)
 
 void tracecmd_parse_cmdlines(struct tep_handle *pevent, char *file, int size);
-void tracecmd_parse_trace_clock(struct tep_handle *pevent, char *file, int size);
 void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent, char *file, unsigned int size);
 void tracecmd_parse_ftrace_printk(struct tep_handle *pevent, char *file, unsigned int size);
 
@@ -127,6 +126,8 @@ void tracecmd_set_flag(struct tracecmd_input *handle, int flag);
 void tracecmd_clear_flag(struct tracecmd_input *handle, int flag);
 unsigned long tracecmd_get_flags(struct tracecmd_input *handle);
 
+void tracecmd_parse_trace_clock(struct tracecmd_input *handle, char *file, int size);
+
 int tracecmd_make_pipe(struct tracecmd_input *handle, int cpu, int fd, int cpus);
 
 int tracecmd_buffer_instances(struct tracecmd_input *handle);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 8cceb31c..f469118a 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -95,6 +95,7 @@ struct tracecmd_input {
 	char *			cpustats;
 	char *			uname;
 	char *			version;
+	char *			trace_clock;
 	struct input_buffer_instance	*buffers;
 	int			parsing_failures;
 
@@ -2571,6 +2572,33 @@ static int read_and_parse_cmdlines(struct tracecmd_input *handle)
 	return 0;
 }
 
+static void extract_trace_clock(struct tracecmd_input *handle, char *line)
+{
+	char *clock = NULL;
+	char *next = NULL;
+	char *data;
+
+	data = strtok_r(line, "[]", &next);
+	sscanf(data, "%ms", &clock);
+	/* TODO: report if it fails to allocate */
+	handle->trace_clock = clock;
+}
+
+void tracecmd_parse_trace_clock(struct tracecmd_input *handle,
+				char *file, int size __maybe_unused)
+{
+	char *line;
+	char *next = NULL;
+
+	line = strtok_r(file, " ", &next);
+	while (line) {
+		/* current trace_clock is shown as "[local]". */
+		if (*line == '[')
+			return extract_trace_clock(handle, line);
+		line = strtok_r(NULL, " ", &next);
+	}
+}
+
 static int read_and_parse_trace_clock(struct tracecmd_input *handle,
 							struct tep_handle *pevent)
 {
@@ -2580,7 +2608,7 @@ static int read_and_parse_trace_clock(struct tracecmd_input *handle,
 	if (read_data_and_size(handle, &trace_clock, &size) < 0)
 		return -1;
 	trace_clock[size] = 0;
-	tracecmd_parse_trace_clock(pevent, trace_clock, size);
+	tracecmd_parse_trace_clock(handle, trace_clock, size);
 	free(trace_clock);
 	return 0;
 }
@@ -2618,7 +2646,7 @@ int tracecmd_init_data(struct tracecmd_input *handle)
 		if (read_and_parse_trace_clock(handle, pevent) < 0) {
 			char clock[] = "[local]";
 			warning("File has trace_clock bug, using local clock");
-			tracecmd_parse_trace_clock(pevent, clock, 8);
+			tracecmd_parse_trace_clock(handle, clock, 8);
 		}
 	}
 
@@ -3011,6 +3039,7 @@ void tracecmd_close(struct tracecmd_input *handle)
 	free(handle->cpustats);
 	free(handle->cpu_data);
 	free(handle->uname);
+	free(handle->trace_clock);
 	close(handle->fd);
 
 	tracecmd_free_hooks(handle->hooks);
diff --git a/lib/trace-cmd/trace-util.c b/lib/trace-cmd/trace-util.c
index c153e4b7..8aa3b6cd 100644
--- a/lib/trace-cmd/trace-util.c
+++ b/lib/trace-cmd/trace-util.c
@@ -73,33 +73,6 @@ void tracecmd_parse_cmdlines(struct tep_handle *pevent,
 	}
 }
 
-static void extract_trace_clock(struct tep_handle *pevent, char *line)
-{
-	char *data;
-	char *clock;
-	char *next = NULL;
-
-	data = strtok_r(line, "[]", &next);
-	sscanf(data, "%ms", &clock);
-	tep_register_trace_clock(pevent, clock);
-	free(clock);
-}
-
-void tracecmd_parse_trace_clock(struct tep_handle *pevent,
-				char *file, int size __maybe_unused)
-{
-	char *line;
-	char *next = NULL;
-
-	line = strtok_r(file, " ", &next);
-	while (line) {
-		/* current trace_clock is shown as "[local]". */
-		if (*line == '[')
-			return extract_trace_clock(pevent, line);
-		line = strtok_r(NULL, " ", &next);
-	}
-}
-
 void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent,
 			 char *file, unsigned int size __maybe_unused)
 {
-- 
2.20.1

Re: [PATCH 1/5 v2] trace-cmd: Move extract trace_clock into trace-input.c

[Tzvetomir Stoyanov]

On Fri, Sep 20, 2019 at 6:10 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
>
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
> Move the extracting of the trace_clock logic into trace-input.c from
> trace-util.c, and store it locally in the tracecmd_input handler. This will
> allow us to remove the trace_clock logic from event_parse.c as it doesn't
> belong there.
>
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
> Changes since v1:
>
>  - Initialized clock to NULL in case scanf failed (Tzvetomir Stoyanov)
>
>  include/trace-cmd/trace-cmd.h |  3 ++-
>  lib/trace-cmd/trace-input.c   | 33 +++++++++++++++++++++++++++++++--
>  lib/trace-cmd/trace-util.c    | 27 ---------------------------
>  3 files changed, 33 insertions(+), 30 deletions(-)
>
> diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
> index 7a9fbc5f..2d4c6e8f 100644
> --- a/include/trace-cmd/trace-cmd.h
> +++ b/include/trace-cmd/trace-cmd.h
> @@ -18,7 +18,6 @@
>  #define TRACECMD_PTR2ERR(ptr)  ((unisgned long)(ptr) & ~TRACECMD_ERR_MSK)
>
>  void tracecmd_parse_cmdlines(struct tep_handle *pevent, char *file, int size);
> -void tracecmd_parse_trace_clock(struct tep_handle *pevent, char *file, int size);
>  void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent, char *file, unsigned int size);
>  void tracecmd_parse_ftrace_printk(struct tep_handle *pevent, char *file, unsigned int size);
>
> @@ -127,6 +126,8 @@ void tracecmd_set_flag(struct tracecmd_input *handle, int flag);
>  void tracecmd_clear_flag(struct tracecmd_input *handle, int flag);
>  unsigned long tracecmd_get_flags(struct tracecmd_input *handle);
>
> +void tracecmd_parse_trace_clock(struct tracecmd_input *handle, char *file, int size);
> +
>  int tracecmd_make_pipe(struct tracecmd_input *handle, int cpu, int fd, int cpus);
>
>  int tracecmd_buffer_instances(struct tracecmd_input *handle);
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index 8cceb31c..f469118a 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -95,6 +95,7 @@ struct tracecmd_input {
>         char *                  cpustats;
>         char *                  uname;
>         char *                  version;
> +       char *                  trace_clock;
>         struct input_buffer_instance    *buffers;
>         int                     parsing_failures;
>
> @@ -2571,6 +2572,33 @@ static int read_and_parse_cmdlines(struct tracecmd_input *handle)
>         return 0;
>  }
>
> +static void extract_trace_clock(struct tracecmd_input *handle, char *line)
> +{
> +       char *clock = NULL;
> +       char *next = NULL;
> +       char *data;
> +
> +       data = strtok_r(line, "[]", &next);
> +       sscanf(data, "%ms", &clock);
> +       /* TODO: report if it fails to allocate */
> +       handle->trace_clock = clock;
> +}
> +
> +void tracecmd_parse_trace_clock(struct tracecmd_input *handle,
> +                               char *file, int size __maybe_unused)
> +{
> +       char *line;
> +       char *next = NULL;
> +
> +       line = strtok_r(file, " ", &next);
> +       while (line) {
> +               /* current trace_clock is shown as "[local]". */
> +               if (*line == '[')
> +                       return extract_trace_clock(handle, line);
> +               line = strtok_r(NULL, " ", &next);
> +       }
> +}
> +
>  static int read_and_parse_trace_clock(struct tracecmd_input *handle,
>                                                         struct tep_handle *pevent)
>  {
> @@ -2580,7 +2608,7 @@ static int read_and_parse_trace_clock(struct tracecmd_input *handle,
>         if (read_data_and_size(handle, &trace_clock, &size) < 0)
>                 return -1;
>         trace_clock[size] = 0;
> -       tracecmd_parse_trace_clock(pevent, trace_clock, size);
> +       tracecmd_parse_trace_clock(handle, trace_clock, size);
>         free(trace_clock);
>         return 0;
>  }
> @@ -2618,7 +2646,7 @@ int tracecmd_init_data(struct tracecmd_input *handle)
>                 if (read_and_parse_trace_clock(handle, pevent) < 0) {
>                         char clock[] = "[local]";
>                         warning("File has trace_clock bug, using local clock");
> -                       tracecmd_parse_trace_clock(pevent, clock, 8);
> +                       tracecmd_parse_trace_clock(handle, clock, 8);
>                 }
>         }
>
> @@ -3011,6 +3039,7 @@ void tracecmd_close(struct tracecmd_input *handle)
>         free(handle->cpustats);
>         free(handle->cpu_data);
>         free(handle->uname);
> +       free(handle->trace_clock);
>         close(handle->fd);
>
>         tracecmd_free_hooks(handle->hooks);
> diff --git a/lib/trace-cmd/trace-util.c b/lib/trace-cmd/trace-util.c
> index c153e4b7..8aa3b6cd 100644
> --- a/lib/trace-cmd/trace-util.c
> +++ b/lib/trace-cmd/trace-util.c
> @@ -73,33 +73,6 @@ void tracecmd_parse_cmdlines(struct tep_handle *pevent,
>         }
>  }
>
> -static void extract_trace_clock(struct tep_handle *pevent, char *line)
> -{
> -       char *data;
> -       char *clock;
> -       char *next = NULL;
> -
> -       data = strtok_r(line, "[]", &next);
> -       sscanf(data, "%ms", &clock);
> -       tep_register_trace_clock(pevent, clock);
> -       free(clock);
> -}
> -
> -void tracecmd_parse_trace_clock(struct tep_handle *pevent,
> -                               char *file, int size __maybe_unused)
> -{
> -       char *line;
> -       char *next = NULL;
> -
> -       line = strtok_r(file, " ", &next);
> -       while (line) {
> -               /* current trace_clock is shown as "[local]". */
> -               if (*line == '[')
> -                       return extract_trace_clock(pevent, line);
> -               line = strtok_r(NULL, " ", &next);
> -       }
> -}
> -
>  void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent,
>                          char *file, unsigned int size __maybe_unused)
>  {
> --
> 2.20.1
>

Looks good, thanks Steven.

Reviewed-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>


-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: [PATCH 1/5 v2] trace-cmd: Move extract trace_clock into trace-input.c

[Steven Rostedt]

On Fri, 20 Sep 2019 16:08:01 +0000
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:


> 
> Looks good, thanks Steven.
> 
> Reviewed-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> 
> 

Thanks Tzvetomir for all the reviews!

-- Steve

[PATCH 2/5] trace-cmd: Separate out time diff code in trace_show_data()

[Steven Rostedt]

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

To make it easier to convert to the new tep_print_event() format, use the
open coded version of the tracing data regardless if a different timestamp
is to be used.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 tracecmd/trace-read.c | 17 +++++++++--------
 1 file changed, 9 insertions(+), 8 deletions(-)

diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index c14e87f76a32..01d904964edf 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -757,6 +757,7 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 {
 	tracecmd_show_data_func func = tracecmd_get_show_data_func(handle);
 	struct tep_handle *pevent;
+	struct tep_event *event;
 	struct trace_seq s;
 	int cpu = record->cpu;
 	bool use_trace_clock;
@@ -793,14 +794,13 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 		}
 	}
 	use_trace_clock = tracecmd_get_use_trace_clock(handle);
+	event = tep_find_event_by_record(pevent, record);
+	tep_print_event_task(pevent, &s, event, record);
+	tep_print_event_time(pevent, &s, event, record,
+			     use_trace_clock);
 	if (tsdiff) {
 		unsigned long long rec_ts = record->ts;
-		struct tep_event *event;
 
-		event = tep_find_event_by_record(pevent, record);
-		tep_print_event_task(pevent, &s, event, record);
-		tep_print_event_time(pevent, &s, event, record,
-					use_trace_clock);
 		buf[0] = 0;
 		if (use_trace_clock && !tep_test_flag(pevent, TEP_NSEC_OUTPUT))
 			rec_ts = (rec_ts + 500) / 1000;
@@ -811,9 +811,10 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 		}
 		last_ts = rec_ts;
 		trace_seq_printf(&s, " %-8s", buf);
-		tep_print_event_data(pevent, &s, event, record);
-	} else
-		tep_print_event(pevent, &s, record, use_trace_clock);
+	}
+
+	tep_print_event_data(pevent, &s, event, record);
+
 	if (s.len && *(s.buffer + s.len - 1) == '\n')
 		s.len--;
 	if (tracecmd_get_debug()) {
-- 
2.20.1

Re: [PATCH 2/5] trace-cmd: Separate out time diff code in trace_show_data()

[Tzvetomir Stoyanov]

On Wed, Sep 18, 2019 at 5:03 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
> To make it easier to convert to the new tep_print_event() format, use the
> open coded version of the tracing data regardless if a different timestamp
> is to be used.
>
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  tracecmd/trace-read.c | 17 +++++++++--------
>  1 file changed, 9 insertions(+), 8 deletions(-)
>
> diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
> index c14e87f76a32..01d904964edf 100644
> --- a/tracecmd/trace-read.c
> +++ b/tracecmd/trace-read.c
> @@ -757,6 +757,7 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
>  {
>         tracecmd_show_data_func func = tracecmd_get_show_data_func(handle);
>         struct tep_handle *pevent;
> +       struct tep_event *event;
>         struct trace_seq s;
>         int cpu = record->cpu;
>         bool use_trace_clock;
> @@ -793,14 +794,13 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
>                 }
>         }
>         use_trace_clock = tracecmd_get_use_trace_clock(handle);
> +       event = tep_find_event_by_record(pevent, record);
> +       tep_print_event_task(pevent, &s, event, record);
> +       tep_print_event_time(pevent, &s, event, record,
> +                            use_trace_clock);
>         if (tsdiff) {
>                 unsigned long long rec_ts = record->ts;
> -               struct tep_event *event;
>
> -               event = tep_find_event_by_record(pevent, record);
> -               tep_print_event_task(pevent, &s, event, record);
> -               tep_print_event_time(pevent, &s, event, record,
> -                                       use_trace_clock);
>                 buf[0] = 0;
>                 if (use_trace_clock && !tep_test_flag(pevent, TEP_NSEC_OUTPUT))
>                         rec_ts = (rec_ts + 500) / 1000;
> @@ -811,9 +811,10 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
>                 }
>                 last_ts = rec_ts;
>                 trace_seq_printf(&s, " %-8s", buf);
> -               tep_print_event_data(pevent, &s, event, record);
> -       } else
> -               tep_print_event(pevent, &s, record, use_trace_clock);
> +       }
> +
> +       tep_print_event_data(pevent, &s, event, record);
> +
>         if (s.len && *(s.buffer + s.len - 1) == '\n')
>                 s.len--;
>         if (tracecmd_get_debug()) {
> --
> 2.20.1
>
>

Looks good to me.
Reviewed-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>


-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

[PATCH 3/5] trace-cmd: Add check for trace_clock using usecs into tracecmd_parse_trace_clock()

[Steven Rostedt]

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

In preparation for using the new tep_print_event() format, move the logic of
checking if the trace_clock used should be default as printed in usecs into
tracecmd_parse_trace_clock() when it parses the trace_clock.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/trace-cmd/trace-cmd.h | 1 +
 lib/trace-cmd/trace-input.c   | 8 ++++++++
 2 files changed, 9 insertions(+)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index eb36a1f20c30..7c3bc2229461 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -87,6 +87,7 @@ enum {
 	TRACECMD_FL_IGNORE_DATE		= (1 << 0),
 	TRACECMD_FL_BUFFER_INSTANCE	= (1 << 1),
 	TRACECMD_FL_LATENCY		= (1 << 2),
+	TRACECMD_FL_IN_USECS		= (1 << 3),
 };
 
 struct tracecmd_ftrace {
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 5533d42fd7c2..73f27a4e50d0 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -2582,6 +2582,14 @@ static void extract_trace_clock(struct tracecmd_input *handle, char *line)
 	sscanf(data, "%ms", &clock);
 	/* TODO: report if it fails to allocate */
 	handle->trace_clock = clock;
+
+	if (!clock)
+		return;
+
+	if (!strcmp(clock, "local") || !strcmp(clock, "global")
+	    || !strcmp(clock, "uptime") || !strcmp(clock, "perf")
+	    || !strncmp(clock, "mono", 4))
+		handle->flags |= TRACECMD_FL_IN_USECS;
 }
 
 void tracecmd_parse_trace_clock(struct tracecmd_input *handle,
-- 
2.20.1

Re: [PATCH 3/5] trace-cmd: Add check for trace_clock using usecs into tracecmd_parse_trace_clock()

[Tzvetomir Stoyanov]

On Wed, Sep 18, 2019 at 5:03 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
> In preparation for using the new tep_print_event() format, move the logic of
> checking if the trace_clock used should be default as printed in usecs into
> tracecmd_parse_trace_clock() when it parses the trace_clock.
>
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  include/trace-cmd/trace-cmd.h | 1 +
>  lib/trace-cmd/trace-input.c   | 8 ++++++++
>  2 files changed, 9 insertions(+)
>
> diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
> index eb36a1f20c30..7c3bc2229461 100644
> --- a/include/trace-cmd/trace-cmd.h
> +++ b/include/trace-cmd/trace-cmd.h
> @@ -87,6 +87,7 @@ enum {
>         TRACECMD_FL_IGNORE_DATE         = (1 << 0),
>         TRACECMD_FL_BUFFER_INSTANCE     = (1 << 1),
>         TRACECMD_FL_LATENCY             = (1 << 2),
> +       TRACECMD_FL_IN_USECS            = (1 << 3),
>  };
>
>  struct tracecmd_ftrace {
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index 5533d42fd7c2..73f27a4e50d0 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -2582,6 +2582,14 @@ static void extract_trace_clock(struct tracecmd_input *handle, char *line)
>         sscanf(data, "%ms", &clock);
>         /* TODO: report if it fails to allocate */
>         handle->trace_clock = clock;
> +
> +       if (!clock)
> +               return;
> +
> +       if (!strcmp(clock, "local") || !strcmp(clock, "global")
> +           || !strcmp(clock, "uptime") || !strcmp(clock, "perf")
> +           || !strncmp(clock, "mono", 4))
> +               handle->flags |= TRACECMD_FL_IN_USECS;
>  }
>
>  void tracecmd_parse_trace_clock(struct tracecmd_input *handle,
> --
> 2.20.1
>
>

Looks OK.
Reviewed-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>

-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

[PATCH 4/5] libtraceevent, perf tools: Changes in tep_print_event_* APIs

[Steven Rostedt]

From: Tzvetomir Stoyanov <tstoyanov@vmware.com>

Libtraceevent APIs for printing various trace events information are
complicated, there are complex extra parameters. To control the way
event information is printed, the user should call a set of functions in
a specific sequence.

These APIs are reimplemented to provide a more simple interface for
printing event information.

Removed APIs:

 	tep_print_event_task()
	tep_print_event_time()
	tep_print_event_data()
	tep_event_info()
	tep_is_latency_format()
	tep_set_latency_format()
	tep_data_latency_format()
	tep_set_print_raw()

A new API for printing event information is introduced:
   void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
		        struct tep_record *record, const char *fmt, ...);
where "fmt" is a printf-like format string, followed by the event
fields to be printed. Supported fields:
 TEP_PRINT_PID, "%d" - event PID
 TEP_PRINT_CPU, "%d" - event CPU
 TEP_PRINT_COMM, "%s" - event command string
 TEP_PRINT_NAME, "%s" - event name
 TEP_PRINT_LATENCY, "%s" - event latency
 TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
   can be specified as part of this format string:
   "%precision.divisord". Example:
   "%3.1000d" - divide the time by 1000 and print the first 3 digits
   before the dot. Thus, the time stamp "123456000" will be printed as
   "123.456"
 TEP_PRINT_INFO, "%s" - event information.
 TEP_PRINT_INFO_RAW, "%s" - event information, in raw format.

Example:
  tep_print_event(tep, s, record, "%16s-%-5d [%03d] %s %6.1000d %s %s",
		  TEP_PRINT_COMM, TEP_PRINT_PID, TEP_PRINT_CPU,
		  TEP_PRINT_LATENCY, TEP_PRINT_TIME, TEP_PRINT_NAME, TEP_PRINT_INFO);
Output:
	ls-11314 [005] d.h. 185207.366383 function __wake_up

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Cc: Patrick McLean <chutzpah@gentoo.org>
Link: http://lore.kernel.org/linux-trace-devel/20190801074959.22023-2-tz.stoyanov@gmail.com
Link: http://lore.kernel.org/lkml/20190805204355.041132030@goodmis.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
[ Added support for trace-cmd trace-read.c ]
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/traceevent/event-parse.h   |  29 +--
 lib/traceevent/event-parse-api.c   |  40 ----
 lib/traceevent/event-parse-local.h |   4 -
 lib/traceevent/event-parse.c       | 322 +++++++++++++++++------------
 tracecmd/trace-read.c              |  78 ++++---
 5 files changed, 250 insertions(+), 223 deletions(-)

diff --git a/include/traceevent/event-parse.h b/include/traceevent/event-parse.h
index 99da5ef89c83..5dff952d1ea1 100644
--- a/include/traceevent/event-parse.h
+++ b/include/traceevent/event-parse.h
@@ -436,18 +436,18 @@ int tep_register_print_string(struct tep_handle *tep, const char *fmt,
 			      unsigned long long addr);
 bool tep_is_pid_registered(struct tep_handle *tep, int pid);
 
-void tep_print_event_task(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record);
-void tep_print_event_time(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record,
-			  bool use_trace_clock);
-void tep_print_event_data(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record);
+#define TEP_PRINT_INFO		"INFO"
+#define TEP_PRINT_INFO_RAW	"INFO_RAW"
+#define TEP_PRINT_COMM		"COMM"
+#define TEP_PRINT_LATENCY	"LATENCY"
+#define TEP_PRINT_NAME		"NAME"
+#define TEP_PRINT_PID		1U
+#define TEP_PRINT_TIME		2U
+#define TEP_PRINT_CPU		3U
+
 void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
-		     struct tep_record *record, bool use_trace_clock);
+		     struct tep_record *record, const char *fmt, ...)
+	__attribute__ ((format (printf, 4, 5)));
 
 int tep_parse_header_page(struct tep_handle *tep, char *buf, unsigned long size,
 			  int long_size);
@@ -520,8 +520,6 @@ tep_find_event_by_name(struct tep_handle *tep, const char *sys, const char *name
 struct tep_event *
 tep_find_event_by_record(struct tep_handle *tep, struct tep_record *record);
 
-void tep_data_latency_format(struct tep_handle *tep,
-			     struct trace_seq *s, struct tep_record *record);
 int tep_data_type(struct tep_handle *tep, struct tep_record *rec);
 int tep_data_pid(struct tep_handle *tep, struct tep_record *rec);
 int tep_data_preempt_count(struct tep_handle *tep, struct tep_record *rec);
@@ -536,8 +534,6 @@ void tep_print_field(struct trace_seq *s, void *data,
 		     struct tep_format_field *field);
 void tep_print_fields(struct trace_seq *s, void *data,
 		      int size __maybe_unused, struct tep_event *event);
-void tep_event_info(struct trace_seq *s, struct tep_event *event,
-		    struct tep_record *record);
 int tep_strerror(struct tep_handle *tep, enum tep_errno errnum,
 		 char *buf, size_t buflen);
 
@@ -562,12 +558,9 @@ bool tep_is_file_bigendian(struct tep_handle *tep);
 void tep_set_file_bigendian(struct tep_handle *tep, enum tep_endian endian);
 bool tep_is_local_bigendian(struct tep_handle *tep);
 void tep_set_local_bigendian(struct tep_handle *tep, enum tep_endian endian);
-bool tep_is_latency_format(struct tep_handle *tep);
-void tep_set_latency_format(struct tep_handle *tep, int lat);
 int tep_get_header_page_size(struct tep_handle *tep);
 int tep_get_header_timestamp_size(struct tep_handle *tep);
 bool tep_is_old_format(struct tep_handle *tep);
-void tep_set_print_raw(struct tep_handle *tep, int print_raw);
 void tep_set_test_filters(struct tep_handle *tep, int test_filters);
 
 struct tep_handle *tep_alloc(void);
diff --git a/lib/traceevent/event-parse-api.c b/lib/traceevent/event-parse-api.c
index 988587840c80..4faf52a65791 100644
--- a/lib/traceevent/event-parse-api.c
+++ b/lib/traceevent/event-parse-api.c
@@ -302,33 +302,6 @@ void tep_set_local_bigendian(struct tep_handle *tep, enum tep_endian endian)
 		tep->host_bigendian = endian;
 }
 
-/**
- * tep_is_latency_format - get if the latency output format is configured
- * @tep: a handle to the tep_handle
- *
- * This returns true if the latency output format is configured
- * If @tep is NULL, false is returned.
- */
-bool tep_is_latency_format(struct tep_handle *tep)
-{
-	if (tep)
-		return (tep->latency_format);
-	return false;
-}
-
-/**
- * tep_set_latency_format - set the latency output format
- * @tep: a handle to the tep_handle
- * @lat: non zero for latency output format
- *
- * This sets the latency output format
-  */
-void tep_set_latency_format(struct tep_handle *tep, int lat)
-{
-	if (tep)
-		tep->latency_format = lat;
-}
-
 /**
  * tep_is_old_format - get if an old kernel is used
  * @tep: a handle to the tep_handle
@@ -344,19 +317,6 @@ bool tep_is_old_format(struct tep_handle *tep)
 	return false;
 }
 
-/**
- * tep_set_print_raw - set a flag to force print in raw format
- * @tep: a handle to the tep_handle
- * @print_raw: the new value of the print_raw flag
- *
- * This sets a flag to force print in raw format
- */
-void tep_set_print_raw(struct tep_handle *tep, int print_raw)
-{
-	if (tep)
-		tep->print_raw = print_raw;
-}
-
 /**
  * tep_set_test_filters - set a flag to test a filter string
  * @tep: a handle to the tep_handle
diff --git a/lib/traceevent/event-parse-local.h b/lib/traceevent/event-parse-local.h
index 09aa142f7fdd..6e58ee1fe7c8 100644
--- a/lib/traceevent/event-parse-local.h
+++ b/lib/traceevent/event-parse-local.h
@@ -28,8 +28,6 @@ struct tep_handle {
 	enum tep_endian file_bigendian;
 	enum tep_endian host_bigendian;
 
-	int latency_format;
-
 	int old_format;
 
 	int cpus;
@@ -70,8 +68,6 @@ struct tep_handle {
 	int ld_offset;
 	int ld_size;
 
-	int print_raw;
-
 	int test_filters;
 
 	int flags;
diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
index 3e83636076b2..d1085aab9c43 100644
--- a/lib/traceevent/event-parse.c
+++ b/lib/traceevent/event-parse.c
@@ -5212,24 +5212,20 @@ out_failed:
 	}
 }
 
-/**
- * tep_data_latency_format - parse the data for the latency format
- * @tep: a handle to the trace event parser context
- * @s: the trace_seq to write to
- * @record: the record to read from
- *
+/*
  * This parses out the Latency format (interrupts disabled,
  * need rescheduling, in hard/soft interrupt, preempt count
  * and lock depth) and places it into the trace_seq.
  */
-void tep_data_latency_format(struct tep_handle *tep,
-			     struct trace_seq *s, struct tep_record *record)
+static void data_latency_format(struct tep_handle *tep, struct trace_seq *s,
+				char *format, struct tep_record *record)
 {
 	static int check_lock_depth = 1;
 	static int check_migrate_disable = 1;
 	static int lock_depth_exists;
 	static int migrate_disable_exists;
 	unsigned int lat_flags;
+	struct trace_seq sq;
 	unsigned int pc;
 	int lock_depth = 0;
 	int migrate_disable = 0;
@@ -5237,6 +5233,7 @@ void tep_data_latency_format(struct tep_handle *tep,
 	int softirq;
 	void *data = record->data;
 
+	trace_seq_init(&sq);
 	lat_flags = parse_common_flags(tep, data);
 	pc = parse_common_pc(tep, data);
 	/* lock_depth may not always exist */
@@ -5264,7 +5261,7 @@ void tep_data_latency_format(struct tep_handle *tep,
 	hardirq = lat_flags & TRACE_FLAG_HARDIRQ;
 	softirq = lat_flags & TRACE_FLAG_SOFTIRQ;
 
-	trace_seq_printf(s, "%c%c%c",
+	trace_seq_printf(&sq, "%c%c%c",
 	       (lat_flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
 	       (lat_flags & TRACE_FLAG_IRQS_NOSUPPORT) ?
 	       'X' : '.',
@@ -5274,24 +5271,32 @@ void tep_data_latency_format(struct tep_handle *tep,
 	       hardirq ? 'h' : softirq ? 's' : '.');
 
 	if (pc)
-		trace_seq_printf(s, "%x", pc);
+		trace_seq_printf(&sq, "%x", pc);
 	else
-		trace_seq_putc(s, '.');
+		trace_seq_printf(&sq, ".");
 
 	if (migrate_disable_exists) {
 		if (migrate_disable < 0)
-			trace_seq_putc(s, '.');
+			trace_seq_printf(&sq, ".");
 		else
-			trace_seq_printf(s, "%d", migrate_disable);
+			trace_seq_printf(&sq, "%d", migrate_disable);
 	}
 
 	if (lock_depth_exists) {
 		if (lock_depth < 0)
-			trace_seq_putc(s, '.');
+			trace_seq_printf(&sq, ".");
 		else
-			trace_seq_printf(s, "%d", lock_depth);
+			trace_seq_printf(&sq, "%d", lock_depth);
 	}
 
+	if (sq.state == TRACE_SEQ__MEM_ALLOC_FAILED) {
+		s->state = TRACE_SEQ__MEM_ALLOC_FAILED;
+		return;
+	}
+
+	trace_seq_terminate(&sq);
+	trace_seq_puts(s, sq.buffer);
+	trace_seq_destroy(&sq);
 	trace_seq_terminate(s);
 }
 
@@ -5452,21 +5457,16 @@ int tep_cmdline_pid(struct tep_handle *tep, struct tep_cmdline *cmdline)
 	return cmdline->pid;
 }
 
-/**
- * tep_event_info - parse the data into the print format
- * @s: the trace_seq to write to
- * @event: the handle to the event
- * @record: the record to read from
- *
+/*
  * This parses the raw @data using the given @event information and
  * writes the print format into the trace_seq.
  */
-void tep_event_info(struct trace_seq *s, struct tep_event *event,
-		    struct tep_record *record)
+static void print_event_info(struct trace_seq *s, char *format, bool raw,
+			     struct tep_event *event, struct tep_record *record)
 {
 	int print_pretty = 1;
 
-	if (event->tep->print_raw || (event->flags & TEP_EVENT_FL_PRINTRAW))
+	if (raw || (event->flags & TEP_EVENT_FL_PRINTRAW))
 		tep_print_fields(s, record->data, record->size, event);
 	else {
 
@@ -5481,20 +5481,6 @@ void tep_event_info(struct trace_seq *s, struct tep_event *event,
 	trace_seq_terminate(s);
 }
 
-static bool is_timestamp_in_us(char *trace_clock, bool use_trace_clock)
-{
-	if (!trace_clock || !use_trace_clock)
-		return true;
-
-	if (!strcmp(trace_clock, "local") || !strcmp(trace_clock, "global")
-	    || !strcmp(trace_clock, "uptime") || !strcmp(trace_clock, "perf")
-	    || !strncmp(trace_clock, "mono", 4))
-		return true;
-
-	/* trace_clock is setting in tsc or counter mode */
-	return false;
-}
-
 /**
  * tep_find_event_by_record - return the event from a given record
  * @tep: a handle to the trace event parser context
@@ -5518,129 +5504,195 @@ tep_find_event_by_record(struct tep_handle *tep, struct tep_record *record)
 	return tep_find_event(tep, type);
 }
 
-/**
- * tep_print_event_task - Write the event task comm, pid and CPU
- * @tep: a handle to the trace event parser context
- * @s: the trace_seq to write to
- * @event: the handle to the record's event
- * @record: The record to get the event from
- *
- * Writes the tasks comm, pid and CPU to @s.
+/*
+ * Writes the timestamp of the record into @s. Time divisor and precision can be
+ * specified as part of printf @format string. Example:
+ *	"%3.1000d" - divide the time by 1000 and print the first 3 digits
+ *	before the dot. Thus, the timestamp "123456000" will be printed as
+ *	"123.456"
  */
-void tep_print_event_task(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record)
+static void print_event_time(struct tep_handle *tep, struct trace_seq *s,
+				 char *format, struct tep_event *event,
+				 struct tep_record *record)
+{
+	unsigned long long time;
+	char *divstr;
+	int prec = 0, pr;
+	int div = 0;
+	int p10 = 1;
+
+	if (isdigit(*(format + 1)))
+		prec = atoi(format + 1);
+	divstr = strchr(format, '.');
+	if (divstr && isdigit(*(divstr + 1)))
+		div = atoi(divstr + 1);
+	time = record->ts;
+	if (div)
+		time /= div;
+	pr = prec;
+	while (pr--)
+		p10 *= 10;
+
+	if (p10 > 1 && p10 < time)
+		trace_seq_printf(s, "%5llu.%0*llu", time / p10, prec, time % p10);
+	else
+		trace_seq_printf(s, "%12llu\n", time);
+}
+
+struct print_event_type {
+	enum {
+		EVENT_TYPE_INT = 1,
+		EVENT_TYPE_STRING,
+		EVENT_TYPE_UNKNOWN,
+	} type;
+	char format[32];
+};
+
+static void print_string(struct tep_handle *tep, struct trace_seq *s,
+			 struct tep_record *record, struct tep_event *event,
+			 const char *arg, struct print_event_type *type)
 {
-	void *data = record->data;
 	const char *comm;
 	int pid;
 
-	pid = parse_common_pid(tep, data);
-	comm = find_cmdline(tep, pid);
+	if (strncmp(arg, TEP_PRINT_LATENCY, strlen(TEP_PRINT_LATENCY)) == 0) {
+		data_latency_format(tep, s, type->format, record);
+	} else if (strncmp(arg, TEP_PRINT_COMM, strlen(TEP_PRINT_COMM)) == 0) {
+		pid = parse_common_pid(tep, record->data);
+		comm = find_cmdline(tep, pid);
+		trace_seq_printf(s, type->format, comm);
+	} else if (strncmp(arg, TEP_PRINT_INFO_RAW, strlen(TEP_PRINT_INFO_RAW)) == 0) {
+		print_event_info(s, type->format, true, event, record);
+	} else if (strncmp(arg, TEP_PRINT_INFO, strlen(TEP_PRINT_INFO)) == 0) {
+		print_event_info(s, type->format, false, event, record);
+	} else if  (strncmp(arg, TEP_PRINT_NAME, strlen(TEP_PRINT_NAME)) == 0) {
+		trace_seq_printf(s, type->format, event->name);
+	} else {
+		trace_seq_printf(s, "[UNKNOWN TEP TYPE %s]", arg);
+	}
 
-	if (tep->latency_format)
-		trace_seq_printf(s, "%8.8s-%-5d %3d", comm, pid, record->cpu);
-	else
-		trace_seq_printf(s, "%16s-%-5d [%03d]", comm, pid, record->cpu);
 }
 
-/**
- * tep_print_event_time - Write the event timestamp
- * @tep: a handle to the trace event parser context
- * @s: the trace_seq to write to
- * @event: the handle to the record's event
- * @record: The record to get the event from
- * @use_trace_clock: Set to parse according to the @tep->trace_clock
- *
- * Writes the timestamp of the record into @s.
- */
-void tep_print_event_time(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record,
-			  bool use_trace_clock)
+static void print_int(struct tep_handle *tep, struct trace_seq *s,
+		      struct tep_record *record, struct tep_event *event,
+		      int arg, struct print_event_type *type)
 {
-	unsigned long secs;
-	unsigned long usecs;
-	unsigned long nsecs;
-	int p;
-	bool use_usec_format;
+	int param;
 
-	use_usec_format = is_timestamp_in_us(tep->trace_clock, use_trace_clock);
-	if (use_usec_format) {
-		secs = record->ts / NSEC_PER_SEC;
-		nsecs = record->ts - secs * NSEC_PER_SEC;
+	switch (arg) {
+	case TEP_PRINT_CPU:
+		param = record->cpu;
+		break;
+	case TEP_PRINT_PID:
+		param = parse_common_pid(tep, record->data);
+		break;
+	case TEP_PRINT_TIME:
+		return print_event_time(tep, s, type->format, event, record);
+	default:
+		return;
 	}
+	trace_seq_printf(s, type->format, param);
+}
 
-	if (tep->latency_format) {
-		tep_data_latency_format(tep, s, record);
-	}
+static int tep_print_event_param_type(char *format,
+				      struct print_event_type *type)
+{
+	char *str = format + 1;
+	int i = 1;
 
-	if (use_usec_format) {
-		if (tep->flags & TEP_NSEC_OUTPUT) {
-			usecs = nsecs;
-			p = 9;
-		} else {
-			usecs = (nsecs + 500) / NSEC_PER_USEC;
-			/* To avoid usecs larger than 1 sec */
-			if (usecs >= USEC_PER_SEC) {
-				usecs -= USEC_PER_SEC;
-				secs++;
-			}
-			p = 6;
+	type->type = EVENT_TYPE_UNKNOWN;
+	while (*str) {
+		switch (*str) {
+		case 'd':
+		case 'u':
+		case 'i':
+		case 'x':
+		case 'X':
+		case 'o':
+			type->type = EVENT_TYPE_INT;
+			break;
+		case 's':
+			type->type = EVENT_TYPE_STRING;
+			break;
 		}
-
-		trace_seq_printf(s, " %5lu.%0*lu:", secs, p, usecs);
-	} else
-		trace_seq_printf(s, " %12llu:", record->ts);
+		str++;
+		i++;
+		if (type->type != EVENT_TYPE_UNKNOWN)
+			break;
+	}
+	memset(type->format, 0, 32);
+	memcpy(type->format, format, i < 32 ? i : 31);
+	return i;
 }
 
 /**
- * tep_print_event_data - Write the event data section
+ * tep_print_event - Write various event information
  * @tep: a handle to the trace event parser context
  * @s: the trace_seq to write to
- * @event: the handle to the record's event
  * @record: The record to get the event from
- *
- * Writes the parsing of the record's data to @s.
+ * @format: a printf format string. Supported event fileds:
+ *	TEP_PRINT_PID, "%d" - event PID
+ *	TEP_PRINT_CPU, "%d" - event CPU
+ *	TEP_PRINT_COMM, "%s" - event command string
+ *	TEP_PRINT_NAME, "%s" - event name
+ *	TEP_PRINT_LATENCY, "%s" - event latency
+ *	TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
+ *			can be specified as part of this format string:
+ *			"%precision.divisord". Example:
+ *			"%3.1000d" - divide the time by 1000 and print the first
+ *			3 digits before the dot. Thus, the time stamp
+ *			"123456000" will be printed as "123.456"
+ *	TEP_PRINT_INFO, "%s" - event information. If any width is specified in
+ *			the format string, the event information will be printed
+ *			in raw format.
+ * Writes the specified event information into @s.
  */
-void tep_print_event_data(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record)
-{
-	static const char *spaces = "                    "; /* 20 spaces */
-	int len;
-
-	trace_seq_printf(s, " %s: ", event->name);
-
-	/* Space out the event names evenly. */
-	len = strlen(event->name);
-	if (len < 20)
-		trace_seq_printf(s, "%.*s", 20 - len, spaces);
-
-	tep_event_info(s, event, record);
-}
-
 void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
-		     struct tep_record *record, bool use_trace_clock)
-{
+		     struct tep_record *record, const char *fmt, ...)
+{
+	struct print_event_type type;
+	char *format = strdup(fmt);
+	char *current = format;
+	char *str = format;
+	int offset;
+	va_list args;
 	struct tep_event *event;
 
-	event = tep_find_event_by_record(tep, record);
-	if (!event) {
-		int i;
-		int type = trace_parse_common_type(tep, record->data);
-
-		do_warning("ug! no event found for type %d", type);
-		trace_seq_printf(s, "[UNKNOWN TYPE %d]", type);
-		for (i = 0; i < record->size; i++)
-			trace_seq_printf(s, " %02x",
-					 ((unsigned char *)record->data)[i]);
+	if (!format)
 		return;
-	}
 
-	tep_print_event_task(tep, s, event, record);
-	tep_print_event_time(tep, s, event, record, use_trace_clock);
-	tep_print_event_data(tep, s, event, record);
+	event = tep_find_event_by_record(tep, record);
+	va_start(args, fmt);
+	while (*current) {
+		current = strchr(str, '%');
+		if (!current) {
+			trace_seq_puts(s, str);
+			break;
+		}
+		memset(&type, 0, sizeof(type));
+		offset = tep_print_event_param_type(current, &type);
+		*current = '\0';
+		trace_seq_puts(s, str);
+		current += offset;
+		switch (type.type) {
+		case EVENT_TYPE_STRING:
+			print_string(tep, s, record, event,
+				     va_arg(args, char*), &type);
+			break;
+		case EVENT_TYPE_INT:
+			print_int(tep, s, record, event,
+				  va_arg(args, int), &type);
+			break;
+		case EVENT_TYPE_UNKNOWN:
+		default:
+			trace_seq_printf(s, "[UNKNOWN TYPE]");
+			break;
+		}
+		str = current;
+
+	}
+	va_end(args);
+	free(format);
 }
 
 static int events_id_cmp(const void *a, const void *b)
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 01d904964edf..4958fa81c834 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -100,6 +100,9 @@ static int no_softirqs;
 
 static int tsdiff;
 
+static int latency_format;
+static const char *format_type = TEP_PRINT_INFO;
+
 static struct tep_format_field *wakeup_task;
 static struct tep_format_field *wakeup_success;
 static struct tep_format_field *wakeup_new_task;
@@ -125,6 +128,35 @@ static struct hook_list *last_hook;
 #define WAKEUP_HASH_SIZE 1024
 static struct trace_hash wakeup_hash;
 
+static void print_event_name(struct trace_seq *s, struct tep_event *event)
+{
+	static const char *spaces = "                    "; /* 20 spaces */
+	int len;
+
+	trace_seq_printf(s, " %s: ", event->name);
+
+	/* Space out the event names evenly. */
+	len = strlen(event->name);
+	if (len < 20)
+		trace_seq_printf(s, "%.*s", 20 - len, spaces);
+}
+
+static void print_event(struct trace_seq *s, struct tracecmd_input *handle,
+			struct tep_record *record)
+{
+	struct tep_handle *tep = tracecmd_get_pevent(handle);
+	struct tep_event *event;
+	const char *lfmt = latency_format ? "%8.8s-%-5d %3d" : "%16s-%-5d [%03d]";
+	const char *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:";
+
+	event = tep_find_event_by_record(tep, record);
+	tep_print_event(tep, s, record, lfmt, TEP_PRINT_COMM,
+			TEP_PRINT_PID, TEP_PRINT_CPU);
+	tep_print_event(tep, s, record, tfmt, TEP_PRINT_TIME);
+	print_event_name(s, event);
+	tep_print_event(tep, s, record, "%s", format_type);
+}
+
 /* Debug variables for testing tracecmd_read_at */
 #define TEST_READ_AT 0
 #if TEST_READ_AT
@@ -134,22 +166,18 @@ static int test_read_at_copy = 100;
 static int test_read_at_index;
 static void show_test(struct tracecmd_input *handle)
 {
-	struct tep_handle *pevent;
 	struct tep_record *record;
 	struct trace_seq s;
-	int cpu;
 
 	if (!test_read_at_offset) {
 		printf("\nNO RECORD COPIED\n");
 		return;
 	}
 
-	pevent = tracecmd_get_pevent(handle);
-
-	record = tracecmd_read_at(handle, test_read_at_offset, &cpu);
+	record = tracecmd_read_at(handle, test_read_at_offset, NULL);
 	printf("\nHERE'S THE COPY RECORD\n");
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -176,7 +204,6 @@ static int test_at_timestamp_cpu = -1;
 static int test_at_timestamp_index;
 static void show_test(struct tracecmd_input *handle)
 {
-	struct tep_handle *pevent;
 	struct tep_record *record;
 	struct trace_seq s;
 	int cpu = test_at_timestamp_cpu;
@@ -186,8 +213,6 @@ static void show_test(struct tracecmd_input *handle)
 		return;
 	}
 
-	pevent = tracecmd_get_pevent(handle);
-
 	if (tracecmd_set_cpu_to_timestamp(handle, cpu, test_at_timestamp_ts))
 		return;
 
@@ -196,7 +221,7 @@ static void show_test(struct tracecmd_input *handle)
 	       (void *)(record->offset & ~(page_size - 1)),
 	       (void *)record->offset);
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -221,13 +246,10 @@ static void test_save(struct tep_record *record, int cpu)
 #define DO_TEST
 static void show_test(struct tracecmd_input *handle)
 {
-	struct tep_handle *pevent;
 	struct tep_record *record;
 	struct trace_seq s;
 	int cpu = 0;
 
-	pevent = tracecmd_get_pevent(handle);
-
 	record = tracecmd_read_cpu_first(handle, cpu);
 	if (!record) {
 		printf("No first record?\n");
@@ -237,7 +259,7 @@ static void show_test(struct tracecmd_input *handle)
 	printf("\nHERE'S THE FIRST RECORD with offset %p\n",
 	       (void *)record->offset);
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -253,7 +275,7 @@ static void show_test(struct tracecmd_input *handle)
 	printf("\nHERE'S THE LAST RECORD with offset %p\n",
 	       (void *)record->offset);
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -268,6 +290,9 @@ static void test_save(struct tep_record *record, int cpu)
 #ifndef DO_TEST
 static void show_test(struct tracecmd_input *handle)
 {
+	/* quiet the compiler */
+	if (0)
+		print_event(NULL, NULL, NULL);
 }
 static void test_save(struct tep_record *record, int cpu)
 {
@@ -756,6 +781,8 @@ static void finish_wakeup(void)
 void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 {
 	tracecmd_show_data_func func = tracecmd_get_show_data_func(handle);
+	const char *lfmt = latency_format ? "%8.8s-%-5d %3d" : "%16s-%-5d [%03d]";
+	const char *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:";
 	struct tep_handle *pevent;
 	struct tep_event *event;
 	struct trace_seq s;
@@ -776,6 +803,8 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 	}
 
 	pevent = tracecmd_get_pevent(handle);
+	event = tep_find_event_by_record(pevent, record);
+	use_trace_clock = tracecmd_get_use_trace_clock(handle);
 
 	trace_seq_init(&s);
 	if (record->missed_events > 0)
@@ -793,11 +822,11 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 			trace_seq_putc(&s, '\n');
 		}
 	}
-	use_trace_clock = tracecmd_get_use_trace_clock(handle);
-	event = tep_find_event_by_record(pevent, record);
-	tep_print_event_task(pevent, &s, event, record);
-	tep_print_event_time(pevent, &s, event, record,
-			     use_trace_clock);
+
+	tep_print_event(pevent, &s, record, lfmt, TEP_PRINT_COMM,
+			TEP_PRINT_PID, TEP_PRINT_CPU);
+	tep_print_event(pevent, &s, record, tfmt, TEP_PRINT_TIME);
+
 	if (tsdiff) {
 		unsigned long long rec_ts = record->ts;
 
@@ -813,7 +842,8 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 		trace_seq_printf(&s, " %-8s", buf);
 	}
 
-	tep_print_event_data(pevent, &s, event, record);
+	print_event_name(&s, event);
+	tep_print_event(pevent, &s, record, "%s", format_type);
 
 	if (s.len && *(s.buffer + s.len - 1) == '\n')
 		s.len--;
@@ -1433,7 +1463,6 @@ void trace_report (int argc, char **argv)
 	int show_printk = 0;
 	int show_uname = 0;
 	int show_version = 0;
-	int latency_format = 0;
 	int show_events = 0;
 	int print_events = 0;
 	int nanosec = 0;
@@ -1703,7 +1732,7 @@ void trace_report (int argc, char **argv)
 			tep_set_flag(pevent, TEP_NSEC_OUTPUT);
 
 		if (raw)
-			tep_set_print_raw(pevent, 1);
+			format_type = TEP_PRINT_INFO_RAW;
 
 		if (test_filters_mode)
 			tep_set_test_filters(pevent, 1);
@@ -1767,9 +1796,6 @@ void trace_report (int argc, char **argv)
 		set_event_flags(pevent, raw_events, TEP_EVENT_FL_PRINTRAW);
 	}
 
-	if (latency_format)
-		tep_set_latency_format(pevent, latency_format);
-
 	otype = OUTPUT_NORMAL;
 
 	if (show_stat)
-- 
2.20.1

Re: [PATCH 4/5] libtraceevent, perf tools: Changes in tep_print_event_* APIs

[Steven Rostedt]

On Tue, 17 Sep 2019 22:03:38 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> 
> Libtraceevent APIs for printing various trace events information are
> complicated, there are complex extra parameters. To control the way
> event information is printed, the user should call a set of functions in
> a specific sequence.
> 
> These APIs are reimplemented to provide a more simple interface for
> printing event information.
> 
> Removed APIs:
> 
>  	tep_print_event_task()
> 	tep_print_event_time()
> 	tep_print_event_data()
> 	tep_event_info()
> 	tep_is_latency_format()
> 	tep_set_latency_format()
> 	tep_data_latency_format()
> 	tep_set_print_raw()
> 
> A new API for printing event information is introduced:
>    void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
> 		        struct tep_record *record, const char *fmt, ...);
> where "fmt" is a printf-like format string, followed by the event
> fields to be printed. Supported fields:
>  TEP_PRINT_PID, "%d" - event PID
>  TEP_PRINT_CPU, "%d" - event CPU
>  TEP_PRINT_COMM, "%s" - event command string
>  TEP_PRINT_NAME, "%s" - event name
>  TEP_PRINT_LATENCY, "%s" - event latency
>  TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
>    can be specified as part of this format string:
>    "%precision.divisord". Example:
>    "%3.1000d" - divide the time by 1000 and print the first 3 digits
>    before the dot. Thus, the time stamp "123456000" will be printed as
>    "123.456"
>  TEP_PRINT_INFO, "%s" - event information.
>  TEP_PRINT_INFO_RAW, "%s" - event information, in raw format.
> 
> Example:
>   tep_print_event(tep, s, record, "%16s-%-5d [%03d] %s %6.1000d %s %s",
> 		  TEP_PRINT_COMM, TEP_PRINT_PID, TEP_PRINT_CPU,
> 		  TEP_PRINT_LATENCY, TEP_PRINT_TIME, TEP_PRINT_NAME, TEP_PRINT_INFO);
> Output:
> 	ls-11314 [005] d.h. 185207.366383 function __wake_up
> 
> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: linux-trace-devel@vger.kernel.org
> Cc: Patrick McLean <chutzpah@gentoo.org>
> Link: http://lore.kernel.org/linux-trace-devel/20190801074959.22023-2-tz.stoyanov@gmail.com
> Link: http://lore.kernel.org/lkml/20190805204355.041132030@goodmis.org
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> [ Added support for trace-cmd trace-read.c ]
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>


I needed to modify this with the following changes:

diff --git a/kernel-shark/src/libkshark.c b/kernel-shark/src/libkshark.c
index 47ec9c21..4207ae6f 100644
--- a/kernel-shark/src/libkshark.c
+++ b/kernel-shark/src/libkshark.c
@@ -1103,7 +1103,7 @@ static const char *kshark_get_latency(struct tep_handle *pe,
 		return NULL;
 
 	trace_seq_reset(&seq);
-	tep_data_latency_format(pe, &seq, record);
+	tep_print_event(pe, &seq, record, "%s", TEP_PRINT_LATENCY);
 	return seq.buffer;
 }
 
@@ -1117,7 +1117,7 @@ static const char *kshark_get_info(struct tep_handle *pe,
 		return NULL;
 
 	trace_seq_reset(&seq);
-	tep_event_info(&seq, event, record);
+	tep_print_event(pe, &seq, record, "%s", TEP_PRINT_INFO);
 
 	/*
 	 * The event info string contains a trailing newline.


-- Steve

[PATCH 4/5 v2] libtraceevent, perf tools: Changes in tep_print_event_* APIs

[Steven Rostedt]

From: Tzvetomir Stoyanov <tstoyanov@vmware.com>

Libtraceevent APIs for printing various trace events information are
complicated, there are complex extra parameters. To control the way
event information is printed, the user should call a set of functions in
a specific sequence.

These APIs are reimplemented to provide a more simple interface for
printing event information.

Removed APIs:

 	tep_print_event_task()
	tep_print_event_time()
	tep_print_event_data()
	tep_event_info()
	tep_is_latency_format()
	tep_set_latency_format()
	tep_data_latency_format()
	tep_set_print_raw()

A new API for printing event information is introduced:
   void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
		        struct tep_record *record, const char *fmt, ...);
where "fmt" is a printf-like format string, followed by the event
fields to be printed. Supported fields:
 TEP_PRINT_PID, "%d" - event PID
 TEP_PRINT_CPU, "%d" - event CPU
 TEP_PRINT_COMM, "%s" - event command string
 TEP_PRINT_NAME, "%s" - event name
 TEP_PRINT_LATENCY, "%s" - event latency
 TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
   can be specified as part of this format string:
   "%precision.divisord". Example:
   "%3.1000d" - divide the time by 1000 and print the first 3 digits
   before the dot. Thus, the time stamp "123456000" will be printed as
   "123.456"
 TEP_PRINT_INFO, "%s" - event information.
 TEP_PRINT_INFO_RAW, "%s" - event information, in raw format.

Example:
  tep_print_event(tep, s, record, "%16s-%-5d [%03d] %s %6.1000d %s %s",
		  TEP_PRINT_COMM, TEP_PRINT_PID, TEP_PRINT_CPU,
		  TEP_PRINT_LATENCY, TEP_PRINT_TIME, TEP_PRINT_NAME, TEP_PRINT_INFO);
Output:
	ls-11314 [005] d.h. 185207.366383 function __wake_up

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: linux-trace-devel@vger.kernel.org
Cc: Patrick McLean <chutzpah@gentoo.org>
Link: http://lore.kernel.org/linux-trace-devel/20190801074959.22023-2-tz.stoyanov@gmail.com
Link: http://lore.kernel.org/lkml/20190805204355.041132030@goodmis.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
[ Added support for trace-cmd trace-read.c and kernelshark libkshark.c ]
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/traceevent/event-parse.h   |  29 +--
 kernel-shark/src/libkshark.c       |   4 +-
 lib/traceevent/event-parse-api.c   |  40 ----
 lib/traceevent/event-parse-local.h |   4 -
 lib/traceevent/event-parse.c       | 322 +++++++++++++++++------------
 tracecmd/trace-read.c              |  78 ++++---
 6 files changed, 252 insertions(+), 225 deletions(-)

diff --git a/include/traceevent/event-parse.h b/include/traceevent/event-parse.h
index 99da5ef8..5dff952d 100644
--- a/include/traceevent/event-parse.h
+++ b/include/traceevent/event-parse.h
@@ -436,18 +436,18 @@ int tep_register_print_string(struct tep_handle *tep, const char *fmt,
 			      unsigned long long addr);
 bool tep_is_pid_registered(struct tep_handle *tep, int pid);
 
-void tep_print_event_task(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record);
-void tep_print_event_time(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record,
-			  bool use_trace_clock);
-void tep_print_event_data(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record);
+#define TEP_PRINT_INFO		"INFO"
+#define TEP_PRINT_INFO_RAW	"INFO_RAW"
+#define TEP_PRINT_COMM		"COMM"
+#define TEP_PRINT_LATENCY	"LATENCY"
+#define TEP_PRINT_NAME		"NAME"
+#define TEP_PRINT_PID		1U
+#define TEP_PRINT_TIME		2U
+#define TEP_PRINT_CPU		3U
+
 void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
-		     struct tep_record *record, bool use_trace_clock);
+		     struct tep_record *record, const char *fmt, ...)
+	__attribute__ ((format (printf, 4, 5)));
 
 int tep_parse_header_page(struct tep_handle *tep, char *buf, unsigned long size,
 			  int long_size);
@@ -520,8 +520,6 @@ tep_find_event_by_name(struct tep_handle *tep, const char *sys, const char *name
 struct tep_event *
 tep_find_event_by_record(struct tep_handle *tep, struct tep_record *record);
 
-void tep_data_latency_format(struct tep_handle *tep,
-			     struct trace_seq *s, struct tep_record *record);
 int tep_data_type(struct tep_handle *tep, struct tep_record *rec);
 int tep_data_pid(struct tep_handle *tep, struct tep_record *rec);
 int tep_data_preempt_count(struct tep_handle *tep, struct tep_record *rec);
@@ -536,8 +534,6 @@ void tep_print_field(struct trace_seq *s, void *data,
 		     struct tep_format_field *field);
 void tep_print_fields(struct trace_seq *s, void *data,
 		      int size __maybe_unused, struct tep_event *event);
-void tep_event_info(struct trace_seq *s, struct tep_event *event,
-		    struct tep_record *record);
 int tep_strerror(struct tep_handle *tep, enum tep_errno errnum,
 		 char *buf, size_t buflen);
 
@@ -562,12 +558,9 @@ bool tep_is_file_bigendian(struct tep_handle *tep);
 void tep_set_file_bigendian(struct tep_handle *tep, enum tep_endian endian);
 bool tep_is_local_bigendian(struct tep_handle *tep);
 void tep_set_local_bigendian(struct tep_handle *tep, enum tep_endian endian);
-bool tep_is_latency_format(struct tep_handle *tep);
-void tep_set_latency_format(struct tep_handle *tep, int lat);
 int tep_get_header_page_size(struct tep_handle *tep);
 int tep_get_header_timestamp_size(struct tep_handle *tep);
 bool tep_is_old_format(struct tep_handle *tep);
-void tep_set_print_raw(struct tep_handle *tep, int print_raw);
 void tep_set_test_filters(struct tep_handle *tep, int test_filters);
 
 struct tep_handle *tep_alloc(void);
diff --git a/kernel-shark/src/libkshark.c b/kernel-shark/src/libkshark.c
index 47ec9c21..4207ae6f 100644
--- a/kernel-shark/src/libkshark.c
+++ b/kernel-shark/src/libkshark.c
@@ -1103,7 +1103,7 @@ static const char *kshark_get_latency(struct tep_handle *pe,
 		return NULL;
 
 	trace_seq_reset(&seq);
-	tep_data_latency_format(pe, &seq, record);
+	tep_print_event(pe, &seq, record, "%s", TEP_PRINT_LATENCY);
 	return seq.buffer;
 }
 
@@ -1117,7 +1117,7 @@ static const char *kshark_get_info(struct tep_handle *pe,
 		return NULL;
 
 	trace_seq_reset(&seq);
-	tep_event_info(&seq, event, record);
+	tep_print_event(pe, &seq, record, "%s", TEP_PRINT_INFO);
 
 	/*
 	 * The event info string contains a trailing newline.
diff --git a/lib/traceevent/event-parse-api.c b/lib/traceevent/event-parse-api.c
index 98858784..4faf52a6 100644
--- a/lib/traceevent/event-parse-api.c
+++ b/lib/traceevent/event-parse-api.c
@@ -302,33 +302,6 @@ void tep_set_local_bigendian(struct tep_handle *tep, enum tep_endian endian)
 		tep->host_bigendian = endian;
 }
 
-/**
- * tep_is_latency_format - get if the latency output format is configured
- * @tep: a handle to the tep_handle
- *
- * This returns true if the latency output format is configured
- * If @tep is NULL, false is returned.
- */
-bool tep_is_latency_format(struct tep_handle *tep)
-{
-	if (tep)
-		return (tep->latency_format);
-	return false;
-}
-
-/**
- * tep_set_latency_format - set the latency output format
- * @tep: a handle to the tep_handle
- * @lat: non zero for latency output format
- *
- * This sets the latency output format
-  */
-void tep_set_latency_format(struct tep_handle *tep, int lat)
-{
-	if (tep)
-		tep->latency_format = lat;
-}
-
 /**
  * tep_is_old_format - get if an old kernel is used
  * @tep: a handle to the tep_handle
@@ -344,19 +317,6 @@ bool tep_is_old_format(struct tep_handle *tep)
 	return false;
 }
 
-/**
- * tep_set_print_raw - set a flag to force print in raw format
- * @tep: a handle to the tep_handle
- * @print_raw: the new value of the print_raw flag
- *
- * This sets a flag to force print in raw format
- */
-void tep_set_print_raw(struct tep_handle *tep, int print_raw)
-{
-	if (tep)
-		tep->print_raw = print_raw;
-}
-
 /**
  * tep_set_test_filters - set a flag to test a filter string
  * @tep: a handle to the tep_handle
diff --git a/lib/traceevent/event-parse-local.h b/lib/traceevent/event-parse-local.h
index 09aa142f..6e58ee1f 100644
--- a/lib/traceevent/event-parse-local.h
+++ b/lib/traceevent/event-parse-local.h
@@ -28,8 +28,6 @@ struct tep_handle {
 	enum tep_endian file_bigendian;
 	enum tep_endian host_bigendian;
 
-	int latency_format;
-
 	int old_format;
 
 	int cpus;
@@ -70,8 +68,6 @@ struct tep_handle {
 	int ld_offset;
 	int ld_size;
 
-	int print_raw;
-
 	int test_filters;
 
 	int flags;
diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
index 3e836360..d1085aab 100644
--- a/lib/traceevent/event-parse.c
+++ b/lib/traceevent/event-parse.c
@@ -5212,24 +5212,20 @@ out_failed:
 	}
 }
 
-/**
- * tep_data_latency_format - parse the data for the latency format
- * @tep: a handle to the trace event parser context
- * @s: the trace_seq to write to
- * @record: the record to read from
- *
+/*
  * This parses out the Latency format (interrupts disabled,
  * need rescheduling, in hard/soft interrupt, preempt count
  * and lock depth) and places it into the trace_seq.
  */
-void tep_data_latency_format(struct tep_handle *tep,
-			     struct trace_seq *s, struct tep_record *record)
+static void data_latency_format(struct tep_handle *tep, struct trace_seq *s,
+				char *format, struct tep_record *record)
 {
 	static int check_lock_depth = 1;
 	static int check_migrate_disable = 1;
 	static int lock_depth_exists;
 	static int migrate_disable_exists;
 	unsigned int lat_flags;
+	struct trace_seq sq;
 	unsigned int pc;
 	int lock_depth = 0;
 	int migrate_disable = 0;
@@ -5237,6 +5233,7 @@ void tep_data_latency_format(struct tep_handle *tep,
 	int softirq;
 	void *data = record->data;
 
+	trace_seq_init(&sq);
 	lat_flags = parse_common_flags(tep, data);
 	pc = parse_common_pc(tep, data);
 	/* lock_depth may not always exist */
@@ -5264,7 +5261,7 @@ void tep_data_latency_format(struct tep_handle *tep,
 	hardirq = lat_flags & TRACE_FLAG_HARDIRQ;
 	softirq = lat_flags & TRACE_FLAG_SOFTIRQ;
 
-	trace_seq_printf(s, "%c%c%c",
+	trace_seq_printf(&sq, "%c%c%c",
 	       (lat_flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
 	       (lat_flags & TRACE_FLAG_IRQS_NOSUPPORT) ?
 	       'X' : '.',
@@ -5274,24 +5271,32 @@ void tep_data_latency_format(struct tep_handle *tep,
 	       hardirq ? 'h' : softirq ? 's' : '.');
 
 	if (pc)
-		trace_seq_printf(s, "%x", pc);
+		trace_seq_printf(&sq, "%x", pc);
 	else
-		trace_seq_putc(s, '.');
+		trace_seq_printf(&sq, ".");
 
 	if (migrate_disable_exists) {
 		if (migrate_disable < 0)
-			trace_seq_putc(s, '.');
+			trace_seq_printf(&sq, ".");
 		else
-			trace_seq_printf(s, "%d", migrate_disable);
+			trace_seq_printf(&sq, "%d", migrate_disable);
 	}
 
 	if (lock_depth_exists) {
 		if (lock_depth < 0)
-			trace_seq_putc(s, '.');
+			trace_seq_printf(&sq, ".");
 		else
-			trace_seq_printf(s, "%d", lock_depth);
+			trace_seq_printf(&sq, "%d", lock_depth);
 	}
 
+	if (sq.state == TRACE_SEQ__MEM_ALLOC_FAILED) {
+		s->state = TRACE_SEQ__MEM_ALLOC_FAILED;
+		return;
+	}
+
+	trace_seq_terminate(&sq);
+	trace_seq_puts(s, sq.buffer);
+	trace_seq_destroy(&sq);
 	trace_seq_terminate(s);
 }
 
@@ -5452,21 +5457,16 @@ int tep_cmdline_pid(struct tep_handle *tep, struct tep_cmdline *cmdline)
 	return cmdline->pid;
 }
 
-/**
- * tep_event_info - parse the data into the print format
- * @s: the trace_seq to write to
- * @event: the handle to the event
- * @record: the record to read from
- *
+/*
  * This parses the raw @data using the given @event information and
  * writes the print format into the trace_seq.
  */
-void tep_event_info(struct trace_seq *s, struct tep_event *event,
-		    struct tep_record *record)
+static void print_event_info(struct trace_seq *s, char *format, bool raw,
+			     struct tep_event *event, struct tep_record *record)
 {
 	int print_pretty = 1;
 
-	if (event->tep->print_raw || (event->flags & TEP_EVENT_FL_PRINTRAW))
+	if (raw || (event->flags & TEP_EVENT_FL_PRINTRAW))
 		tep_print_fields(s, record->data, record->size, event);
 	else {
 
@@ -5481,20 +5481,6 @@ void tep_event_info(struct trace_seq *s, struct tep_event *event,
 	trace_seq_terminate(s);
 }
 
-static bool is_timestamp_in_us(char *trace_clock, bool use_trace_clock)
-{
-	if (!trace_clock || !use_trace_clock)
-		return true;
-
-	if (!strcmp(trace_clock, "local") || !strcmp(trace_clock, "global")
-	    || !strcmp(trace_clock, "uptime") || !strcmp(trace_clock, "perf")
-	    || !strncmp(trace_clock, "mono", 4))
-		return true;
-
-	/* trace_clock is setting in tsc or counter mode */
-	return false;
-}
-
 /**
  * tep_find_event_by_record - return the event from a given record
  * @tep: a handle to the trace event parser context
@@ -5518,129 +5504,195 @@ tep_find_event_by_record(struct tep_handle *tep, struct tep_record *record)
 	return tep_find_event(tep, type);
 }
 
-/**
- * tep_print_event_task - Write the event task comm, pid and CPU
- * @tep: a handle to the trace event parser context
- * @s: the trace_seq to write to
- * @event: the handle to the record's event
- * @record: The record to get the event from
- *
- * Writes the tasks comm, pid and CPU to @s.
+/*
+ * Writes the timestamp of the record into @s. Time divisor and precision can be
+ * specified as part of printf @format string. Example:
+ *	"%3.1000d" - divide the time by 1000 and print the first 3 digits
+ *	before the dot. Thus, the timestamp "123456000" will be printed as
+ *	"123.456"
  */
-void tep_print_event_task(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record)
+static void print_event_time(struct tep_handle *tep, struct trace_seq *s,
+				 char *format, struct tep_event *event,
+				 struct tep_record *record)
+{
+	unsigned long long time;
+	char *divstr;
+	int prec = 0, pr;
+	int div = 0;
+	int p10 = 1;
+
+	if (isdigit(*(format + 1)))
+		prec = atoi(format + 1);
+	divstr = strchr(format, '.');
+	if (divstr && isdigit(*(divstr + 1)))
+		div = atoi(divstr + 1);
+	time = record->ts;
+	if (div)
+		time /= div;
+	pr = prec;
+	while (pr--)
+		p10 *= 10;
+
+	if (p10 > 1 && p10 < time)
+		trace_seq_printf(s, "%5llu.%0*llu", time / p10, prec, time % p10);
+	else
+		trace_seq_printf(s, "%12llu\n", time);
+}
+
+struct print_event_type {
+	enum {
+		EVENT_TYPE_INT = 1,
+		EVENT_TYPE_STRING,
+		EVENT_TYPE_UNKNOWN,
+	} type;
+	char format[32];
+};
+
+static void print_string(struct tep_handle *tep, struct trace_seq *s,
+			 struct tep_record *record, struct tep_event *event,
+			 const char *arg, struct print_event_type *type)
 {
-	void *data = record->data;
 	const char *comm;
 	int pid;
 
-	pid = parse_common_pid(tep, data);
-	comm = find_cmdline(tep, pid);
+	if (strncmp(arg, TEP_PRINT_LATENCY, strlen(TEP_PRINT_LATENCY)) == 0) {
+		data_latency_format(tep, s, type->format, record);
+	} else if (strncmp(arg, TEP_PRINT_COMM, strlen(TEP_PRINT_COMM)) == 0) {
+		pid = parse_common_pid(tep, record->data);
+		comm = find_cmdline(tep, pid);
+		trace_seq_printf(s, type->format, comm);
+	} else if (strncmp(arg, TEP_PRINT_INFO_RAW, strlen(TEP_PRINT_INFO_RAW)) == 0) {
+		print_event_info(s, type->format, true, event, record);
+	} else if (strncmp(arg, TEP_PRINT_INFO, strlen(TEP_PRINT_INFO)) == 0) {
+		print_event_info(s, type->format, false, event, record);
+	} else if  (strncmp(arg, TEP_PRINT_NAME, strlen(TEP_PRINT_NAME)) == 0) {
+		trace_seq_printf(s, type->format, event->name);
+	} else {
+		trace_seq_printf(s, "[UNKNOWN TEP TYPE %s]", arg);
+	}
 
-	if (tep->latency_format)
-		trace_seq_printf(s, "%8.8s-%-5d %3d", comm, pid, record->cpu);
-	else
-		trace_seq_printf(s, "%16s-%-5d [%03d]", comm, pid, record->cpu);
 }
 
-/**
- * tep_print_event_time - Write the event timestamp
- * @tep: a handle to the trace event parser context
- * @s: the trace_seq to write to
- * @event: the handle to the record's event
- * @record: The record to get the event from
- * @use_trace_clock: Set to parse according to the @tep->trace_clock
- *
- * Writes the timestamp of the record into @s.
- */
-void tep_print_event_time(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record,
-			  bool use_trace_clock)
+static void print_int(struct tep_handle *tep, struct trace_seq *s,
+		      struct tep_record *record, struct tep_event *event,
+		      int arg, struct print_event_type *type)
 {
-	unsigned long secs;
-	unsigned long usecs;
-	unsigned long nsecs;
-	int p;
-	bool use_usec_format;
+	int param;
 
-	use_usec_format = is_timestamp_in_us(tep->trace_clock, use_trace_clock);
-	if (use_usec_format) {
-		secs = record->ts / NSEC_PER_SEC;
-		nsecs = record->ts - secs * NSEC_PER_SEC;
+	switch (arg) {
+	case TEP_PRINT_CPU:
+		param = record->cpu;
+		break;
+	case TEP_PRINT_PID:
+		param = parse_common_pid(tep, record->data);
+		break;
+	case TEP_PRINT_TIME:
+		return print_event_time(tep, s, type->format, event, record);
+	default:
+		return;
 	}
+	trace_seq_printf(s, type->format, param);
+}
 
-	if (tep->latency_format) {
-		tep_data_latency_format(tep, s, record);
-	}
+static int tep_print_event_param_type(char *format,
+				      struct print_event_type *type)
+{
+	char *str = format + 1;
+	int i = 1;
 
-	if (use_usec_format) {
-		if (tep->flags & TEP_NSEC_OUTPUT) {
-			usecs = nsecs;
-			p = 9;
-		} else {
-			usecs = (nsecs + 500) / NSEC_PER_USEC;
-			/* To avoid usecs larger than 1 sec */
-			if (usecs >= USEC_PER_SEC) {
-				usecs -= USEC_PER_SEC;
-				secs++;
-			}
-			p = 6;
+	type->type = EVENT_TYPE_UNKNOWN;
+	while (*str) {
+		switch (*str) {
+		case 'd':
+		case 'u':
+		case 'i':
+		case 'x':
+		case 'X':
+		case 'o':
+			type->type = EVENT_TYPE_INT;
+			break;
+		case 's':
+			type->type = EVENT_TYPE_STRING;
+			break;
 		}
-
-		trace_seq_printf(s, " %5lu.%0*lu:", secs, p, usecs);
-	} else
-		trace_seq_printf(s, " %12llu:", record->ts);
+		str++;
+		i++;
+		if (type->type != EVENT_TYPE_UNKNOWN)
+			break;
+	}
+	memset(type->format, 0, 32);
+	memcpy(type->format, format, i < 32 ? i : 31);
+	return i;
 }
 
 /**
- * tep_print_event_data - Write the event data section
+ * tep_print_event - Write various event information
  * @tep: a handle to the trace event parser context
  * @s: the trace_seq to write to
- * @event: the handle to the record's event
  * @record: The record to get the event from
- *
- * Writes the parsing of the record's data to @s.
+ * @format: a printf format string. Supported event fileds:
+ *	TEP_PRINT_PID, "%d" - event PID
+ *	TEP_PRINT_CPU, "%d" - event CPU
+ *	TEP_PRINT_COMM, "%s" - event command string
+ *	TEP_PRINT_NAME, "%s" - event name
+ *	TEP_PRINT_LATENCY, "%s" - event latency
+ *	TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
+ *			can be specified as part of this format string:
+ *			"%precision.divisord". Example:
+ *			"%3.1000d" - divide the time by 1000 and print the first
+ *			3 digits before the dot. Thus, the time stamp
+ *			"123456000" will be printed as "123.456"
+ *	TEP_PRINT_INFO, "%s" - event information. If any width is specified in
+ *			the format string, the event information will be printed
+ *			in raw format.
+ * Writes the specified event information into @s.
  */
-void tep_print_event_data(struct tep_handle *tep, struct trace_seq *s,
-			  struct tep_event *event,
-			  struct tep_record *record)
-{
-	static const char *spaces = "                    "; /* 20 spaces */
-	int len;
-
-	trace_seq_printf(s, " %s: ", event->name);
-
-	/* Space out the event names evenly. */
-	len = strlen(event->name);
-	if (len < 20)
-		trace_seq_printf(s, "%.*s", 20 - len, spaces);
-
-	tep_event_info(s, event, record);
-}
-
 void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
-		     struct tep_record *record, bool use_trace_clock)
-{
+		     struct tep_record *record, const char *fmt, ...)
+{
+	struct print_event_type type;
+	char *format = strdup(fmt);
+	char *current = format;
+	char *str = format;
+	int offset;
+	va_list args;
 	struct tep_event *event;
 
-	event = tep_find_event_by_record(tep, record);
-	if (!event) {
-		int i;
-		int type = trace_parse_common_type(tep, record->data);
-
-		do_warning("ug! no event found for type %d", type);
-		trace_seq_printf(s, "[UNKNOWN TYPE %d]", type);
-		for (i = 0; i < record->size; i++)
-			trace_seq_printf(s, " %02x",
-					 ((unsigned char *)record->data)[i]);
+	if (!format)
 		return;
-	}
 
-	tep_print_event_task(tep, s, event, record);
-	tep_print_event_time(tep, s, event, record, use_trace_clock);
-	tep_print_event_data(tep, s, event, record);
+	event = tep_find_event_by_record(tep, record);
+	va_start(args, fmt);
+	while (*current) {
+		current = strchr(str, '%');
+		if (!current) {
+			trace_seq_puts(s, str);
+			break;
+		}
+		memset(&type, 0, sizeof(type));
+		offset = tep_print_event_param_type(current, &type);
+		*current = '\0';
+		trace_seq_puts(s, str);
+		current += offset;
+		switch (type.type) {
+		case EVENT_TYPE_STRING:
+			print_string(tep, s, record, event,
+				     va_arg(args, char*), &type);
+			break;
+		case EVENT_TYPE_INT:
+			print_int(tep, s, record, event,
+				  va_arg(args, int), &type);
+			break;
+		case EVENT_TYPE_UNKNOWN:
+		default:
+			trace_seq_printf(s, "[UNKNOWN TYPE]");
+			break;
+		}
+		str = current;
+
+	}
+	va_end(args);
+	free(format);
 }
 
 static int events_id_cmp(const void *a, const void *b)
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 01d90496..4958fa81 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -100,6 +100,9 @@ static int no_softirqs;
 
 static int tsdiff;
 
+static int latency_format;
+static const char *format_type = TEP_PRINT_INFO;
+
 static struct tep_format_field *wakeup_task;
 static struct tep_format_field *wakeup_success;
 static struct tep_format_field *wakeup_new_task;
@@ -125,6 +128,35 @@ static struct hook_list *last_hook;
 #define WAKEUP_HASH_SIZE 1024
 static struct trace_hash wakeup_hash;
 
+static void print_event_name(struct trace_seq *s, struct tep_event *event)
+{
+	static const char *spaces = "                    "; /* 20 spaces */
+	int len;
+
+	trace_seq_printf(s, " %s: ", event->name);
+
+	/* Space out the event names evenly. */
+	len = strlen(event->name);
+	if (len < 20)
+		trace_seq_printf(s, "%.*s", 20 - len, spaces);
+}
+
+static void print_event(struct trace_seq *s, struct tracecmd_input *handle,
+			struct tep_record *record)
+{
+	struct tep_handle *tep = tracecmd_get_pevent(handle);
+	struct tep_event *event;
+	const char *lfmt = latency_format ? "%8.8s-%-5d %3d" : "%16s-%-5d [%03d]";
+	const char *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:";
+
+	event = tep_find_event_by_record(tep, record);
+	tep_print_event(tep, s, record, lfmt, TEP_PRINT_COMM,
+			TEP_PRINT_PID, TEP_PRINT_CPU);
+	tep_print_event(tep, s, record, tfmt, TEP_PRINT_TIME);
+	print_event_name(s, event);
+	tep_print_event(tep, s, record, "%s", format_type);
+}
+
 /* Debug variables for testing tracecmd_read_at */
 #define TEST_READ_AT 0
 #if TEST_READ_AT
@@ -134,22 +166,18 @@ static int test_read_at_copy = 100;
 static int test_read_at_index;
 static void show_test(struct tracecmd_input *handle)
 {
-	struct tep_handle *pevent;
 	struct tep_record *record;
 	struct trace_seq s;
-	int cpu;
 
 	if (!test_read_at_offset) {
 		printf("\nNO RECORD COPIED\n");
 		return;
 	}
 
-	pevent = tracecmd_get_pevent(handle);
-
-	record = tracecmd_read_at(handle, test_read_at_offset, &cpu);
+	record = tracecmd_read_at(handle, test_read_at_offset, NULL);
 	printf("\nHERE'S THE COPY RECORD\n");
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -176,7 +204,6 @@ static int test_at_timestamp_cpu = -1;
 static int test_at_timestamp_index;
 static void show_test(struct tracecmd_input *handle)
 {
-	struct tep_handle *pevent;
 	struct tep_record *record;
 	struct trace_seq s;
 	int cpu = test_at_timestamp_cpu;
@@ -186,8 +213,6 @@ static void show_test(struct tracecmd_input *handle)
 		return;
 	}
 
-	pevent = tracecmd_get_pevent(handle);
-
 	if (tracecmd_set_cpu_to_timestamp(handle, cpu, test_at_timestamp_ts))
 		return;
 
@@ -196,7 +221,7 @@ static void show_test(struct tracecmd_input *handle)
 	       (void *)(record->offset & ~(page_size - 1)),
 	       (void *)record->offset);
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -221,13 +246,10 @@ static void test_save(struct tep_record *record, int cpu)
 #define DO_TEST
 static void show_test(struct tracecmd_input *handle)
 {
-	struct tep_handle *pevent;
 	struct tep_record *record;
 	struct trace_seq s;
 	int cpu = 0;
 
-	pevent = tracecmd_get_pevent(handle);
-
 	record = tracecmd_read_cpu_first(handle, cpu);
 	if (!record) {
 		printf("No first record?\n");
@@ -237,7 +259,7 @@ static void show_test(struct tracecmd_input *handle)
 	printf("\nHERE'S THE FIRST RECORD with offset %p\n",
 	       (void *)record->offset);
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -253,7 +275,7 @@ static void show_test(struct tracecmd_input *handle)
 	printf("\nHERE'S THE LAST RECORD with offset %p\n",
 	       (void *)record->offset);
 	trace_seq_init(&s);
-	tep_print_event(pevent, &s, cpu, record->data, record->size, record->ts);
+	print_event(&s, handle, record);
 	trace_seq_do_printf(&s);
 	trace_seq_destroy(&s);
 	printf("\n");
@@ -268,6 +290,9 @@ static void test_save(struct tep_record *record, int cpu)
 #ifndef DO_TEST
 static void show_test(struct tracecmd_input *handle)
 {
+	/* quiet the compiler */
+	if (0)
+		print_event(NULL, NULL, NULL);
 }
 static void test_save(struct tep_record *record, int cpu)
 {
@@ -756,6 +781,8 @@ static void finish_wakeup(void)
 void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 {
 	tracecmd_show_data_func func = tracecmd_get_show_data_func(handle);
+	const char *lfmt = latency_format ? "%8.8s-%-5d %3d" : "%16s-%-5d [%03d]";
+	const char *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:";
 	struct tep_handle *pevent;
 	struct tep_event *event;
 	struct trace_seq s;
@@ -776,6 +803,8 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 	}
 
 	pevent = tracecmd_get_pevent(handle);
+	event = tep_find_event_by_record(pevent, record);
+	use_trace_clock = tracecmd_get_use_trace_clock(handle);
 
 	trace_seq_init(&s);
 	if (record->missed_events > 0)
@@ -793,11 +822,11 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 			trace_seq_putc(&s, '\n');
 		}
 	}
-	use_trace_clock = tracecmd_get_use_trace_clock(handle);
-	event = tep_find_event_by_record(pevent, record);
-	tep_print_event_task(pevent, &s, event, record);
-	tep_print_event_time(pevent, &s, event, record,
-			     use_trace_clock);
+
+	tep_print_event(pevent, &s, record, lfmt, TEP_PRINT_COMM,
+			TEP_PRINT_PID, TEP_PRINT_CPU);
+	tep_print_event(pevent, &s, record, tfmt, TEP_PRINT_TIME);
+
 	if (tsdiff) {
 		unsigned long long rec_ts = record->ts;
 
@@ -813,7 +842,8 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 		trace_seq_printf(&s, " %-8s", buf);
 	}
 
-	tep_print_event_data(pevent, &s, event, record);
+	print_event_name(&s, event);
+	tep_print_event(pevent, &s, record, "%s", format_type);
 
 	if (s.len && *(s.buffer + s.len - 1) == '\n')
 		s.len--;
@@ -1433,7 +1463,6 @@ void trace_report (int argc, char **argv)
 	int show_printk = 0;
 	int show_uname = 0;
 	int show_version = 0;
-	int latency_format = 0;
 	int show_events = 0;
 	int print_events = 0;
 	int nanosec = 0;
@@ -1703,7 +1732,7 @@ void trace_report (int argc, char **argv)
 			tep_set_flag(pevent, TEP_NSEC_OUTPUT);
 
 		if (raw)
-			tep_set_print_raw(pevent, 1);
+			format_type = TEP_PRINT_INFO_RAW;
 
 		if (test_filters_mode)
 			tep_set_test_filters(pevent, 1);
@@ -1767,9 +1796,6 @@ void trace_report (int argc, char **argv)
 		set_event_flags(pevent, raw_events, TEP_EVENT_FL_PRINTRAW);
 	}
 
-	if (latency_format)
-		tep_set_latency_format(pevent, latency_format);
-
 	otype = OUTPUT_NORMAL;
 
 	if (show_stat)
-- 
2.20.1

Re: [PATCH 4/5] libtraceevent, perf tools: Changes in tep_print_event_* APIs

[Tzvetomir Stoyanov]

On Fri, Sep 20, 2019 at 1:50 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Tue, 17 Sep 2019 22:03:38 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > From: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> >
> > Libtraceevent APIs for printing various trace events information are
> > complicated, there are complex extra parameters. To control the way
> > event information is printed, the user should call a set of functions in
> > a specific sequence.
> >
> > These APIs are reimplemented to provide a more simple interface for
> > printing event information.
> >
> > Removed APIs:
> >
> >       tep_print_event_task()
> >       tep_print_event_time()
> >       tep_print_event_data()
> >       tep_event_info()
> >       tep_is_latency_format()
> >       tep_set_latency_format()
> >       tep_data_latency_format()
> >       tep_set_print_raw()
> >
> > A new API for printing event information is introduced:
> >    void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
> >                       struct tep_record *record, const char *fmt, ...);
> > where "fmt" is a printf-like format string, followed by the event
> > fields to be printed. Supported fields:
> >  TEP_PRINT_PID, "%d" - event PID
> >  TEP_PRINT_CPU, "%d" - event CPU
> >  TEP_PRINT_COMM, "%s" - event command string
> >  TEP_PRINT_NAME, "%s" - event name
> >  TEP_PRINT_LATENCY, "%s" - event latency
> >  TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
> >    can be specified as part of this format string:
> >    "%precision.divisord". Example:
> >    "%3.1000d" - divide the time by 1000 and print the first 3 digits
> >    before the dot. Thus, the time stamp "123456000" will be printed as
> >    "123.456"
> >  TEP_PRINT_INFO, "%s" - event information.
> >  TEP_PRINT_INFO_RAW, "%s" - event information, in raw format.
> >
> > Example:
> >   tep_print_event(tep, s, record, "%16s-%-5d [%03d] %s %6.1000d %s %s",
> >                 TEP_PRINT_COMM, TEP_PRINT_PID, TEP_PRINT_CPU,
> >                 TEP_PRINT_LATENCY, TEP_PRINT_TIME, TEP_PRINT_NAME, TEP_PRINT_INFO);
> > Output:
> >       ls-11314 [005] d.h. 185207.366383 function __wake_up
> >
> > Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> > Cc: Andrew Morton <akpm@linux-foundation.org>
> > Cc: Jiri Olsa <jolsa@redhat.com>
> > Cc: Namhyung Kim <namhyung@kernel.org>
> > Cc: linux-trace-devel@vger.kernel.org
> > Cc: Patrick McLean <chutzpah@gentoo.org>
> > Link: https://nam04.safelinks.protection.outlook.com/?url=http%3A%2F%2Flore.kernel.org%2Flinux-trace-devel%2F20190801074959.22023-2-tz.stoyanov%40gmail.com&amp;data=02%7C01%7Ctstoyanov%40vmware.com%7Cb43e28f618db4d1ccc4908d73d53caeb%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637045302420525409&amp;sdata=XVy%2FprqSVkHVUJ0Vi1gSeQwnHmc82kipnkMbN%2BaWmiA%3D&amp;reserved=0
> > Link: https://nam04.safelinks.protection.outlook.com/?url=http%3A%2F%2Flore.kernel.org%2Flkml%2F20190805204355.041132030%40goodmis.org&amp;data=02%7C01%7Ctstoyanov%40vmware.com%7Cb43e28f618db4d1ccc4908d73d53caeb%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637045302420535406&amp;sdata=LbuU7Ef2Slbl6%2BVCtw7DRzV5TRp5GrceD6E%2FZ8LbGKM%3D&amp;reserved=0
> > Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> > [ Added support for trace-cmd trace-read.c ]
> > Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
>
>
> I needed to modify this with the following changes:
>
> diff --git a/kernel-shark/src/libkshark.c b/kernel-shark/src/libkshark.c
> index 47ec9c21..4207ae6f 100644
> --- a/kernel-shark/src/libkshark.c
> +++ b/kernel-shark/src/libkshark.c
> @@ -1103,7 +1103,7 @@ static const char *kshark_get_latency(struct tep_handle *pe,
>                 return NULL;
>
>         trace_seq_reset(&seq);
> -       tep_data_latency_format(pe, &seq, record);
> +       tep_print_event(pe, &seq, record, "%s", TEP_PRINT_LATENCY);
>         return seq.buffer;
>  }
>
> @@ -1117,7 +1117,7 @@ static const char *kshark_get_info(struct tep_handle *pe,
>                 return NULL;
>
>         trace_seq_reset(&seq);
> -       tep_event_info(&seq, event, record);
> +       tep_print_event(pe, &seq, record, "%s", TEP_PRINT_INFO);
>
>         /*
>          * The event info string contains a trailing newline.
>
>
> -- Steve

Changes looks OK, thanks Steven.
Reviewed-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>



-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: [PATCH 4/5] libtraceevent, perf tools: Changes in tep_print_event_* APIs

[Steven Rostedt]

On Tue, 17 Sep 2019 22:03:38 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:


> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: linux-trace-devel@vger.kernel.org
> Cc: Patrick McLean <chutzpah@gentoo.org>

Sorry folks for the spam. This was a backport of the kernel's
libtraceevent into trace-cmd's version. I used quilt send mail to post
the series, and since I had the Cc's on this email, you were spammed
with this version.

Please ignore, as the patch is already in the Linux kernel git repo.

-- Steve


> Link: http://lore.kernel.org/linux-trace-devel/20190801074959.22023-2-tz.stoyanov@gmail.com
> Link: http://lore.kernel.org/lkml/20190805204355.041132030@goodmis.org
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> [ Added support for trace-cmd trace-read.c ]
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>

[PATCH 5/5] tools/lib/traceevent: Round up in tep_print_event() time precision

[Steven Rostedt]

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

When testing the output of the old trace-cmd compared to the one that uses
the updated tep_print_event() logic, it was different in that the time stamp
precision in the old format would round up to the nearest precision, where
as the new logic truncates. Bring back the old method of rounding up.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 lib/traceevent/event-parse.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
index d1085aab9c43..7fbbbccab78a 100644
--- a/lib/traceevent/event-parse.c
+++ b/lib/traceevent/event-parse.c
@@ -5527,8 +5527,10 @@ static void print_event_time(struct tep_handle *tep, struct trace_seq *s,
 	if (divstr && isdigit(*(divstr + 1)))
 		div = atoi(divstr + 1);
 	time = record->ts;
-	if (div)
+	if (div) {
+		time += div / 2;
 		time /= div;
+	}
 	pr = prec;
 	while (pr--)
 		p10 *= 10;
-- 
2.20.1

Re: [PATCH 5/5] tools/lib/traceevent: Round up in tep_print_event() time precision

[Tzvetomir Stoyanov]

On Wed, Sep 18, 2019 at 5:03 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
> When testing the output of the old trace-cmd compared to the one that uses
> the updated tep_print_event() logic, it was different in that the time stamp
> precision in the old format would round up to the nearest precision, where
> as the new logic truncates. Bring back the old method of rounding up.
>
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  lib/traceevent/event-parse.c | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
>
> diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
> index d1085aab9c43..7fbbbccab78a 100644
> --- a/lib/traceevent/event-parse.c
> +++ b/lib/traceevent/event-parse.c
> @@ -5527,8 +5527,10 @@ static void print_event_time(struct tep_handle *tep, struct trace_seq *s,
>         if (divstr && isdigit(*(divstr + 1)))
>                 div = atoi(divstr + 1);
>         time = record->ts;
> -       if (div)
> +       if (div) {
> +               time += div / 2;
>                 time /= div;
> +       }
>         pr = prec;
>         while (pr--)
>                 p10 *= 10;
> --
> 2.20.1
>
>

Looks good to me.
Reviewed-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>

-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center