I use linux perf (perf_events) to produce a perf.data file with timestamps.
How can I generate a report of all the events in a sub interval of time [i-start, i-end]?
Can I maybe narrow down perf.data to a perf_subinterv.data file with only events in [i-start, i-end]?
I need to do this to analyze short intervals (2s - 6s) of poor performance every 5mins or so.
perf_events is an event-oriented observability tool, which can help you solve advanced performance and troubleshooting functions.
Perf is a facility comprised of kernel infrastructure for gathering various events and userspace tool to get gathered data from the kernel and analyze it. It is like a gprof, but it is non-invasive, low-overhead and profile the whole stack, including your app, libraries, system calls AND kernel with CPU!
Most perf
tools, including perf report
, support filtering by time:
--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.
For more details see man perf-report
.
This is present since version 4.10 (Feb 2017). If you run an older kernel you can try to build the userspace tools part of perf
yourself. In more recent versions it is possible to specify time percent and multiple time ranges.
I still cannot produce a perf_subinterv.data, but I can narrow down the perf trace in textual representation. Then, for further analysis, I can for instance generate a flame graph.
Command to narrow to time interval at 19:29:43 with 3.47s duration:
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
Generation of flame graph:
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 script:
#
# 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
}
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With