我仍然无法生成perf_subinterv.data文件,但我可以缩小性能跟踪的文本表示。然后,为了进一步分析,我可以例如生成火焰图。
缩小到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
}