diff options
author | Jin Yao <yao.jin@linux.intel.com> | 2019-03-01 05:13:06 -0500 |
---|---|---|
committer | Arnaldo Carvalho de Melo <acme@redhat.com> | 2019-03-01 09:03:53 -0500 |
commit | 284c4e18f55e85155fbcbef5f88b6e62d2b1c29c (patch) | |
tree | af86a865f1ff76a88253afa85c6cf100e8c04f40 | |
parent | 10c3405f060397e565e4f75c403859f9a074bfa5 (diff) |
perf time-utils: Refactor time range parsing code
Jiri points out that we don't need any time checking and time string
parsing if the --time option is not set. That makes sense.
This patch refactors the time range parsing code, move the duplicated
code from perf report and perf script to time_utils and check if --time
option is set before parsing the time string. This patch is no logic
change expected. So the usage of --time is same as before.
For example:
Select the first and second 10% time slices:
perf report --time 10%/1,10%/2
perf script --time 10%/1,10%/2
Select the slices from 0% to 10% and from 30% to 40%:
perf report --time 0%-10%,30%-40%
perf script --time 0%-10%,30%-40%
Select the time slices from timestamp 3971 to 3973
perf report --time 3971,3973
perf script --time 3971,3973
Committer testing:
Using the above examples, check before and after to see if it remains
the same:
$ perf record -F 10000 -- find . -name "*.[ch]" -exec cat {} + > /dev/null
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 1.626 MB perf.data (42392 samples) ]
$
$ perf report --time 10%/1,10%/2 > /tmp/report.before.1
$ perf script --time 10%/1,10%/2 > /tmp/script.before.1
$ perf report --time 0%-10%,30%-40% > /tmp/report.before.2
$ perf script --time 0%-10%,30%-40% > /tmp/script.before.2
$ perf report --time 180457.375844,180457.377717 > /tmp/report.before.3
$ perf script --time 180457.375844,180457.377717 > /tmp/script.before.3
For example, the 3rd test produces this slice:
$ cat /tmp/script.before.3
cat 3147 180457.375844: 2143 cycles:uppp: 7f79362590d9 cfree@GLIBC_2.2.5+0x9 (/usr/lib64/libc-2.28.so)
cat 3147 180457.375986: 2245 cycles:uppp: 558b70f3d86e [unknown] (/usr/bin/cat)
cat 3147 180457.376012: 2164 cycles:uppp: 7f7936257430 _int_malloc+0x8c0 (/usr/lib64/libc-2.28.so)
cat 3147 180457.376140: 2921 cycles:uppp: 558b70f3a554 [unknown] (/usr/bin/cat)
cat 3147 180457.376296: 2844 cycles:uppp: 7f7936258abe malloc+0x4e (/usr/lib64/libc-2.28.so)
cat 3147 180457.376431: 2717 cycles:uppp: 558b70f3b0ca [unknown] (/usr/bin/cat)
cat 3147 180457.376667: 2630 cycles:uppp: 558b70f3d86e [unknown] (/usr/bin/cat)
cat 3147 180457.376795: 2442 cycles:uppp: 7f79362bff55 read+0x15 (/usr/lib64/libc-2.28.so)
cat 3147 180457.376927: 2376 cycles:uppp: ffffffff9aa00163 [unknown] ([unknown])
cat 3147 180457.376954: 2307 cycles:uppp: 7f7936257438 _int_malloc+0x8c8 (/usr/lib64/libc-2.28.so)
cat 3147 180457.377116: 3091 cycles:uppp: 7f7936258a70 malloc+0x0 (/usr/lib64/libc-2.28.so)
cat 3147 180457.377362: 2945 cycles:uppp: 558b70f3a3b0 [unknown] (/usr/bin/cat)
cat 3147 180457.377517: 2727 cycles:uppp: 558b70f3a9aa [unknown] (/usr/bin/cat)
$
Install 'coreutils-debuginfo' to see cat's guts (symbols), but then, the
above chunk translates into this 'perf report' output:
$ cat /tmp/report.before.3
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 13 of event 'cycles:uppp' (time slices: 180457.375844,180457.377717)
# Event count (approx.): 33552
#
# Overhead Command Shared Object Symbol
# ........ ....... ................ ......................
#
17.69% cat libc-2.28.so [.] malloc
14.53% cat cat [.] 0x000000000000586e
13.33% cat libc-2.28.so [.] _int_malloc
8.78% cat cat [.] 0x00000000000023b0
8.71% cat cat [.] 0x0000000000002554
8.13% cat cat [.] 0x00000000000029aa
8.10% cat cat [.] 0x00000000000030ca
7.28% cat libc-2.28.so [.] read
7.08% cat [unknown] [k] 0xffffffff9aa00163
6.39% cat libc-2.28.so [.] cfree@GLIBC_2.2.5
#
# (Tip: Order by the overhead of source file name and line number: perf report -s srcline)
#
$
Now lets see after applying this patch, nothing should change:
$ perf report --time 10%/1,10%/2 > /tmp/report.after.1
$ perf script --time 10%/1,10%/2 > /tmp/script.after.1
$ perf report --time 0%-10%,30%-40% > /tmp/report.after.2
$ perf script --time 0%-10%,30%-40% > /tmp/script.after.2
$ perf report --time 180457.375844,180457.377717 > /tmp/report.after.3
$ perf script --time 180457.375844,180457.377717 > /tmp/script.after.3
$ diff -u /tmp/report.before.1 /tmp/report.after.1
$ diff -u /tmp/script.before.1 /tmp/script.after.1
$ diff -u /tmp/report.before.2 /tmp/report.after.2
--- /tmp/report.before.2 2019-03-01 11:01:53.526094883 -0300
+++ /tmp/report.after.2 2019-03-01 11:09:18.231770467 -0300
@@ -352,5 +352,5 @@
#
-# (Tip: Generate a script for your data: perf script -g <lang>)
+# (Tip: Treat branches as callchains: perf report --branch-history)
#
$ diff -u /tmp/script.before.2 /tmp/script.after.2
$ diff -u /tmp/report.before.3 /tmp/report.after.3
--- /tmp/report.before.3 2019-03-01 11:03:08.890045588 -0300
+++ /tmp/report.after.3 2019-03-01 11:09:40.660224002 -0300
@@ -22,5 +22,5 @@
#
-# (Tip: Order by the overhead of source file name and line number: perf report -s srcline)
+# (Tip: List events using substring match: perf list <keyword>)
#
$ diff -u /tmp/script.before.3 /tmp/script.after.3
$
Cool, just the 'perf report' tips changed, QED.
Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Jin Yao <yao.jin@intel.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Kan Liang <kan.liang@linux.intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1551435186-6008-1-git-send-email-yao.jin@linux.intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
-rw-r--r-- | tools/perf/builtin-report.c | 38 | ||||
-rw-r--r-- | tools/perf/builtin-script.c | 39 | ||||
-rw-r--r-- | tools/perf/util/time-utils.c | 51 | ||||
-rw-r--r-- | tools/perf/util/time-utils.h | 6 |
4 files changed, 72 insertions, 62 deletions
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c index 1532ebde6c4b..ee93c18a6685 100644 --- a/tools/perf/builtin-report.c +++ b/tools/perf/builtin-report.c | |||
@@ -1375,36 +1375,13 @@ repeat: | |||
1375 | if (symbol__init(&session->header.env) < 0) | 1375 | if (symbol__init(&session->header.env) < 0) |
1376 | goto error; | 1376 | goto error; |
1377 | 1377 | ||
1378 | report.ptime_range = perf_time__range_alloc(report.time_str, | 1378 | if (report.time_str) { |
1379 | &report.range_size); | 1379 | ret = perf_time__parse_for_ranges(report.time_str, session, |
1380 | if (!report.ptime_range) { | 1380 | &report.ptime_range, |
1381 | ret = -ENOMEM; | 1381 | &report.range_size, |
1382 | goto error; | 1382 | &report.range_num); |
1383 | } | 1383 | if (ret < 0) |
1384 | |||
1385 | if (perf_time__parse_str(report.ptime_range, report.time_str) != 0) { | ||
1386 | if (session->evlist->first_sample_time == 0 && | ||
1387 | session->evlist->last_sample_time == 0) { | ||
1388 | pr_err("HINT: no first/last sample time found in perf data.\n" | ||
1389 | "Please use latest perf binary to execute 'perf record'\n" | ||
1390 | "(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n"); | ||
1391 | ret = -EINVAL; | ||
1392 | goto error; | ||
1393 | } | ||
1394 | |||
1395 | report.range_num = perf_time__percent_parse_str( | ||
1396 | report.ptime_range, report.range_size, | ||
1397 | report.time_str, | ||
1398 | session->evlist->first_sample_time, | ||
1399 | session->evlist->last_sample_time); | ||
1400 | |||
1401 | if (report.range_num < 0) { | ||
1402 | pr_err("Invalid time string\n"); | ||
1403 | ret = -EINVAL; | ||
1404 | goto error; | 1384 | goto error; |
1405 | } | ||
1406 | } else { | ||
1407 | report.range_num = 1; | ||
1408 | } | 1385 | } |
1409 | 1386 | ||
1410 | if (session->tevent.pevent && | 1387 | if (session->tevent.pevent && |
@@ -1426,7 +1403,8 @@ repeat: | |||
1426 | ret = 0; | 1403 | ret = 0; |
1427 | 1404 | ||
1428 | error: | 1405 | error: |
1429 | zfree(&report.ptime_range); | 1406 | if (report.ptime_range) |
1407 | zfree(&report.ptime_range); | ||
1430 | 1408 | ||
1431 | perf_session__delete(session); | 1409 | perf_session__delete(session); |
1432 | return ret; | 1410 | return ret; |
diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c index 2d8cb1d1682c..53f78cf3113f 100644 --- a/tools/perf/builtin-script.c +++ b/tools/perf/builtin-script.c | |||
@@ -3699,37 +3699,13 @@ int cmd_script(int argc, const char **argv) | |||
3699 | if (err < 0) | 3699 | if (err < 0) |
3700 | goto out_delete; | 3700 | goto out_delete; |
3701 | 3701 | ||
3702 | script.ptime_range = perf_time__range_alloc(script.time_str, | 3702 | if (script.time_str) { |
3703 | &script.range_size); | 3703 | err = perf_time__parse_for_ranges(script.time_str, session, |
3704 | if (!script.ptime_range) { | 3704 | &script.ptime_range, |
3705 | err = -ENOMEM; | 3705 | &script.range_size, |
3706 | goto out_delete; | 3706 | &script.range_num); |
3707 | } | 3707 | if (err < 0) |
3708 | |||
3709 | /* needs to be parsed after looking up reference time */ | ||
3710 | if (perf_time__parse_str(script.ptime_range, script.time_str) != 0) { | ||
3711 | if (session->evlist->first_sample_time == 0 && | ||
3712 | session->evlist->last_sample_time == 0) { | ||
3713 | pr_err("HINT: no first/last sample time found in perf data.\n" | ||
3714 | "Please use latest perf binary to execute 'perf record'\n" | ||
3715 | "(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n"); | ||
3716 | err = -EINVAL; | ||
3717 | goto out_delete; | ||
3718 | } | ||
3719 | |||
3720 | script.range_num = perf_time__percent_parse_str( | ||
3721 | script.ptime_range, script.range_size, | ||
3722 | script.time_str, | ||
3723 | session->evlist->first_sample_time, | ||
3724 | session->evlist->last_sample_time); | ||
3725 | |||
3726 | if (script.range_num < 0) { | ||
3727 | pr_err("Invalid time string\n"); | ||
3728 | err = -EINVAL; | ||
3729 | goto out_delete; | 3708 | goto out_delete; |
3730 | } | ||
3731 | } else { | ||
3732 | script.range_num = 1; | ||
3733 | } | 3709 | } |
3734 | 3710 | ||
3735 | err = __cmd_script(&script); | 3711 | err = __cmd_script(&script); |
@@ -3737,7 +3713,8 @@ int cmd_script(int argc, const char **argv) | |||
3737 | flush_scripting(); | 3713 | flush_scripting(); |
3738 | 3714 | ||
3739 | out_delete: | 3715 | out_delete: |
3740 | zfree(&script.ptime_range); | 3716 | if (script.ptime_range) |
3717 | zfree(&script.ptime_range); | ||
3741 | 3718 | ||
3742 | perf_evlist__free_stats(session->evlist); | 3719 | perf_evlist__free_stats(session->evlist); |
3743 | perf_session__delete(session); | 3720 | perf_session__delete(session); |
diff --git a/tools/perf/util/time-utils.c b/tools/perf/util/time-utils.c index 6193b46050a5..0f53baec660e 100644 --- a/tools/perf/util/time-utils.c +++ b/tools/perf/util/time-utils.c | |||
@@ -11,6 +11,8 @@ | |||
11 | #include "perf.h" | 11 | #include "perf.h" |
12 | #include "debug.h" | 12 | #include "debug.h" |
13 | #include "time-utils.h" | 13 | #include "time-utils.h" |
14 | #include "session.h" | ||
15 | #include "evlist.h" | ||
14 | 16 | ||
15 | int parse_nsec_time(const char *str, u64 *ptime) | 17 | int parse_nsec_time(const char *str, u64 *ptime) |
16 | { | 18 | { |
@@ -374,7 +376,7 @@ bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, | |||
374 | struct perf_time_interval *ptime; | 376 | struct perf_time_interval *ptime; |
375 | int i; | 377 | int i; |
376 | 378 | ||
377 | if ((timestamp == 0) || (num == 0)) | 379 | if ((!ptime_buf) || (timestamp == 0) || (num == 0)) |
378 | return false; | 380 | return false; |
379 | 381 | ||
380 | if (num == 1) | 382 | if (num == 1) |
@@ -396,6 +398,53 @@ bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, | |||
396 | return (i == num) ? true : false; | 398 | return (i == num) ? true : false; |
397 | } | 399 | } |
398 | 400 | ||
401 | int perf_time__parse_for_ranges(const char *time_str, | ||
402 | struct perf_session *session, | ||
403 | struct perf_time_interval **ranges, | ||
404 | int *range_size, int *range_num) | ||
405 | { | ||
406 | struct perf_time_interval *ptime_range; | ||
407 | int size, num, ret; | ||
408 | |||
409 | ptime_range = perf_time__range_alloc(time_str, &size); | ||
410 | if (!ptime_range) | ||
411 | return -ENOMEM; | ||
412 | |||
413 | if (perf_time__parse_str(ptime_range, time_str) != 0) { | ||
414 | if (session->evlist->first_sample_time == 0 && | ||
415 | session->evlist->last_sample_time == 0) { | ||
416 | pr_err("HINT: no first/last sample time found in perf data.\n" | ||
417 | "Please use latest perf binary to execute 'perf record'\n" | ||
418 | "(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n"); | ||
419 | ret = -EINVAL; | ||
420 | goto error; | ||
421 | } | ||
422 | |||
423 | num = perf_time__percent_parse_str( | ||
424 | ptime_range, size, | ||
425 | time_str, | ||
426 | session->evlist->first_sample_time, | ||
427 | session->evlist->last_sample_time); | ||
428 | |||
429 | if (num < 0) { | ||
430 | pr_err("Invalid time string\n"); | ||
431 | ret = -EINVAL; | ||
432 | goto error; | ||
433 | } | ||
434 | } else { | ||
435 | num = 1; | ||
436 | } | ||
437 | |||
438 | *range_size = size; | ||
439 | *range_num = num; | ||
440 | *ranges = ptime_range; | ||
441 | return 0; | ||
442 | |||
443 | error: | ||
444 | free(ptime_range); | ||
445 | return ret; | ||
446 | } | ||
447 | |||
399 | int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz) | 448 | int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz) |
400 | { | 449 | { |
401 | u64 sec = timestamp / NSEC_PER_SEC; | 450 | u64 sec = timestamp / NSEC_PER_SEC; |
diff --git a/tools/perf/util/time-utils.h b/tools/perf/util/time-utils.h index 70b177d2b98c..b923de44e36f 100644 --- a/tools/perf/util/time-utils.h +++ b/tools/perf/util/time-utils.h | |||
@@ -23,6 +23,12 @@ bool perf_time__skip_sample(struct perf_time_interval *ptime, u64 timestamp); | |||
23 | bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, | 23 | bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, |
24 | int num, u64 timestamp); | 24 | int num, u64 timestamp); |
25 | 25 | ||
26 | struct perf_session; | ||
27 | |||
28 | int perf_time__parse_for_ranges(const char *str, struct perf_session *session, | ||
29 | struct perf_time_interval **ranges, | ||
30 | int *range_size, int *range_num); | ||
31 | |||
26 | int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz); | 32 | int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz); |
27 | 33 | ||
28 | int fetch_current_timestamp(char *buf, size_t sz); | 34 | int fetch_current_timestamp(char *buf, size_t sz); |