aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorJin Yao <yao.jin@linux.intel.com>2019-03-01 05:13:06 -0500
committerArnaldo Carvalho de Melo <acme@redhat.com>2019-03-01 09:03:53 -0500
commit284c4e18f55e85155fbcbef5f88b6e62d2b1c29c (patch)
treeaf86a865f1ff76a88253afa85c6cf100e8c04f40
parent10c3405f060397e565e4f75c403859f9a074bfa5 (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.c38
-rw-r--r--tools/perf/builtin-script.c39
-rw-r--r--tools/perf/util/time-utils.c51
-rw-r--r--tools/perf/util/time-utils.h6
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
1428error: 1405error:
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
3739out_delete: 3715out_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
15int parse_nsec_time(const char *str, u64 *ptime) 17int 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
401int 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
443error:
444 free(ptime_range);
445 return ret;
446}
447
399int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz) 448int 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);
23bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, 23bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf,
24 int num, u64 timestamp); 24 int num, u64 timestamp);
25 25
26struct perf_session;
27
28int 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
26int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz); 32int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz);
27 33
28int fetch_current_timestamp(char *buf, size_t sz); 34int fetch_current_timestamp(char *buf, size_t sz);