[tip:perf/core] perf tools: Introduce timestamp__scnprintf_usec()

[tip-bot for Namhyung Kim]

Commit-ID:  99620a5d0cc8e2dd9aedb629a6e81825f0db020e
Gitweb: http://git.kernel.org/tip/99620a5d0cc8e2dd9aedb629a6e81825f0db020e
Author: Namhyung Kim 
AuthorDate: Mon, 24 Oct 2016 11:02:45 +0900
Committer:  Arnaldo Carvalho de Melo 
CommitDate: Fri, 28 Oct 2016 11:29:40 -0200

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 
Signed-off-by: Namhyung Kim 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Peter Zijlstra 
Link: http://lkml.kernel.org/r/20161024020246.14928-3-namhy...@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo 
---
 tools/perf/builtin-sched.c  | 10 +++---
 tools/perf/builtin-script.c | 10 ++
 tools/perf/util/util.c  |  8 
 tools/perf/util/util.h  |  3 +++
 4 files changed, 24 insertions(+), 7 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1f33d15..fb34412 100644
--- 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 412fb6e..e1daff3 100644
--- 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 = >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 85c5680..5bbd1f6 100644
--- 

[tip:perf/core] perf tools: Introduce timestamp__scnprintf_usec()

[tip-bot for Namhyung Kim]

Commit-ID:  99620a5d0cc8e2dd9aedb629a6e81825f0db020e
Gitweb: http://git.kernel.org/tip/99620a5d0cc8e2dd9aedb629a6e81825f0db020e
Author: Namhyung Kim 
AuthorDate: Mon, 24 Oct 2016 11:02:45 +0900
Committer:  Arnaldo Carvalho de Melo 
CommitDate: Fri, 28 Oct 2016 11:29:40 -0200

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 
Signed-off-by: Namhyung Kim 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Peter Zijlstra 
Link: http://lkml.kernel.org/r/20161024020246.14928-3-namhy...@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo 
---
 tools/perf/builtin-sched.c  | 10 +++---
 tools/perf/builtin-script.c | 10 ++
 tools/perf/util/util.c  |  8 
 tools/perf/util/util.h  |  3 +++
 4 files changed, 24 insertions(+), 7 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1f33d15..fb34412 100644
--- 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 412fb6e..e1daff3 100644
--- 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 = >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 85c5680..5bbd1f6 100644
--- 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