linux/tools/perf/util/time-utils.c
Jin Yao 284c4e18f5 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>
2019-03-01 11:03:53 -03:00

472 lines
9.0 KiB
C

// SPDX-License-Identifier: GPL-2.0
#include <stdlib.h>
#include <string.h>
#include <sys/time.h>
#include <linux/time64.h>
#include <time.h>
#include <errno.h>
#include <inttypes.h>
#include <math.h>
#include "perf.h"
#include "debug.h"
#include "time-utils.h"
#include "session.h"
#include "evlist.h"
int parse_nsec_time(const char *str, u64 *ptime)
{
u64 time_sec, time_nsec;
char *end;
time_sec = strtoul(str, &end, 10);
if (*end != '.' && *end != '\0')
return -1;
if (*end == '.') {
int i;
char nsec_buf[10];
if (strlen(++end) > 9)
return -1;
strncpy(nsec_buf, end, 9);
nsec_buf[9] = '\0';
/* make it nsec precision */
for (i = strlen(nsec_buf); i < 9; i++)
nsec_buf[i] = '0';
time_nsec = strtoul(nsec_buf, &end, 10);
if (*end != '\0')
return -1;
} else
time_nsec = 0;
*ptime = time_sec * NSEC_PER_SEC + time_nsec;
return 0;
}
static int parse_timestr_sec_nsec(struct perf_time_interval *ptime,
char *start_str, char *end_str)
{
if (start_str && (*start_str != '\0') &&
(parse_nsec_time(start_str, &ptime->start) != 0)) {
return -1;
}
if (end_str && (*end_str != '\0') &&
(parse_nsec_time(end_str, &ptime->end) != 0)) {
return -1;
}
return 0;
}
static int split_start_end(char **start, char **end, const char *ostr, char ch)
{
char *start_str, *end_str;
char *d, *str;
if (ostr == NULL || *ostr == '\0')
return 0;
/* copy original string because we need to modify it */
str = strdup(ostr);
if (str == NULL)
return -ENOMEM;
start_str = str;
d = strchr(start_str, ch);
if (d) {
*d = '\0';
++d;
}
end_str = d;
*start = start_str;
*end = end_str;
return 0;
}
int perf_time__parse_str(struct perf_time_interval *ptime, const char *ostr)
{
char *start_str = NULL, *end_str;
int rc;
rc = split_start_end(&start_str, &end_str, ostr, ',');
if (rc || !start_str)
return rc;
ptime->start = 0;
ptime->end = 0;
rc = parse_timestr_sec_nsec(ptime, start_str, end_str);
free(start_str);
/* make sure end time is after start time if it was given */
if (rc == 0 && ptime->end && ptime->end < ptime->start)
return -EINVAL;
pr_debug("start time %" PRIu64 ", ", ptime->start);
pr_debug("end time %" PRIu64 "\n", ptime->end);
return rc;
}
static int parse_percent(double *pcnt, char *str)
{
char *c, *endptr;
double d;
c = strchr(str, '%');
if (c)
*c = '\0';
else
return -1;
d = strtod(str, &endptr);
if (endptr != str + strlen(str))
return -1;
*pcnt = d / 100.0;
return 0;
}
static int percent_slash_split(char *str, struct perf_time_interval *ptime,
u64 start, u64 end)
{
char *p, *end_str;
double pcnt, start_pcnt, end_pcnt;
u64 total = end - start;
int i;
/*
* Example:
* 10%/2: select the second 10% slice and the third 10% slice
*/
/* We can modify this string since the original one is copied */
p = strchr(str, '/');
if (!p)
return -1;
*p = '\0';
if (parse_percent(&pcnt, str) < 0)
return -1;
p++;
i = (int)strtol(p, &end_str, 10);
if (*end_str)
return -1;
if (pcnt <= 0.0)
return -1;
start_pcnt = pcnt * (i - 1);
end_pcnt = pcnt * i;
if (start_pcnt < 0.0 || start_pcnt > 1.0 ||
end_pcnt < 0.0 || end_pcnt > 1.0) {
return -1;
}
ptime->start = start + round(start_pcnt * total);
ptime->end = start + round(end_pcnt * total);
return 0;
}
static int percent_dash_split(char *str, struct perf_time_interval *ptime,
u64 start, u64 end)
{
char *start_str = NULL, *end_str;
double start_pcnt, end_pcnt;
u64 total = end - start;
int ret;
/*
* Example: 0%-10%
*/
ret = split_start_end(&start_str, &end_str, str, '-');
if (ret || !start_str)
return ret;
if ((parse_percent(&start_pcnt, start_str) != 0) ||
(parse_percent(&end_pcnt, end_str) != 0)) {
free(start_str);
return -1;
}
free(start_str);
if (start_pcnt < 0.0 || start_pcnt > 1.0 ||
end_pcnt < 0.0 || end_pcnt > 1.0 ||
start_pcnt > end_pcnt) {
return -1;
}
ptime->start = start + round(start_pcnt * total);
ptime->end = start + round(end_pcnt * total);
return 0;
}
typedef int (*time_pecent_split)(char *, struct perf_time_interval *,
u64 start, u64 end);
static int percent_comma_split(struct perf_time_interval *ptime_buf, int num,
const char *ostr, u64 start, u64 end,
time_pecent_split func)
{
char *str, *p1, *p2;
int len, ret, i = 0;
str = strdup(ostr);
if (str == NULL)
return -ENOMEM;
len = strlen(str);
p1 = str;
while (p1 < str + len) {
if (i >= num) {
free(str);
return -1;
}
p2 = strchr(p1, ',');
if (p2)
*p2 = '\0';
ret = (func)(p1, &ptime_buf[i], start, end);
if (ret < 0) {
free(str);
return -1;
}
pr_debug("start time %d: %" PRIu64 ", ", i, ptime_buf[i].start);
pr_debug("end time %d: %" PRIu64 "\n", i, ptime_buf[i].end);
i++;
if (p2)
p1 = p2 + 1;
else
break;
}
free(str);
return i;
}
static int one_percent_convert(struct perf_time_interval *ptime_buf,
const char *ostr, u64 start, u64 end, char *c)
{
char *str;
int len = strlen(ostr), ret;
/*
* c points to '%'.
* '%' should be the last character
*/
if (ostr + len - 1 != c)
return -1;
/*
* Construct a string like "xx%/1"
*/
str = malloc(len + 3);
if (str == NULL)
return -ENOMEM;
memcpy(str, ostr, len);
strcpy(str + len, "/1");
ret = percent_slash_split(str, ptime_buf, start, end);
if (ret == 0)
ret = 1;
free(str);
return ret;
}
int perf_time__percent_parse_str(struct perf_time_interval *ptime_buf, int num,
const char *ostr, u64 start, u64 end)
{
char *c;
/*
* ostr example:
* 10%/2,10%/3: select the second 10% slice and the third 10% slice
* 0%-10%,30%-40%: multiple time range
* 50%: just one percent
*/
memset(ptime_buf, 0, sizeof(*ptime_buf) * num);
c = strchr(ostr, '/');
if (c) {
return percent_comma_split(ptime_buf, num, ostr, start,
end, percent_slash_split);
}
c = strchr(ostr, '-');
if (c) {
return percent_comma_split(ptime_buf, num, ostr, start,
end, percent_dash_split);
}
c = strchr(ostr, '%');
if (c)
return one_percent_convert(ptime_buf, ostr, start, end, c);
return -1;
}
struct perf_time_interval *perf_time__range_alloc(const char *ostr, int *size)
{
const char *p1, *p2;
int i = 1;
struct perf_time_interval *ptime;
/*
* At least allocate one time range.
*/
if (!ostr)
goto alloc;
p1 = ostr;
while (p1 < ostr + strlen(ostr)) {
p2 = strchr(p1, ',');
if (!p2)
break;
p1 = p2 + 1;
i++;
}
alloc:
*size = i;
ptime = calloc(i, sizeof(*ptime));
return ptime;
}
bool perf_time__skip_sample(struct perf_time_interval *ptime, u64 timestamp)
{
/* if time is not set don't drop sample */
if (timestamp == 0)
return false;
/* otherwise compare sample time to time window */
if ((ptime->start && timestamp < ptime->start) ||
(ptime->end && timestamp > ptime->end)) {
return true;
}
return false;
}
bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf,
int num, u64 timestamp)
{
struct perf_time_interval *ptime;
int i;
if ((!ptime_buf) || (timestamp == 0) || (num == 0))
return false;
if (num == 1)
return perf_time__skip_sample(&ptime_buf[0], timestamp);
/*
* start/end of multiple time ranges must be valid.
*/
for (i = 0; i < num; i++) {
ptime = &ptime_buf[i];
if (timestamp >= ptime->start &&
((timestamp < ptime->end && i < num - 1) ||
(timestamp <= ptime->end && i == num - 1))) {
break;
}
}
return (i == num) ? true : false;
}
int perf_time__parse_for_ranges(const char *time_str,
struct perf_session *session,
struct perf_time_interval **ranges,
int *range_size, int *range_num)
{
struct perf_time_interval *ptime_range;
int size, num, ret;
ptime_range = perf_time__range_alloc(time_str, &size);
if (!ptime_range)
return -ENOMEM;
if (perf_time__parse_str(ptime_range, time_str) != 0) {
if (session->evlist->first_sample_time == 0 &&
session->evlist->last_sample_time == 0) {
pr_err("HINT: no first/last sample time found in perf data.\n"
"Please use latest perf binary to execute 'perf record'\n"
"(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n");
ret = -EINVAL;
goto error;
}
num = perf_time__percent_parse_str(
ptime_range, size,
time_str,
session->evlist->first_sample_time,
session->evlist->last_sample_time);
if (num < 0) {
pr_err("Invalid time string\n");
ret = -EINVAL;
goto error;
}
} else {
num = 1;
}
*range_size = size;
*range_num = num;
*ranges = ptime_range;
return 0;
error:
free(ptime_range);
return ret;
}
int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz)
{
u64 sec = timestamp / NSEC_PER_SEC;
u64 usec = (timestamp % NSEC_PER_SEC) / NSEC_PER_USEC;
return scnprintf(buf, sz, "%"PRIu64".%06"PRIu64, sec, usec);
}
int fetch_current_timestamp(char *buf, size_t sz)
{
struct timeval tv;
struct tm tm;
char dt[32];
if (gettimeofday(&tv, NULL) || !localtime_r(&tv.tv_sec, &tm))
return -1;
if (!strftime(dt, sizeof(dt), "%Y%m%d%H%M%S", &tm))
return -1;
scnprintf(buf, sz, "%s%02u", dt, (unsigned)tv.tv_usec / 10000);
return 0;
}