lkml.org 
[lkml]   [2016]   [Oct]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH 3/3] perf tools: Introduce timestamp_in_usec()
From
Date


On 10/23/2016 07:02 PM, Namhyung Kim wrote:
> 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.
>
> Reported-by: Joonwoo Park <joonwoop@codeaurora.org>

Sorry I was busy with something else so didn't have chance to follow up
on my initial proposal and thanks for take caring of this.

> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
> tools/perf/builtin-sched.c | 9 ++++++---
> tools/perf/builtin-script.c | 9 ++++++---
> tools/perf/util/util.c | 9 +++++++++
> tools/perf/util/util.h | 3 +++
> 4 files changed, 24 insertions(+), 6 deletions(-)
>
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 97d6cbf486bb..c88d64ae997e 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 buf[32];
>
> if (!work_list->nb_atoms)
> return;
> @@ -1213,11 +1214,11 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
>
> avg = work_list->total_lat / work_list->nb_atoms;
>
> - 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);
> + timestamp_in_usec(buf, sizeof(buf), work_list->max_lat));

This should be :
s/work_list->max_lat/work_list->max_lat_at/

> }
>
> static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
> @@ -1402,6 +1403,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 buf[32];
>
> BUG_ON(this_cpu >= MAX_CPUS || this_cpu < 0);
>
> @@ -1492,7 +1494,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);
> + color_fprintf(stdout, color, " %12s secs ",
> + timestamp_in_usec(buf, sizeof(buf), timestamp));
> 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 7228d141a789..c848c74bdc90 100644
> --- a/tools/perf/builtin-script.c
> +++ b/tools/perf/builtin-script.c
> @@ -437,7 +437,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)) {
> @@ -464,14 +463,18 @@ static void print_sample_start(struct perf_sample *sample,
> }
>
> if (PRINT_FIELD(TIME)) {
> + char buf[32];
> + size_t sz = sizeof(buf);
> +
> 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);
> + printf("%12s: ", timestamp_in_usec(buf, sz,
> + sample->time));
> }
> }
>
> diff --git a/tools/perf/util/util.c b/tools/perf/util/util.c
> index 85c56800f17a..aa3e778989ce 100644
> --- a/tools/perf/util/util.c
> +++ b/tools/perf/util/util.c
> @@ -433,6 +433,15 @@ int parse_nsec_time(const char *str, u64 *ptime)
> return 0;
> }
>
> +char *timestamp_in_usec(char *buf, size_t sz, u64 timestamp)

I agree with Jirka. timestamp_usec__scnprintf looks better.

Thanks,
Joonwoo

> +{
> + u64 sec = timestamp / NSEC_PER_SEC;
> + u64 usec = (timestamp % NSEC_PER_SEC) / NSEC_PER_USEC;
> +
> + scnprintf(buf, sz, "%"PRIu64".%06"PRIu64, sec, usec);
> + return buf;
> +}
> +
> 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 71b6992f1d98..ece974f1c538 100644
> --- 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);
> +
> +char *timestamp_in_usec(char *buf, size_t sz, u64 timestamp);
> +
> #endif /* GIT_COMPAT_UTIL_H */
>

\
 
 \ /
  Last update: 2016-10-24 22:56    [W:0.080 / U:0.136 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site