Commit 99620a5d authored by Namhyung Kim's avatar Namhyung Kim Committed by Arnaldo Carvalho de Melo

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: default avatarJoonwoo Park <joonwoop@codeaurora.org>
Signed-off-by: default avatarNamhyung 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.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
parent e107f129
...@@ -1191,6 +1191,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ ...@@ -1191,6 +1191,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
int i; int i;
int ret; int ret;
u64 avg; u64 avg;
char max_lat_at[32];
if (!work_list->nb_atoms) if (!work_list->nb_atoms)
return; return;
...@@ -1212,12 +1213,13 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ ...@@ -1212,12 +1213,13 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
printf(" "); printf(" ");
avg = work_list->total_lat / work_list->nb_atoms; 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, (double)work_list->total_runtime / NSEC_PER_MSEC,
work_list->nb_atoms, (double)avg / 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 / 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) 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, ...@@ -1402,6 +1404,7 @@ static int map_switch_event(struct perf_sched *sched, struct perf_evsel *evsel,
int cpus_nr; int cpus_nr;
bool new_cpu = false; bool new_cpu = false;
const char *color = PERF_COLOR_NORMAL; const char *color = PERF_COLOR_NORMAL;
char stimestamp[32];
BUG_ON(this_cpu >= MAX_CPUS || this_cpu < 0); 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, ...@@ -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)) if (sched->map.cpus && !cpu_map__has(sched->map.cpus, this_cpu))
goto out; 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)) { if (new_shortname || (verbose && sched_in->tid)) {
const char *pid_color = color; const char *pid_color = color;
......
...@@ -441,7 +441,6 @@ static void print_sample_start(struct perf_sample *sample, ...@@ -441,7 +441,6 @@ static void print_sample_start(struct perf_sample *sample,
{ {
struct perf_event_attr *attr = &evsel->attr; struct perf_event_attr *attr = &evsel->attr;
unsigned long secs; unsigned long secs;
unsigned long usecs;
unsigned long long nsecs; unsigned long long nsecs;
if (PRINT_FIELD(COMM)) { if (PRINT_FIELD(COMM)) {
...@@ -471,11 +470,14 @@ static void print_sample_start(struct perf_sample *sample, ...@@ -471,11 +470,14 @@ static void print_sample_start(struct perf_sample *sample,
nsecs = sample->time; nsecs = sample->time;
secs = nsecs / NSEC_PER_SEC; secs = nsecs / NSEC_PER_SEC;
nsecs -= secs * NSEC_PER_SEC; nsecs -= secs * NSEC_PER_SEC;
usecs = nsecs / NSEC_PER_USEC;
if (nanosecs) if (nanosecs)
printf("%5lu.%09llu: ", secs, nsecs); printf("%5lu.%09llu: ", secs, nsecs);
else else {
printf("%5lu.%06lu: ", secs, usecs); char sample_time[32];
timestamp__scnprintf_usec(sample->time, sample_time, sizeof(sample_time));
printf("%12s: ", sample_time);
}
} }
} }
......
...@@ -433,6 +433,14 @@ int parse_nsec_time(const char *str, u64 *ptime) ...@@ -433,6 +433,14 @@ int parse_nsec_time(const char *str, u64 *ptime)
return 0; 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) unsigned long parse_tag_value(const char *str, struct parse_tag *tags)
{ {
struct parse_tag *i = tags; struct parse_tag *i = tags;
......
...@@ -362,4 +362,7 @@ extern int sched_getcpu(void); ...@@ -362,4 +362,7 @@ extern int sched_getcpu(void);
#endif #endif
int is_printable_array(char *p, unsigned int len); 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 */ #endif /* GIT_COMPAT_UTIL_H */
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment