如何将 perf.data 缩小到时间子间隔

Question

我使用 linux perf (perf_events) 生成带有时间戳的 perf.data 文件。

如何生成子时间间隔内所有事件的报告 [i-start, i-end]？

我可以将 perf.data 缩小到仅包含 [i-start, i-end] 中的事件的 perf_subinterv.data 文件吗？

我需要这样做以每 5 分钟左右分析一次短时间间隔（2 秒 - 6 秒）的性能不佳。

Answer 1

大部分perf工具，包括perf report，都支持按时间过滤：

--time::
  Only analyze samples within given time window: <start>,<stop>. Times
  have the format seconds.microseconds. If start is not given (i.e., time
  string is ',x.y') then analysis starts at the beginning of the file. If
  stop time is not given (i.e, time string is 'x.y,') then analysis goes
  to end of file.

更多详情请见man perf-report。

这是自 4.10 版（2017 年 2 月）以来存在的。如果您运行较旧的内核，您可以尝试自己构建perf 的用户空间工具部分。在较新的版本中，可以指定时间百分比和多个时间范围。

Answer 2

我仍然无法生成 perf_subinterv.data，但我可以缩小文本表示形式的 perf 跟踪。然后，为了进一步分析，我可以生成一个火焰图。

命令将时间间隔缩小到 19:29:43，持续时间为 3.47 秒：

perf script -i ./perf_2016-03-23_192924.468036489.data | awk -v perfdata=./perf_2016-03-23_192924.468036489.data -v interval_start=19:29:43 -v duration=3.47 -f perf_script_cut_interval.awk > perf_2016-03-23_192924.468036489_INTERV_19:29:43.txt

火焰图的生成：

stackcollapse-perf.pl perf_2016-03-23_192924.468036489_INTERV_19:29:43.txt | flamegraph.pl > perf_2016-03-23_192924.468036489_INTERV_19:29:43.svg

gawk 脚本：

#
# Consumes output of 'perf script profile.data' and filters events from a given
# time interval
#
# input variables:
#
# perfdata:
#
#      File with profiling data. Name must be perf_<date>_<time>.data, where
#      <time> has the format <hh><mm><secs>, e.g. perf_2016-03-23_140426.002147215.data
#     
# interval_start:
#
#      Start time of the interval with format <hh><mm><secs>, e.g. 19:29:43.890735
#
# duration:
#
#      length of the interval
#

BEGIN {
  print("processing", perfdata) > "/dev/stderr"
  # parse timestamp of perf rec start
  match(perfdata, /.*perf_.*_(..)(..)(.+)\.data/, ts_perf_rec)
  # parse interval start
  match(interval_start, /(..):(..):(.+)/ , ts_interval)
  hh=1
  mm=2
  ss=3
  printf("ts_perf_rec            = %02d:%02d:%05f\n", ts_perf_rec[hh], ts_perf_rec[mm], ts_perf_rec[ss]) > "/dev/stderr"
  printf("ts_interval            = %02d:%02d:%05f\n", ts_interval[hh], ts_interval[mm], ts_interval[ss]) > "/dev/stderr"
  # current line belongs to header
  in_header = 1
  # current line belongs to selected interval
  in_interval = 0

  # first timestamp in perf.data
  first_ts = -1
  FS="[ :]"
}

# find end of header
/^[^#]/ {
  if (in_header) {
    in_header = 0
  }
}

# find timestamps
# example line: java 15950 515784.682786: cycles: 
/^.+ [0-9]+ [0-9]+\.[0-9]+:/ {
  cur_ts = $3 + 0.0
  if (first_ts == -1) {
    # translate ts_interval to profile data timestamps by identifying the first
    # timestamp with ts_perf_rec
    first_ts = cur_ts

    # delta_recstart_intervalstart is the time difference from the first
    # profiling event to the filter interval
    delta_recstart_intervalstart[ss] = ts_interval[ss] - ts_perf_rec[ss]
    if (delta_recstart_intervalstart[ss] < 0) {
      delta_recstart_intervalstart[ss] += 60
      delta_recstart_intervalstart[mm] = -1
    }
    delta_recstart_intervalstart[mm] += ts_interval[mm] - ts_perf_rec[mm]
    if (delta_recstart_intervalstart[mm] < 0) {
      delta_recstart_intervalstart[mm] += 60
      delta_recstart_intervalstart[hh] = -1
    }
    delta_recstart_intervalstart[hh] += ts_interval[hh] - ts_perf_rec[hh]

    # beginning and end of the interval in profiling timestamps
    interval_begin_s = delta_recstart_intervalstart[hh] * 3600 + delta_recstart_intervalstart[mm] * 60 + delta_recstart_intervalstart[ss] + first_ts
    interval_end_s = interval_begin_s + duration

    printf("ts_perf_rec                  = %02d:%02d:%05f\n", ts_perf_rec[hh], ts_perf_rec[mm], ts_perf_rec[ss]) > "/dev/stderr"
    printf("first_ts                     = %f\n", first_ts) > "/dev/stderr"
    printf("ts_interval                  = %02d:%02d:%05f\n", ts_interval[hh], ts_interval[mm], ts_interval[ss]) > "/dev/stderr"
    printf("delta_recstart_intervalstart = %02d:%02d:%05f\n",
           delta_recstart_intervalstart[hh], delta_recstart_intervalstart[mm], delta_recstart_intervalstart[ss]) > "/dev/stderr"
    printf("duration                     = %f\n", duration) > "/dev/stderr"
    printf("interval_begin_s             = %05f\n", interval_begin_s) > "/dev/stderr"
    printf("interval_end_s               = %05f\n", interval_end_s) > "/dev/stderr"
  }

  in_interval = ((cur_ts >= interval_begin_s) && (cur_ts < interval_end_s))
}

# print every line that belongs to the header or the selected time interval
in_interval || in_header {
  print $0
}