perf tools: Introduce timestamp__scnprintf_usec()

Joonwoo reported that there's a mismatch between timestamps in script
and sched commands.  This was because of difference in printing the
timestamp.  Factor out the code and share it so that they can be in
sync.  Also I found that sched map has similar problem, fix it too.

Committer notes:

Fixed the max_lat_at bug introduced by Namhyung's original patch, as
pointed out by Joonwoo, and made it a function following the scnprintf()
model, i.e. returning the number of bytes formatted, and receiving as
the first parameter the object from where the data to the formatting is
obtained, renaming it from:

   char *timestamp_in_usec(char *bf, size_t size, u64 timestamp)

to

   int timestamp__scnprintf_usec(u64 timestamp, char *bf, size_t size)

Reported-by: Joonwoo Park <joonwoop@codeaurora.org>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Link: http://lkml.kernel.org/r/20161024020246.14928-3-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1f33d15314a556e2fa1f2956046667583733d8ed..fb3441211e4ba3ca51f638a2e2fb87ac6c55bf1d 100644 (file)
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -1191,6 +1191,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
        int i;
        int ret;
        u64 avg;
+       char max_lat_at[32];
 
        if (!work_list->nb_atoms)
                return;
@@ -1212,12 +1213,13 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
                printf(" ");
 
        avg = work_list->total_lat / work_list->nb_atoms;
+       timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
 
-       printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13.6f s\n",
+       printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13s s\n",
              (double)work_list->total_runtime / NSEC_PER_MSEC,
                 work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
                 (double)work_list->max_lat / NSEC_PER_MSEC,
-                (double)work_list->max_lat_at / NSEC_PER_SEC);
+                max_lat_at);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
@@ -1402,6 +1404,7 @@ static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,
        int cpus_nr;
        bool new_cpu = false;
        const char *color = PERF_COLOR_NORMAL;
+       char stimestamp[32];
 
        BUG_ON(this_cpu >= MAX_CPUS || this_cpu < 0);
 
@@ -1492,7 +1495,8 @@ static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,
        if (sched->map.cpus && !cpu_map__has(sched->map.cpus, this_cpu))
                goto out;
 
-       color_fprintf(stdout, color, "  %12.6f secs ", (double)timestamp / NSEC_PER_SEC);
+       timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp));
+       color_fprintf(stdout, color, "  %12s secs ", stimestamp);
        if (new_shortname || (verbose && sched_in->tid)) {
                const char *pid_color = color;
 

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 412fb6e65ac06dcdb7e00e667c9f12d0a8edbeda..e1daff36d0702920038e9685c47e881d6b7195db 100644 (file)
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -441,7 +441,6 @@ static void print_sample_start(struct perf_sample *sample,
 {
        struct perf_event_attr *attr = &evsel->attr;
        unsigned long secs;
-       unsigned long usecs;
        unsigned long long nsecs;
 
        if (PRINT_FIELD(COMM)) {
@@ -471,11 +470,14 @@ static void print_sample_start(struct perf_sample *sample,
                nsecs = sample->time;
                secs = nsecs / NSEC_PER_SEC;
                nsecs -= secs * NSEC_PER_SEC;
-               usecs = nsecs / NSEC_PER_USEC;
+
                if (nanosecs)
                        printf("%5lu.%09llu: ", secs, nsecs);
-               else
-                       printf("%5lu.%06lu: ", secs, usecs);
+               else {
+                       char sample_time[32];
+                       timestamp__scnprintf_usec(sample->time, sample_time, sizeof(sample_time));
+                       printf("%12s: ", sample_time);
+               }
        }
 }
 

diff --git a/tools/perf/util/util.c b/tools/perf/util/util.c
index 85c56800f17a6018eb080db40e9a08b03f9a460c..5bbd1f609f1f4da28fe5f671162e62289dab1ad8 100644 (file)
--- a/tools/perf/util/util.c
+++ b/tools/perf/util/util.c
@@ -433,6 +433,14 @@ int parse_nsec_time(const char *str, u64 *ptime)
        return 0;
 }
 
+int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz)
+{
+       u64  sec = timestamp / NSEC_PER_SEC;
+       u64 usec = (timestamp % NSEC_PER_SEC) / NSEC_PER_USEC;
+
+       return scnprintf(buf, sz, "%"PRIu64".%06"PRIu64, sec, usec);
+}
+
 unsigned long parse_tag_value(const char *str, struct parse_tag *tags)
 {
        struct parse_tag *i = tags;

diff --git a/tools/perf/util/util.h b/tools/perf/util/util.h
index 71b6992f1d985d7db11bd6b97f0656faed7ddf7c..79662d67891e1a06c1c85e484d8d8cbe9ecc4562 100644 (file)
--- a/tools/perf/util/util.h
+++ b/tools/perf/util/util.h
@@ -362,4 +362,7 @@ extern int sched_getcpu(void);
 #endif
 
 int is_printable_array(char *p, unsigned int len);
+
+int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz);
+
 #endif /* GIT_COMPAT_UTIL_H */