perf report: Use timestamp__scnprintf_nsec for time sort key

PATCH Applied Andi Kleen 3 participants 5 messages Aug 23, 2019 – Aug 27, 2019 perf events

lore

Share & tools

lore

Andi Kleen

author

2019-08-23 21:03 UTC #0 lore raw

PATCH 1/2 perf report: Use timestamp__scnprintf_nsec for time sort key

From: Andi Kleen <[email protected]>

Use timestamp__scnprintf_nsec to print nanoseconds for the time sort key, instead of open coding.

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/sort.c | 10 ++--------
 1 file changed, 2 insertions(+), 8 deletions(-)

tools/perf/util/sort.c +2 -8

index f9a38a1dd4d1..0985e9072db0 100644
@@ -668,17 +668,11 @@ sort__time_cmp(struct hist_entry *left, struct hist_entry *right)
 static int hist_entry__time_snprintf(struct hist_entry *he, char *bf,
 				    size_t size, unsigned int width)
 {
-	unsigned long secs;
-	unsigned long long nsecs;
 	char he_time[32];
 
-	nsecs = he->time;
-	secs = nsecs / NSEC_PER_SEC;
-	nsecs -= secs * NSEC_PER_SEC;
-
 	if (symbol_conf.nanosecs)
-		snprintf(he_time, sizeof he_time, "%5lu.%09llu: ",
-			 secs, nsecs);
+		timestamp__scnprintf_nsec(he->time, he_time,
+					  sizeof(he_time));
 	else
 		timestamp__scnprintf_usec(he->time, he_time,
 					  sizeof(he_time));

Signature · 1 line

2.20.1

Andi Kleen

author

2019-08-23 21:03 UTC #1 lore raw

PATCH 2/2 perf report: Fix --ns time sort key output

From: Andi Kleen <[email protected]>

If the user specified --ns, the column to print the sort time stamp wasn't wide enough to actually print the full nanoseconds.

Widen the time key column width when --ns is specified.

Before:

% perf record -a sleep 1
% perf report --sort time,overhead,symbol --stdio --ns
...

     2.39%  187851.10000  [k] smp_call_function_single                                                                                -      -
     1.53%  187851.10000  [k] intel_idle                                                                                              -      -
     0.59%  187851.10000  [.] __wcscmp_ifunc                                                                                          -      -
     0.33%  187851.10000  [.] 0000000000000000                                                                                        -      -
     0.28%  187851.10000  [k] cpuidle_enter_state                                                                                     -      -

After:

% perf report --sort time,overhead,symbol --stdio --ns
...

     2.39%  187851.100000000  [k] smp_call_function_single                                                                                -      -
     1.53%  187851.100000000  [k] intel_idle                                                                                              -      -
     0.59%  187851.100000000  [.] __wcscmp_ifunc                                                                                          -      -
     0.33%  187851.100000000  [.] 0000000000000000                                                                                        -      -
     0.28%  187851.100000000  [k] cpuidle_enter_state                                                                                     -      -

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/hist.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

tools/perf/util/hist.c +4 -1

index 8efbf58dc3d0..33702675073c 100644
@@ -193,7 +193,10 @@ void hists__calc_col_len(struct hists *hists, struct hist_entry *h)
 	hists__new_col_len(hists, HISTC_MEM_LVL, 21 + 3);
 	hists__new_col_len(hists, HISTC_LOCAL_WEIGHT, 12);
 	hists__new_col_len(hists, HISTC_GLOBAL_WEIGHT, 12);
-	hists__new_col_len(hists, HISTC_TIME, 12);
+	if (symbol_conf.nanosecs)
+		hists__new_col_len(hists, HISTC_TIME, 16);
+	else
+		hists__new_col_len(hists, HISTC_TIME, 12);
 
 	if (h->srcline) {
 		len = MAX(strlen(h->srcline), strlen(sort_srcline.se_header));

Signature · 1 line

2.20.1

tip-bot2 for Andi Kleen

merge bot Applied

2019-08-27 08:26 UTC #2 lore raw

[tip: perf/core] perf report: Fix --ns time sort key output

The following commit has been merged into the perf/core branch of tip:

Commit-ID:     3dab6ac080dcd7f71cb9ceb84ad7dafecd6f7c07
Gitweb:        https://git.kernel.org/tip/3dab6ac080dcd7f71cb9ceb84ad7dafecd6f7c07
Author:        Andi Kleen <[email protected]>
AuthorDate:    Fri, 23 Aug 2019 14:03:38 -07:00
Committer:     Arnaldo Carvalho de Melo <[email protected]>
CommitterDate: Mon, 26 Aug 2019 11:58:29 -03:00

perf report: Fix --ns time sort key output

If the user specified --ns, the column to print the sort time stamp wasn't wide enough to actually print the full nanoseconds.

Widen the time key column width when --ns is specified.

Before:

  % perf record -a sleep 1
  % perf report --sort time,overhead,symbol --stdio --ns
  ...
       2.39%  187851.10000  [k] smp_call_function_single   -      -
       1.53%  187851.10000  [k] intel_idle                 -      -
       0.59%  187851.10000  [.] __wcscmp_ifunc             -      -
       0.33%  187851.10000  [.] 0000000000000000           -      -
       0.28%  187851.10000  [k] cpuidle_enter_state        -      -

After:

  % perf report --sort time,overhead,symbol --stdio --ns
  ...
       2.39%  187851.100000000  [k] smp_call_function_single   -      -
       1.53%  187851.100000000  [k] intel_idle                 -      -
       0.59%  187851.100000000  [.] __wcscmp_ifunc             -      -
       0.33%  187851.100000000  [.] 0000000000000000           -      -
       0.28%  187851.100000000  [k] cpuidle_enter_state        -      -

Signed-off-by Andi Kleen <[email protected]>

Tested-by Arnaldo Carvalho de Melo <[email protected]>

Cc Jiri Olsa <[email protected]>

Link http://lkml.kernel.org/r/[email protected] open here

Signed-off-by Arnaldo Carvalho de Melo <[email protected]>

---
 tools/perf/util/hist.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

tools/perf/util/hist.c +4 -1

index 8efbf58..3370267 100644
@@ -193,7 +193,10 @@ void hists__calc_col_len(struct hists *hists, struct hist_entry *h)
 	hists__new_col_len(hists, HISTC_MEM_LVL, 21 + 3);
 	hists__new_col_len(hists, HISTC_LOCAL_WEIGHT, 12);
 	hists__new_col_len(hists, HISTC_GLOBAL_WEIGHT, 12);
-	hists__new_col_len(hists, HISTC_TIME, 12);
+	if (symbol_conf.nanosecs)
+		hists__new_col_len(hists, HISTC_TIME, 16);
+	else
+		hists__new_col_len(hists, HISTC_TIME, 12);
 
 	if (h->srcline) {
 		len = MAX(strlen(h->srcline), strlen(sort_srcline.se_header));

Arnaldo Carvalho de Melo

2019-08-25 14:31 UTC #3 lore raw

In reply to Andi Kleen

Em Fri, Aug 23, 2019 at 02:03:37PM -0700, Andi Kleen escreveu:

Quoted 4 lines

From: Andi Kleen <[email protected]>
Use timestamp__scnprintf_nsec to print nanoseconds for the time sort key, instead of open coding.

Thanks, tested and applied.

- Arnaldo

Quoted 31 lines

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/sort.c | 10 ++--------
 1 file changed, 2 insertions(+), 8 deletions(-)

tools/perf/util/sort.c +2 -8

index f9a38a1dd4d1..0985e9072db0 100644
@@ -668,17 +668,11 @@ sort__time_cmp(struct hist_entry *left, struct hist_entry *right)
 static int hist_entry__time_snprintf(struct hist_entry *he, char *bf,
 				    size_t size, unsigned int width)
 {
-	unsigned long secs;
-	unsigned long long nsecs;
 	char he_time[32];
 
-	nsecs = he->time;
-	secs = nsecs / NSEC_PER_SEC;
-	nsecs -= secs * NSEC_PER_SEC;
-
 	if (symbol_conf.nanosecs)
-		snprintf(he_time, sizeof he_time, "%5lu.%09llu: ",
-			 secs, nsecs);
+		timestamp__scnprintf_nsec(he->time, he_time,
+					  sizeof(he_time));
 	else
 		timestamp__scnprintf_usec(he->time, he_time,
 					  sizeof(he_time));

Signature · 1 line

2.20.1

Signature · 1 line

- Arnaldo

tip-bot2 for Andi Kleen

merge bot Applied

2019-08-27 08:28 UTC #4 lore raw

[tip: perf/core] perf report: Use timestamp__scnprintf_nsec() for time sort key

In reply to Andi Kleen

The following commit has been merged into the perf/core branch of tip:

Commit-ID:     092804ae092fc6097348f5c09b62cde040717aa1
Gitweb:        https://git.kernel.org/tip/092804ae092fc6097348f5c09b62cde040717aa1
Author:        Andi Kleen <[email protected]>
AuthorDate:    Fri, 23 Aug 2019 14:03:37 -07:00
Committer:     Arnaldo Carvalho de Melo <[email protected]>
CommitterDate: Mon, 26 Aug 2019 11:58:29 -03:00

perf report: Use timestamp__scnprintf_nsec() for time sort key

Use timestamp__scnprintf_nsec() to print nanoseconds for the time sort key, instead of open coding.

Signed-off-by Andi Kleen <[email protected]>

Cc Jiri Olsa <[email protected]>

Link http://lkml.kernel.org/r/[email protected] open here

Signed-off-by Arnaldo Carvalho de Melo <[email protected]>

---
 tools/perf/util/sort.c | 10 ++--------
 1 file changed, 2 insertions(+), 8 deletions(-)

tools/perf/util/sort.c +2 -8

index c522bdd..83eb3fa 100644
@@ -670,17 +670,11 @@ sort__time_cmp(struct hist_entry *left, struct hist_entry *right)
 static int hist_entry__time_snprintf(struct hist_entry *he, char *bf,
 				    size_t size, unsigned int width)
 {
-	unsigned long secs;
-	unsigned long long nsecs;
 	char he_time[32];
 
-	nsecs = he->time;
-	secs = nsecs / NSEC_PER_SEC;
-	nsecs -= secs * NSEC_PER_SEC;
-
 	if (symbol_conf.nanosecs)
-		snprintf(he_time, sizeof he_time, "%5lu.%09llu: ",
-			 secs, nsecs);
+		timestamp__scnprintf_nsec(he->time, he_time,
+					  sizeof(he_time));
 	else
 		timestamp__scnprintf_usec(he->time, he_time,
 					  sizeof(he_time));