perf sched: kill time stamp discrepancy between script and latency

PATCH In review Joonwoo Park 2 participants 6 messages Sep 29, 2016 – Oct 4, 2016 perf events

Share & tools

Joonwoo Park

author

2016-09-29 02:26 UTC #0 lore raw

PATCH 1/1 perf sched: kill time stamp discrepancy between script and latency

Perf sched latency is handy to find out the maximum sched latency and the time stamp of the event. After running sched latency, if a found latency looks suspicious it's quite reasonable to run perf script subsequently and search with the time stamp given by perf sched latency to continue further debugging. However, at present, it's possible the time stamp given by perf sched latency cannot be found in the trace output by perf script because perf sched latency converts the event time from ns to ms as double float and prints it with printf which does banker's rounding as opposed to perf script doesn't.

For example:

0x750ff0 [0x80]: event: 9
<snip>
2 1858303049520 0x750ff0 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 15281/15281: 0xffffffff8162a63a period: 1 addr: 0

    ... thread: hackbench:15281

<snip>

    $ perf sched -i perf.data latency | grep hackbench
      hackbench:(401)       +   3539.283 ms |    23347 | avg:    7.286 ms | max:  829.998 ms | max at:   1858.303050 s

    $ perf script -i perf.data | grep "1858\.303050"

    $ perf script -i perf.data | grep "1858\.303049"
      hackbench 15281 [002]  1858.303049:       sched:sched_switch: prev_comm=hackbench prev_pid=15281 prev_prio=120 prev_state=D ==> next_comm=hackbench next_pid=15603 next_prio=120

Fix perf latency to print out time stamp without rounding to avoid such discrepancy.

Cc Peter Zijlstra <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc Alexander Shishkin <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc [email protected]

Signed-off-by Joonwoo Park <[email protected]>

---

I was tempted to get rid of all u64 to double casting in the function output_lat_thread but didn't because there is no data loss as of today. Double float gives at least 15 significant decimal digits precision while the function requires only 14 significant digits precision.

$ python -c "print(len(str(int(0xffffffffffffffff / 1e6))))"
14

 tools/lib/traceevent/event-parse.h |  1 +
 tools/perf/builtin-sched.c         | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)

tools/lib/traceevent/event-parse.h +1 -0

index 9ffde37..f42703c 100644
@@ -174,6 +174,7 @@ struct pevent_plugin_option {
 
 #define NSECS_PER_SEC		1000000000ULL
 #define NSECS_PER_USEC		1000ULL
+#define MSECS_PER_SEC		1000ULL
 
 enum format_flags {
 	FIELD_IS_ARRAY		= 1,

tools/perf/builtin-sched.c +10 -2

index afa0576..e5cf51a 100644
@@ -1190,6 +1190,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 	int i;
 	int ret;
 	u64 avg;
+	u64 max_lat_at_sec, max_lat_at_msec;
 
 	if (!work_list->nb_atoms)
 		return;

@@ -1212,11 +1213,18 @@ 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",
+	/*
+	 * Avoid round up with printf to prevent event time discrepency
+	 * between sched script and latency.
+	 */
+	max_lat_at_sec = work_list->max_lat_at / NSECS_PER_SEC;
+	max_lat_at_msec = (work_list->max_lat_at -
+			   max_lat_at_sec * NSECS_PER_SEC) / MSECS_PER_SEC;
+	printf("+%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %6lu.%06lu s\n",
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
 		 (double)work_list->max_lat / 1e6,
-		 (double)work_list->max_lat_at / 1e9);
+		 max_lat_at_sec, max_lat_at_msec);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)

Signature · 2 lines

The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
hosted by The Linux Foundation

Joonwoo Park

author

2016-09-29 02:29 UTC #1 lore raw

Quoted 76 lines · Joonwoo Park

Perf sched latency is handy to find out the maximum sched latency and the time stamp of the event. After running sched latency, if a found latency looks suspicious it's quite reasonable to run perf script subsequently and search with the time stamp given by perf sched latency to continue further debugging. However, at present, it's possible the time stamp given by perf sched latency cannot be found in the trace output by perf script because perf sched latency converts the event time from ns to ms as double float and prints it with printf which does banker's rounding as opposed to perf script doesn't.
For example:
   0x750ff0 [0x80]: event: 9
   <snip>
   2 1858303049520 0x750ff0 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 15281/15281: 0xffffffff8162a63a period: 1 addr: 0
    ... thread: hackbench:15281
   <snip>

    $ perf sched -i perf.data latency | grep hackbench
      hackbench:(401)       +   3539.283 ms |    23347 | avg:    7.286 ms | max:  829.998 ms | max at:   1858.303050 s

    $ perf script -i perf.data | grep "1858\.303050"

    $ perf script -i perf.data | grep "1858\.303049"
      hackbench 15281 [002]  1858.303049:       sched:sched_switch: prev_comm=hackbench prev_pid=15281 prev_prio=120 prev_state=D ==> next_comm=hackbench next_pid=15603 next_prio=120
Fix perf latency to print out time stamp without rounding to avoid such discrepancy.
Cc Peter Zijlstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Alexander Shishkin <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc [email protected]
Signed-off-by Joonwoo Park <[email protected]>
---
I was tempted to get rid of all u64 to double casting in the function output_lat_thread but didn't because there is no data loss as of today. Double float gives at least 15 significant decimal digits precision while the function requires only 14 significant digits precision.
$ python -c "print(len(str(int(0xffffffffffffffff / 1e6))))"
14
 tools/lib/traceevent/event-parse.h |  1 +
 tools/perf/builtin-sched.c         | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)
tools/lib/traceevent/event-parse.h +1 -0
index 9ffde37..f42703c 100644
@@ -174,6 +174,7 @@ struct pevent_plugin_option {
 
 #define NSECS_PER_SEC		1000000000ULL
 #define NSECS_PER_USEC		1000ULL
+#define MSECS_PER_SEC		1000ULL
 
 enum format_flags {
 	FIELD_IS_ARRAY		= 1,
tools/perf/builtin-sched.c +1 -0
index afa0576..e5cf51a 100644
@@ -1190,6 +1190,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 	int i;
 	int ret;
 	u64 avg;
+	u64 max_lat_at_sec, max_lat_at_msec;
 
 	if (!work_list->nb_atoms)
 		return;

tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1217

Quoted 6 lines

tools/perf/builtin-sched.c +2 -1

@@ -1212,11 +1213,18 @@ 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",
+	/*
+	 * Avoid round up with printf to prevent event time discrepency

s/discrepency/discrepancy/
I will fix this typo after gathering review comments.

Thanks,
Joonwoo

Quoted 15 lines

tools/perf/builtin-sched.c +7 -1

+	 * between sched script and latency.
+	 */
+	max_lat_at_sec = work_list->max_lat_at / NSECS_PER_SEC;
+	max_lat_at_msec = (work_list->max_lat_at -
+			   max_lat_at_sec * NSECS_PER_SEC) / MSECS_PER_SEC;
+	printf("+%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %6lu.%06lu s\n",
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
 		 (double)work_list->max_lat / 1e6,
-		 (double)work_list->max_lat_at / 1e9);
+		 max_lat_at_sec, max_lat_at_msec);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)

Namhyung Kim

maintainer

2016-10-01 05:15 UTC #2 lore raw

In reply to Joonwoo Park

Hi Joonwoo,

Quoted 68 lines · Joonwoo Park

Perf sched latency is handy to find out the maximum sched latency and the time stamp of the event. After running sched latency, if a found latency looks suspicious it's quite reasonable to run perf script subsequently and search with the time stamp given by perf sched latency to continue further debugging. However, at present, it's possible the time stamp given by perf sched latency cannot be found in the trace output by perf script because perf sched latency converts the event time from ns to ms as double float and prints it with printf which does banker's rounding as opposed to perf script doesn't.
For example:
   0x750ff0 [0x80]: event: 9
   <snip>
   2 1858303049520 0x750ff0 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 15281/15281: 0xffffffff8162a63a period: 1 addr: 0
    ... thread: hackbench:15281
   <snip>

    $ perf sched -i perf.data latency | grep hackbench
      hackbench:(401)       +   3539.283 ms |    23347 | avg:    7.286 ms | max:  829.998 ms | max at:   1858.303050 s

    $ perf script -i perf.data | grep "1858\.303050"

    $ perf script -i perf.data | grep "1858\.303049"
      hackbench 15281 [002]  1858.303049:       sched:sched_switch: prev_comm=hackbench prev_pid=15281 prev_prio=120 prev_state=D ==> next_comm=hackbench next_pid=15603 next_prio=120
Fix perf latency to print out time stamp without rounding to avoid such discrepancy.
Cc Peter Zijlstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Alexander Shishkin <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc [email protected]
Signed-off-by Joonwoo Park <[email protected]>
---
I was tempted to get rid of all u64 to double casting in the function output_lat_thread but didn't because there is no data loss as of today. Double float gives at least 15 significant decimal digits precision while the function requires only 14 significant digits precision.
$ python -c "print(len(str(int(0xffffffffffffffff / 1e6))))"
14
 tools/lib/traceevent/event-parse.h |  1 +
 tools/perf/builtin-sched.c         | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)
tools/lib/traceevent/event-parse.h +1 -0
index 9ffde37..f42703c 100644
@@ -174,6 +174,7 @@ struct pevent_plugin_option {
 
 #define NSECS_PER_SEC		1000000000ULL
 #define NSECS_PER_USEC		1000ULL
+#define MSECS_PER_SEC		1000ULL
 
 enum format_flags {
 	FIELD_IS_ARRAY		= 1,
tools/perf/builtin-sched.c +0 -0
index afa0576..e5cf51a 100644

tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1193

Quoted 4 lines

tools/perf/builtin-sched.c +1 -0

@@ -1190,6 +1190,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 	int i;
 	int ret;
 	u64 avg;
+	u64 max_lat_at_sec, max_lat_at_msec;

Isn't it usec rathen than msec? :)

Quoted 6 lines

tools/perf/builtin-sched.c +0 -0

 	if (!work_list->nb_atoms)
 		return;

@@ -1212,11 +1213,18 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 
 	avg = work_list->total_lat / work_list->nb_atoms;

tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1223

Quoted 10 lines

tools/perf/builtin-sched.c +8 -1

 
-	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13.6f s\n",
+	/*
+	 * Avoid round up with printf to prevent event time discrepency
+	 * between sched script and latency.
+	 */
+	max_lat_at_sec = work_list->max_lat_at / NSECS_PER_SEC;
+	max_lat_at_msec = (work_list->max_lat_at -
+			   max_lat_at_sec * NSECS_PER_SEC) / MSECS_PER_SEC;
+	printf("+%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %6lu.%06lu s\n",

Maybe you'd better to be in sync with the script code:

	if (PRINT_FIELD(TIME)) {
		nsecs = sample->time;
		secs = nsecs / NSECS_PER_SEC;
		nsecs -= secs * NSECS_PER_SEC;
		usecs = nsecs / NSECS_PER_USEC;
		if (nanosecs)
			printf("%5lu.%09llu: ", secs, nsecs);
		else
			printf("%5lu.%06lu: ", secs, usecs);
	}

Thanks,
Namhyung

Quoted 12 lines

tools/perf/builtin-sched.c +1 -1

 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
 		 (double)work_list->max_lat / 1e6,
-		 (double)work_list->max_lat_at / 1e9);
+		 max_lat_at_sec, max_lat_at_msec);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)

Signature · 2 lines

The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
hosted by The Linux Foundation

Joonwoo Park

author

2016-10-03 22:05 UTC #3 lore raw

Quoted 64 lines · Namhyung Kim

Hi Joonwoo,
Quoted 61 lines · Joonwoo Park
Perf sched latency is handy to find out the maximum sched latency and the time stamp of the event. After running sched latency, if a found latency looks suspicious it's quite reasonable to run perf script subsequently and search with the time stamp given by perf sched latency to continue further debugging. However, at present, it's possible the time stamp given by perf sched latency cannot be found in the trace output by perf script because perf sched latency converts the event time from ns to ms as double float and prints it with printf which does banker's rounding as opposed to perf script doesn't.
For example:
   0x750ff0 [0x80]: event: 9
   <snip>
   2 1858303049520 0x750ff0 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 15281/15281: 0xffffffff8162a63a period: 1 addr: 0
    ... thread: hackbench:15281
   <snip>

    $ perf sched -i perf.data latency | grep hackbench
      hackbench:(401)       +   3539.283 ms |    23347 | avg:    7.286 ms | max:  829.998 ms | max at:   1858.303050 s

    $ perf script -i perf.data | grep "1858\.303050"

    $ perf script -i perf.data | grep "1858\.303049"
      hackbench 15281 [002]  1858.303049:       sched:sched_switch: prev_comm=hackbench prev_pid=15281 prev_prio=120 prev_state=D ==> next_comm=hackbench next_pid=15603 next_prio=120
Fix perf latency to print out time stamp without rounding to avoid such discrepancy.
Cc Peter Zijlstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Alexander Shishkin <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc [email protected]
Signed-off-by Joonwoo Park <[email protected]>
---
I was tempted to get rid of all u64 to double casting in the function output_lat_thread but didn't because there is no data loss as of today. Double float gives at least 15 significant decimal digits precision while the function requires only 14 significant digits precision.
$ python -c "print(len(str(int(0xffffffffffffffff / 1e6))))"
14
 tools/lib/traceevent/event-parse.h |  1 +
 tools/perf/builtin-sched.c         | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)
tools/lib/traceevent/event-parse.h +1 -0
index 9ffde37..f42703c 100644
@@ -174,6 +174,7 @@ struct pevent_plugin_option {
 
 #define NSECS_PER_SEC		1000000000ULL
 #define NSECS_PER_USEC		1000ULL
+#define MSECS_PER_SEC		1000ULL
 

Quoted 13 lines

tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1193
Quoted 11 lines
tools/lib/traceevent/event-parse.h +0 -0
 enum format_flags {
 	FIELD_IS_ARRAY		= 1,
tools/perf/builtin-sched.c +1 -0
index afa0576..e5cf51a 100644
@@ -1190,6 +1190,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 	int i;
 	int ret;
 	u64 avg;
+	u64 max_lat_at_sec, max_lat_at_msec;
Isn't it usec rathen than msec? :)

It's to contain three decimal digits which are msecs when 'max_lat_at' is expressed in sec. For example when max_lat_at = 1858303049520 which is 1858.3030495199998 sec, max_lat_at_msec is meant to be 303.

I must admit variable's name is bit misleading. Maybe just secs, msecs are better? Also just noticed u64 isn't needed for msecs. Will size down.

Quoted 20 lines

Quoted 7 lines

tools/perf/builtin-sched.c +0 -0

 	if (!work_list->nb_atoms)
 		return;

@@ -1212,11 +1213,18 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 
 	avg = work_list->total_lat / work_list->nb_atoms;

tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1223

Quoted 10 lines

tools/perf/builtin-sched.c +8 -1

 
-	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13.6f s\n",
+	/*
+	 * Avoid round up with printf to prevent event time discrepency
+	 * between sched script and latency.
+	 */
+	max_lat_at_sec = work_list->max_lat_at / NSECS_PER_SEC;
+	max_lat_at_msec = (work_list->max_lat_at -
+			   max_lat_at_sec * NSECS_PER_SEC) / MSECS_PER_SEC;
+	printf("+%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %6lu.%06lu s\n",

Maybe you'd better to be in sync with the script code:

Quoted 10 lines

	if (PRINT_FIELD(TIME)) {
		nsecs = sample->time;
		secs = nsecs / NSECS_PER_SEC;
		nsecs -= secs * NSECS_PER_SEC;
		usecs = nsecs / NSECS_PER_USEC;
		if (nanosecs)
			printf("%5lu.%09llu: ", secs, nsecs);
		else
			printf("%5lu.%06lu: ", secs, usecs);
	}

Apart from variable name, I'm not quite sure what to sync because sched doesn't print in nsecs. Maybe you just wanted for variable names in sync rather than logic?

Thanks!
Joonwoo

Quoted 17 lines

Thanks,
Namhyung
Quoted 12 lines
tools/perf/builtin-sched.c +1 -2
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
 		 (double)work_list->max_lat / 1e6,
-		 (double)work_list->max_lat_at / 1e9);
+		 max_lat_at_sec, max_lat_at_msec);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, hosted by The Linux Foundation

Namhyung Kim

maintainer

2016-10-04 12:04 UTC #4 lore raw

Quoted 81 lines · Joonwoo Park

Quoted 64 lines · Namhyung Kim
Hi Joonwoo,
Quoted 61 lines · Joonwoo Park
Perf sched latency is handy to find out the maximum sched latency and the time stamp of the event. After running sched latency, if a found latency looks suspicious it's quite reasonable to run perf script subsequently and search with the time stamp given by perf sched latency to continue further debugging. However, at present, it's possible the time stamp given by perf sched latency cannot be found in the trace output by perf script because perf sched latency converts the event time from ns to ms as double float and prints it with printf which does banker's rounding as opposed to perf script doesn't.
For example:
   0x750ff0 [0x80]: event: 9
   <snip>
   2 1858303049520 0x750ff0 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 15281/15281: 0xffffffff8162a63a period: 1 addr: 0
    ... thread: hackbench:15281
   <snip>

    $ perf sched -i perf.data latency | grep hackbench
      hackbench:(401)       +   3539.283 ms |    23347 | avg:    7.286 ms | max:  829.998 ms | max at:   1858.303050 s

    $ perf script -i perf.data | grep "1858\.303050"

    $ perf script -i perf.data | grep "1858\.303049"
      hackbench 15281 [002]  1858.303049:       sched:sched_switch: prev_comm=hackbench prev_pid=15281 prev_prio=120 prev_state=D ==> next_comm=hackbench next_pid=15603 next_prio=120
Fix perf latency to print out time stamp without rounding to avoid such discrepancy.
Cc Peter Zijlstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Alexander Shishkin <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc [email protected]
Signed-off-by Joonwoo Park <[email protected]>
---
I was tempted to get rid of all u64 to double casting in the function output_lat_thread but didn't because there is no data loss as of today. Double float gives at least 15 significant decimal digits precision while the function requires only 14 significant digits precision.
$ python -c "print(len(str(int(0xffffffffffffffff / 1e6))))"
14
 tools/lib/traceevent/event-parse.h |  1 +
 tools/perf/builtin-sched.c         | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)
tools/lib/traceevent/event-parse.h +1 -0
index 9ffde37..f42703c 100644
@@ -174,6 +174,7 @@ struct pevent_plugin_option {
 
 #define NSECS_PER_SEC		1000000000ULL
 #define NSECS_PER_USEC		1000ULL
+#define MSECS_PER_SEC		1000ULL
 
Quoted 13 lines
tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1193
Quoted 11 lines
tools/lib/traceevent/event-parse.h +0 -0
 enum format_flags {
 	FIELD_IS_ARRAY		= 1,
tools/perf/builtin-sched.c +1 -0
index afa0576..e5cf51a 100644
@@ -1190,6 +1190,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 	int i;
 	int ret;
 	u64 avg;
+	u64 max_lat_at_sec, max_lat_at_msec;
Isn't it usec rathen than msec? :)

Quoted 4 lines

It's to contain three decimal digits which are msecs when 'max_lat_at' is expressed in sec.
For example when max_lat_at = 1858303049520 which is 1858.3030495199998 sec, max_lat_at_msec is meant to be 303.

??? But didn't you want to print it as 303049?

Looking at the code, the 'max_lat' is a latency which was printed in msec (%9.3f ms) but the 'max_lat_at' is a timestamp which was printed in sec (%13.6f s). This is confusing but they use effectively same unit (usec) by using different number of digit after the period.

Quoted 4 lines

I must admit variable's name is bit misleading. Maybe just secs, msecs are better?
Also just noticed u64 isn't needed for msecs. Will size down.

IIUC you wanted usec for timestamp rather than msec, aren't you?

Quoted 32 lines

Quoted 21 lines

Quoted 8 lines

tools/perf/builtin-sched.c +0 -0

 	if (!work_list->nb_atoms)
 		return;

@@ -1212,11 +1213,18 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 
 	avg = work_list->total_lat / work_list->nb_atoms;

tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1223

Quoted 10 lines

tools/perf/builtin-sched.c +8 -1

 
-	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13.6f s\n",
+	/*
+	 * Avoid round up with printf to prevent event time discrepency
+	 * between sched script and latency.
+	 */
+	max_lat_at_sec = work_list->max_lat_at / NSECS_PER_SEC;
+	max_lat_at_msec = (work_list->max_lat_at -
+			   max_lat_at_sec * NSECS_PER_SEC) / MSECS_PER_SEC;
+	printf("+%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %6lu.%06lu s\n",

Maybe you'd better to be in sync with the script code:

Quoted 10 lines

	if (PRINT_FIELD(TIME)) {
		nsecs = sample->time;
		secs = nsecs / NSECS_PER_SEC;
		nsecs -= secs * NSECS_PER_SEC;
		usecs = nsecs / NSECS_PER_USEC;
		if (nanosecs)
			printf("%5lu.%09llu: ", secs, nsecs);
		else
			printf("%5lu.%06lu: ", secs, usecs);
	}

Quoted 3 lines

Apart from variable name, I'm not quite sure what to sync because sched doesn't print in nsecs.
Maybe you just wanted for variable names in sync rather than logic?

You found inconsistency between the two, and wanted to show same time. So wouldn't it be better factor out the code and reuse it from the both callsite? If you don't need nsec, you could make it an option.

But this is just a general suggestion and maybe it's not worth doing here since the code is small.. So I won't insist on it strongly.

Thanks
Namhyung

Quoted 14 lines

Quoted 14 lines
Quoted 14 lines
tools/perf/builtin-sched.c +1 -2
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
 		 (double)work_list->max_lat / 1e6,
-		 (double)work_list->max_lat_at / 1e9);
+		 max_lat_at_sec, max_lat_at_msec);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, hosted by The Linux Foundation

Joonwoo Park

author

2016-10-04 17:11 UTC #5 lore raw

Quoted 95 lines · Namhyung Kim

Quoted 81 lines · Joonwoo Park
Quoted 64 lines · Namhyung Kim
Hi Joonwoo,
Quoted 61 lines · Joonwoo Park
Perf sched latency is handy to find out the maximum sched latency and the time stamp of the event. After running sched latency, if a found latency looks suspicious it's quite reasonable to run perf script subsequently and search with the time stamp given by perf sched latency to continue further debugging. However, at present, it's possible the time stamp given by perf sched latency cannot be found in the trace output by perf script because perf sched latency converts the event time from ns to ms as double float and prints it with printf which does banker's rounding as opposed to perf script doesn't.
For example:
   0x750ff0 [0x80]: event: 9
   <snip>
   2 1858303049520 0x750ff0 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 15281/15281: 0xffffffff8162a63a period: 1 addr: 0
    ... thread: hackbench:15281
   <snip>

    $ perf sched -i perf.data latency | grep hackbench
      hackbench:(401)       +   3539.283 ms |    23347 | avg:    7.286 ms | max:  829.998 ms | max at:   1858.303050 s

    $ perf script -i perf.data | grep "1858\.303050"

    $ perf script -i perf.data | grep "1858\.303049"
      hackbench 15281 [002]  1858.303049:       sched:sched_switch: prev_comm=hackbench prev_pid=15281 prev_prio=120 prev_state=D ==> next_comm=hackbench next_pid=15603 next_prio=120
Fix perf latency to print out time stamp without rounding to avoid such discrepancy.
Cc Peter Zijlstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Alexander Shishkin <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc [email protected]
Signed-off-by Joonwoo Park <[email protected]>
---
I was tempted to get rid of all u64 to double casting in the function output_lat_thread but didn't because there is no data loss as of today. Double float gives at least 15 significant decimal digits precision while the function requires only 14 significant digits precision.
$ python -c "print(len(str(int(0xffffffffffffffff / 1e6))))"
14
 tools/lib/traceevent/event-parse.h |  1 +
 tools/perf/builtin-sched.c         | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)
tools/lib/traceevent/event-parse.h +1 -0
index 9ffde37..f42703c 100644
@@ -174,6 +174,7 @@ struct pevent_plugin_option {
 
 #define NSECS_PER_SEC		1000000000ULL
 #define NSECS_PER_USEC		1000ULL
+#define MSECS_PER_SEC		1000ULL
 
Quoted 13 lines
tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1193
Quoted 11 lines
tools/lib/traceevent/event-parse.h +0 -0
 enum format_flags {
 	FIELD_IS_ARRAY		= 1,
tools/perf/builtin-sched.c +1 -0
index afa0576..e5cf51a 100644
@@ -1190,6 +1190,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 	int i;
 	int ret;
 	u64 avg;
+	u64 max_lat_at_sec, max_lat_at_msec;
Isn't it usec rathen than msec? :)
Quoted 4 lines
It's to contain three decimal digits which are msecs when 'max_lat_at' is expressed in sec.
For example when max_lat_at = 1858303049520 which is 1858.3030495199998 sec, max_lat_at_msec is meant to be 303.
??? But didn't you want to print it as 303049?
Looking at the code, the 'max_lat' is a latency which was printed in msec (%9.3f ms) but the 'max_lat_at' is a timestamp which was printed in sec (%13.6f s). This is confusing but they use effectively same unit (usec) by using different number of digit after the period.
Quoted 1 line

Quoted 5 lines

Quoted 3 lines
I must admit variable's name is bit misleading. Maybe just secs, msecs are better?
Also just noticed u64 isn't needed for msecs. Will size down.
IIUC you wanted usec for timestamp rather than msec, aren't you?

Ugh. I was a dummy. My bad. Will fix this.

Quoted 37 lines

Quoted 33 lines
Quoted 22 lines
Quoted 9 lines
tools/perf/builtin-sched.c +0 -0
 	if (!work_list->nb_atoms)
 		return;
@@ -1212,11 +1213,18 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 
 	avg = work_list->total_lat / work_list->nb_atoms;
tools/perf/builtin-sched.c static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_ · line 1223
Quoted 10 lines
tools/perf/builtin-sched.c +8 -1
 
-	printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13.6f s\n",
+	/*
+	 * Avoid round up with printf to prevent event time discrepency
+	 * between sched script and latency.
+	 */
+	max_lat_at_sec = work_list->max_lat_at / NSECS_PER_SEC;
+	max_lat_at_msec = (work_list->max_lat_at -
+			   max_lat_at_sec * NSECS_PER_SEC) / MSECS_PER_SEC;
+	printf("+%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %6lu.%06lu s\n",
Maybe you'd better to be in sync with the script code:
Quoted 10 lines
	if (PRINT_FIELD(TIME)) {
		nsecs = sample->time;
		secs = nsecs / NSECS_PER_SEC;
		nsecs -= secs * NSECS_PER_SEC;
		usecs = nsecs / NSECS_PER_USEC;
		if (nanosecs)
			printf("%5lu.%09llu: ", secs, nsecs);
		else
			printf("%5lu.%06lu: ", secs, usecs);
	}
Quoted 3 lines
Apart from variable name, I'm not quite sure what to sync because sched doesn't print in nsecs.
Maybe you just wanted for variable names in sync rather than logic?

Quoted 6 lines

You found inconsistency between the two, and wanted to show same time. So wouldn't it be better factor out the code and reuse it from the both callsite? If you don't need nsec, you could make it an option.
But this is just a general suggestion and maybe it's not worth doing here since the code is small.. So I won't insist on it strongly.

I see what you're suggesting. Will try to factor out the common part in the next revision.

Thanks,
Joonwoo

Quoted 18 lines

Thanks
Namhyung
Quoted 14 lines
Quoted 14 lines
Quoted 14 lines
tools/perf/builtin-sched.c +1 -2
 	      (double)work_list->total_runtime / 1e6,
 		 work_list->nb_atoms, (double)avg / 1e6,
 		 (double)work_list->max_lat / 1e6,
-		 (double)work_list->max_lat_at / 1e9);
+		 max_lat_at_sec, max_lat_at_msec);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, hosted by The Linux Foundation