* [PATCH] trace-cmd: Add helper function to get the time stamp print format
@ 2020-07-06 15:14 Tzvetomir Stoyanov (VMware)
2020-07-07 0:54 ` Steven Rostedt
0 siblings, 1 reply; 2+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2020-07-06 15:14 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
Printing time stamps depends on:
- traced data - if we display latency tracing or normal events
- user defined time precision - up to nanoseconds or microseconds
In few places in the code there is logic to get the print
time stamp format based on these criteria. That code is replaced
with a helper function, to make the implementation more consistent.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
tracecmd/trace-read.c | 31 ++++++++++++++++++++++++++++---
1 file changed, 28 insertions(+), 3 deletions(-)
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index c1f840d5..f1ba7835 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -141,13 +141,38 @@ static void print_event_name(struct trace_seq *s, struct tep_event *event)
trace_seq_printf(s, "%.*s", 20 - len, spaces);
}
+enum time_fmt {
+ TIME_FMT_LAT = 1,
+ TIME_FMT_NORMAL = 2,
+};
+
+static const char *time_format(struct tracecmd_input *handle, enum time_fmt tf)
+{
+ struct tep_handle *tep = tracecmd_get_pevent(handle);
+
+ switch (tf) {
+ case TIME_FMT_LAT:
+ if (latency_format)
+ return "%8.8s-%-5d %3d";
+ return "%16s-%-5d [%03d]";
+ default:
+ if (tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS) {
+ if (tep_test_flag(tep, TEP_NSEC_OUTPUT))
+ return " %9.1d";
+ else
+ return " %6.1000d";
+ } else
+ return "%12d:";
+ }
+}
+
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:";
+ const char *lfmt = time_format(handle, TIME_FMT_LAT);
+ const char *tfmt = time_format(handle, TIME_FMT_NORMAL);
event = tep_find_event_by_record(tep, record);
tep_print_event(tep, s, record, lfmt, TEP_PRINT_COMM,
@@ -781,7 +806,7 @@ 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 *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:";
+ const char *tfmt = time_format(handle, TIME_FMT_NORMAL);
struct tep_handle *pevent;
struct tep_event *event;
struct trace_seq s;
--
2.26.2
^ permalink raw reply related [flat|nested] 2+ messages in thread
* Re: [PATCH] trace-cmd: Add helper function to get the time stamp print format
2020-07-06 15:14 [PATCH] trace-cmd: Add helper function to get the time stamp print format Tzvetomir Stoyanov (VMware)
@ 2020-07-07 0:54 ` Steven Rostedt
0 siblings, 0 replies; 2+ messages in thread
From: Steven Rostedt @ 2020-07-07 0:54 UTC (permalink / raw)
To: Tzvetomir Stoyanov (VMware); +Cc: linux-trace-devel
Hi Tzvetomir,
I change the commit log for the actual reason. The trace-cmd report -t
wasn't working.
-- Steve
From 3a7d928b1b9d67eec840c6a868627e39fc7b1a73 Mon Sep 17 00:00:00 2001
From: "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com>
Date: Mon, 6 Jul 2020 18:14:04 +0300
Subject: [PATCH] trace-cmd: Fix trace-cmd report -t to show full timestamp
The -t wasn't printing the full nanosecond time stamp as it is described in
the man pages. Instead it was still printing just microsecond precision.
Before the patch:
# trace-cmd report -t
kworker/5:1H-887 [005] 14943901.178049: sched_stat_runtime: comm=kworker/5:1H pid=887 runtime=13436 [ns] vruntime=1660916130854173 [ns]
kworker/5:1H-887 [005] 14943901.178066: sched_switch: kworker/5:1H:887 [100] W ==> swapper/5:0 [120]
sleep-25090 [002] 14943901.178089: sched_waking: comm=migration/2 pid=22 prio=0 target_cpu=002
sleep-25090 [002] 14943901.178091: sched_wakeup: migration/2:22 [0] success=1 CPU:002
sleep-25090 [002] 14943901.178092: sched_stat_runtime: comm=trace-cmd pid=25090 runtime=221204 [ns] vruntime=20995297524016 [ns]
sleep-25090 [002] 14943901.178094: sched_switch: trace-cmd:25090 [120] R ==> migration/2:22 [0]
migration/2-22 [002] 14943901.178097: sched_migrate_task: comm=trace-cmd pid=25090 prio=120 orig_cpu=2 dest_cpu=17
migration/2-22 [002] 14943901.178101: sched_wake_idle_without_ipi: cpu=17
migration/2-22 [002] 14943901.178103: sched_switch: migration/2:22 [0] S ==> swapper/2:0 [120]
After the patch:
# trace-cmd report -t
kworker/5:1H-887 [005] 14943901.178048648 sched_stat_runtime: comm=kworker/5:1H pid=887 runtime=13436 [ns] vruntime=1660916130854173 [ns]
kworker/5:1H-887 [005] 14943901.178065741 sched_switch: kworker/5:1H:887 [100] W ==> swapper/5:0 [120]
sleep-25090 [002] 14943901.178088505 sched_waking: comm=migration/2 pid=22 prio=0 target_cpu=002
sleep-25090 [002] 14943901.178090827 sched_wakeup: migration/2:22 [0] success=1 CPU:002
sleep-25090 [002] 14943901.178091660 sched_stat_runtime: comm=trace-cmd pid=25090 runtime=221204 [ns] vruntime=20995297524016 [ns]
sleep-25090 [002] 14943901.178093512 sched_switch: trace-cmd:25090 [120] R ==> migration/2:22 [0]
migration/2-22 [002] 14943901.178097240 sched_migrate_task: comm=trace-cmd pid=25090 prio=120 orig_cpu=2 dest_cpu=17
migration/2-22 [002] 14943901.178101255 sched_wake_idle_without_ipi: cpu=17
migration/2-22 [002] 14943901.178103431 sched_switch: migration/2:22 [0] S ==> swapper/2:0 [120]
Link: https://lore.kernel.org/linux-trace-devel/20200706151404.25603-1-tz.stoyanov@gmail.com
Fixes: 150d479b623a ("libtraceevent, perf tools: Changes in tep_print_event_* APIs")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
tracecmd/trace-read.c | 31 ++++++++++++++++++++++++++++---
1 file changed, 28 insertions(+), 3 deletions(-)
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index c1f840d5..f1ba7835 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -141,13 +141,38 @@ static void print_event_name(struct trace_seq *s, struct tep_event *event)
trace_seq_printf(s, "%.*s", 20 - len, spaces);
}
+enum time_fmt {
+ TIME_FMT_LAT = 1,
+ TIME_FMT_NORMAL = 2,
+};
+
+static const char *time_format(struct tracecmd_input *handle, enum time_fmt tf)
+{
+ struct tep_handle *tep = tracecmd_get_pevent(handle);
+
+ switch (tf) {
+ case TIME_FMT_LAT:
+ if (latency_format)
+ return "%8.8s-%-5d %3d";
+ return "%16s-%-5d [%03d]";
+ default:
+ if (tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS) {
+ if (tep_test_flag(tep, TEP_NSEC_OUTPUT))
+ return " %9.1d";
+ else
+ return " %6.1000d";
+ } else
+ return "%12d:";
+ }
+}
+
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:";
+ const char *lfmt = time_format(handle, TIME_FMT_LAT);
+ const char *tfmt = time_format(handle, TIME_FMT_NORMAL);
event = tep_find_event_by_record(tep, record);
tep_print_event(tep, s, record, lfmt, TEP_PRINT_COMM,
@@ -781,7 +806,7 @@ 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 *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:";
+ const char *tfmt = time_format(handle, TIME_FMT_NORMAL);
struct tep_handle *pevent;
struct tep_event *event;
struct trace_seq s;
--
2.25.4
^ permalink raw reply related [flat|nested] 2+ messages in thread
end of thread, other threads:[~2020-07-07 0:54 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-07-06 15:14 [PATCH] trace-cmd: Add helper function to get the time stamp print format Tzvetomir Stoyanov (VMware)
2020-07-07 0:54 ` Steven Rostedt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).