Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1506825 > unrolled thread

[PATCH 3/3] perf tools: Introduce timestamp_in_usec()

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH 3/3] perf tools: Introduce timestamp_in_usec() Namhyung Kim <namhyung@kernel.org> - 2016-10-24 04:10 +0200
    Re: [PATCH 3/3] perf tools: Introduce timestamp_in_usec() Jiri Olsa <jolsa@redhat.com> - 2016-10-24 18:50 +0200
    Re: [PATCH 3/3] perf tools: Introduce timestamp_in_usec() Joonwoo Park <joonwoop@codeaurora.org> - 2016-10-24 23:00 +0200

#1506825 — [PATCH 3/3] perf tools: Introduce timestamp_in_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.

Reported-by: Joonwoo Park <joonwoop@codeaurora.org>
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));
 }
 
 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)
+{
+	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 */
-- 
2.10.0

[toc] | [next] | [standalone]

#1507433

On Mon, Oct 24, 2016 at 11:02:45AM +0900, Namhyung Kim wrote:

SNIP

> +
>  		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)
> +{

good idea.. 2 things:
  - I've spot several other places by looking for NSEC_PER_USEC
    but haven't checked deeply they could be also users for this function

  - timestamp_usec__scnprint might fir better

thanks,
jirka

[toc] | [prev] | [next] | [standalone]

#1507724

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 */
>

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web