Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1759703AbcJ1Nau (ORCPT ); Fri, 28 Oct 2016 09:30:50 -0400 Received: from mail.kernel.org ([198.145.29.136]:59104 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751795AbcJ1Nas (ORCPT ); Fri, 28 Oct 2016 09:30:48 -0400 Date: Fri, 28 Oct 2016 11:30:41 -0200 From: Arnaldo Carvalho de Melo To: Joonwoo Park Cc: Ingo Molnar , linux-kernel@vger.kernel.org, Namhyung Kim , David Ahern , Jiri Olsa , Peter Zijlstra , Arnaldo Carvalho de Melo Subject: Re: [PATCH 08/15] perf tools: Introduce timestamp_in_usec() Message-ID: <20161028133041.GC28694@kernel.org> References: <1477600855-27580-1-git-send-email-acme@kernel.org> <1477600855-27580-9-git-send-email-acme@kernel.org> <41a9c8e5-044e-d42d-0e42-058b974d4f00@codeaurora.org> <20161028125338.GA28694@kernel.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20161028125338.GA28694@kernel.org> X-Url: http://acmel.wordpress.com User-Agent: Mutt/1.7.1 (2016-10-04) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 6401 Lines: 171 Em Fri, Oct 28, 2016 at 10:53:38AM -0200, Arnaldo Carvalho de Melo escreveu: > Em Thu, Oct 27, 2016 at 04:14:55PM -0700, Joonwoo Park escreveu: > > > > > > On 10/27/2016 01:40 PM, Arnaldo Carvalho de Melo wrote: > > > From: Namhyung Kim > > > > > > 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-and-Acked-by: Joonwoo Park > > > > Hmm.. I didn't ACK this patch because of bug I commented at > > https://www.mail-archive.com/linux-kernel@vger.kernel.org/msg1256724.html > > > > s/work_list->max_lat/work_list->max_lat_at/ > > Sorry about that, I took the "thanks for taking care of this" as an ack, > now that I re-read that message I saw your points later on in that > e-mail. > > Since Ingo hasn't pulled this, I'll try fixing it, will check that other > naming issue, So, here is how it ended up, it fixes the problem you pointed out and renames the function to follow the scnprintf() convention, as used elsewhere in tools/perf (tools/perf/util/annotate.h has several examples). commit 99620a5d0cc8e2dd9aedb629a6e81825f0db020e Author: Namhyung Kim Date: Mon Oct 24 11:02:45 2016 +0900 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-namhyung@kernel.org Signed-off-by: Arnaldo Carvalho de Melo diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c index 1f33d15314a5..fb3441211e4b 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 412fb6e65ac0..e1daff36d070 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 = &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 85c56800f17a..5bbd1f609f1f 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 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 71b6992f1d98..79662d67891e 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); + +int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz); + #endif /* GIT_COMPAT_UTIL_H */