| 1 | |
| 2 | |
| 3 | |
| 4 | |
| 5 | |
| 6 | |
| 7 | |
| 8 | |
| 9 | |
| 10 | |
| 11 | |
| 12 | |
| 13 |
|
| 14 | from __future__ import division, print_function
|
| 15 |
|
| 16 | import io
|
| 17 | import os
|
| 18 | import sys
|
| 19 | import struct
|
| 20 | import argparse
|
| 21 | import contextlib
|
| 22 |
|
| 23 | from libxed import LibXED
|
| 24 | from ctypes import create_string_buffer, addressof
|
| 25 |
|
| 26 | sys.path.append(os.environ['PERF_EXEC_PATH'] + \
|
| 27 | '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
|
| 28 |
|
| 29 | from perf_trace_context import perf_set_itrace_options, \
|
| 30 | perf_sample_insn, perf_sample_srccode
|
| 31 |
|
| 32 | try:
|
| 33 | broken_pipe_exception = BrokenPipeError
|
| 34 | except:
|
| 35 | broken_pipe_exception = IOError
|
| 36 |
|
| 37 | glb_switch_str = {}
|
| 38 | glb_insn = False
|
| 39 | glb_disassembler = None
|
| 40 | glb_src = False
|
| 41 | glb_source_file_name = None
|
| 42 | glb_line_number = None
|
| 43 | glb_dso = None
|
| 44 | glb_stash_dict = {}
|
| 45 | glb_output = None
|
| 46 | glb_output_pos = 0
|
| 47 | glb_cpu = -1
|
| 48 | glb_time = 0
|
| 49 |
|
| 50 | def get_optional_null(perf_dict, field):
|
| 51 | if field in perf_dict:
|
| 52 | return perf_dict[field]
|
| 53 | return ""
|
| 54 |
|
| 55 | def get_optional_zero(perf_dict, field):
|
| 56 | if field in perf_dict:
|
| 57 | return perf_dict[field]
|
| 58 | return 0
|
| 59 |
|
| 60 | def get_optional_bytes(perf_dict, field):
|
| 61 | if field in perf_dict:
|
| 62 | return perf_dict[field]
|
| 63 | return bytes()
|
| 64 |
|
| 65 | def get_optional(perf_dict, field):
|
| 66 | if field in perf_dict:
|
| 67 | return perf_dict[field]
|
| 68 | return "[unknown]"
|
| 69 |
|
| 70 | def get_offset(perf_dict, field):
|
| 71 | if field in perf_dict:
|
| 72 | return "+%#x" % perf_dict[field]
|
| 73 | return ""
|
| 74 |
|
| 75 | def trace_begin():
|
| 76 | ap = argparse.ArgumentParser(usage = "", add_help = False)
|
| 77 | ap.add_argument("--insn-trace", action='store_true')
|
| 78 | ap.add_argument("--src-trace", action='store_true')
|
| 79 | ap.add_argument("--all-switch-events", action='store_true')
|
| 80 | ap.add_argument("--interleave", type=int, nargs='?', const=4, default=0)
|
| 81 | global glb_args
|
| 82 | global glb_insn
|
| 83 | global glb_src
|
| 84 | glb_args = ap.parse_args()
|
| 85 | if glb_args.insn_trace:
|
| 86 | print("Intel PT Instruction Trace")
|
| 87 | itrace = "i0nsepwxI"
|
| 88 | glb_insn = True
|
| 89 | elif glb_args.src_trace:
|
| 90 | print("Intel PT Source Trace")
|
| 91 | itrace = "i0nsepwxI"
|
| 92 | glb_insn = True
|
| 93 | glb_src = True
|
| 94 | else:
|
| 95 | print("Intel PT Branch Trace, Power Events, Event Trace and PTWRITE")
|
| 96 | itrace = "bepwxI"
|
| 97 | global glb_disassembler
|
| 98 | try:
|
| 99 | glb_disassembler = LibXED()
|
| 100 | except:
|
| 101 | glb_disassembler = None
|
| 102 | perf_set_itrace_options(perf_script_context, itrace)
|
| 103 |
|
| 104 | def trace_end():
|
| 105 | if glb_args.interleave:
|
| 106 | flush_stashed_output()
|
| 107 | print("End")
|
| 108 |
|
| 109 | def trace_unhandled(event_name, context, event_fields_dict):
|
| 110 | print(' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())]))
|
| 111 |
|
| 112 | def stash_output():
|
| 113 | global glb_stash_dict
|
| 114 | global glb_output_pos
|
| 115 | output_str = glb_output.getvalue()[glb_output_pos:]
|
| 116 | n = len(output_str)
|
| 117 | if n:
|
| 118 | glb_output_pos += n
|
| 119 | if glb_cpu not in glb_stash_dict:
|
| 120 | glb_stash_dict[glb_cpu] = []
|
| 121 | glb_stash_dict[glb_cpu].append(output_str)
|
| 122 |
|
| 123 | def flush_stashed_output():
|
| 124 | global glb_stash_dict
|
| 125 | while glb_stash_dict:
|
| 126 | cpus = list(glb_stash_dict.keys())
|
| 127 | |
| 128 | for cpu in cpus:
|
| 129 | items = glb_stash_dict[cpu]
|
| 130 | countdown = glb_args.interleave
|
| 131 | while len(items) and countdown:
|
| 132 | sys.stdout.write(items[0])
|
| 133 | del items[0]
|
| 134 | countdown -= 1
|
| 135 | if not items:
|
| 136 | del glb_stash_dict[cpu]
|
| 137 |
|
| 138 | def print_ptwrite(raw_buf):
|
| 139 | data = struct.unpack_from("<IQ", raw_buf)
|
| 140 | flags = data[0]
|
| 141 | payload = data[1]
|
| 142 | exact_ip = flags & 1
|
| 143 | try:
|
| 144 | s = payload.to_bytes(8, "little").decode("ascii").rstrip("\x00")
|
| 145 | if not s.isprintable():
|
| 146 | s = ""
|
| 147 | except:
|
| 148 | s = ""
|
| 149 | print("IP: %u payload: %#x" % (exact_ip, payload), s, end=' ')
|
| 150 |
|
| 151 | def print_cbr(raw_buf):
|
| 152 | data = struct.unpack_from("<BBBBII", raw_buf)
|
| 153 | cbr = data[0]
|
| 154 | f = (data[4] + 500) / 1000
|
| 155 | p = ((cbr * 1000 / data[2]) + 5) / 10
|
| 156 | print("%3u freq: %4u MHz (%3u%%)" % (cbr, f, p), end=' ')
|
| 157 |
|
| 158 | def print_mwait(raw_buf):
|
| 159 | data = struct.unpack_from("<IQ", raw_buf)
|
| 160 | payload = data[1]
|
| 161 | hints = payload & 0xff
|
| 162 | extensions = (payload >> 32) & 0x3
|
| 163 | print("hints: %#x extensions: %#x" % (hints, extensions), end=' ')
|
| 164 |
|
| 165 | def print_pwre(raw_buf):
|
| 166 | data = struct.unpack_from("<IQ", raw_buf)
|
| 167 | payload = data[1]
|
| 168 | hw = (payload >> 7) & 1
|
| 169 | cstate = (payload >> 12) & 0xf
|
| 170 | subcstate = (payload >> 8) & 0xf
|
| 171 | print("hw: %u cstate: %u sub-cstate: %u" % (hw, cstate, subcstate),
|
| 172 | end=' ')
|
| 173 |
|
| 174 | def print_exstop(raw_buf):
|
| 175 | data = struct.unpack_from("<I", raw_buf)
|
| 176 | flags = data[0]
|
| 177 | exact_ip = flags & 1
|
| 178 | print("IP: %u" % (exact_ip), end=' ')
|
| 179 |
|
| 180 | def print_pwrx(raw_buf):
|
| 181 | data = struct.unpack_from("<IQ", raw_buf)
|
| 182 | payload = data[1]
|
| 183 | deepest_cstate = payload & 0xf
|
| 184 | last_cstate = (payload >> 4) & 0xf
|
| 185 | wake_reason = (payload >> 8) & 0xf
|
| 186 | print("deepest cstate: %u last cstate: %u wake reason: %#x" %
|
| 187 | (deepest_cstate, last_cstate, wake_reason), end=' ')
|
| 188 |
|
| 189 | def print_psb(raw_buf):
|
| 190 | data = struct.unpack_from("<IQ", raw_buf)
|
| 191 | offset = data[1]
|
| 192 | print("offset: %#x" % (offset), end=' ')
|
| 193 |
|
| 194 | glb_cfe = ["", "INTR", "IRET", "SMI", "RSM", "SIPI", "INIT", "VMENTRY", "VMEXIT",
|
| 195 | "VMEXIT_INTR", "SHUTDOWN", "", "UINT", "UIRET"] + [""] * 18
|
| 196 | glb_evd = ["", "PFA", "VMXQ", "VMXR"] + [""] * 60
|
| 197 |
|
| 198 | def print_evt(raw_buf):
|
| 199 | data = struct.unpack_from("<BBH", raw_buf)
|
| 200 | typ = data[0] & 0x1f
|
| 201 | ip_flag = (data[0] & 0x80) >> 7
|
| 202 | vector = data[1]
|
| 203 | evd_cnt = data[2]
|
| 204 | s = glb_cfe[typ]
|
| 205 | if s:
|
| 206 | print(" cfe: %s IP: %u vector: %u" % (s, ip_flag, vector), end=' ')
|
| 207 | else:
|
| 208 | print(" cfe: %u IP: %u vector: %u" % (typ, ip_flag, vector), end=' ')
|
| 209 | pos = 4
|
| 210 | for i in range(evd_cnt):
|
| 211 | data = struct.unpack_from("<QQ", raw_buf)
|
| 212 | et = data[0] & 0x3f
|
| 213 | s = glb_evd[et]
|
| 214 | if s:
|
| 215 | print("%s: %#x" % (s, data[1]), end=' ')
|
| 216 | else:
|
| 217 | print("EVD_%u: %#x" % (et, data[1]), end=' ')
|
| 218 |
|
| 219 | def print_iflag(raw_buf):
|
| 220 | data = struct.unpack_from("<IQ", raw_buf)
|
| 221 | iflag = data[0] & 1
|
| 222 | old_iflag = iflag ^ 1
|
| 223 | via_branch = data[0] & 2
|
| 224 | branch_ip = data[1]
|
| 225 | if via_branch:
|
| 226 | s = "via"
|
| 227 | else:
|
| 228 | s = "non"
|
| 229 | print("IFLAG: %u->%u %s branch" % (old_iflag, iflag, s), end=' ')
|
| 230 |
|
| 231 | def common_start_str(comm, sample):
|
| 232 | ts = sample["time"]
|
| 233 | cpu = sample["cpu"]
|
| 234 | pid = sample["pid"]
|
| 235 | tid = sample["tid"]
|
| 236 | if "machine_pid" in sample:
|
| 237 | machine_pid = sample["machine_pid"]
|
| 238 | vcpu = sample["vcpu"]
|
| 239 | return "VM:%5d VCPU:%03d %16s %5u/%-5u [%03u] %9u.%09u " % (machine_pid, vcpu, comm, pid, tid, cpu, ts / 1000000000, ts %1000000000)
|
| 240 | else:
|
| 241 | return "%16s %5u/%-5u [%03u] %9u.%09u " % (comm, pid, tid, cpu, ts / 1000000000, ts %1000000000)
|
| 242 |
|
| 243 | def print_common_start(comm, sample, name):
|
| 244 | flags_disp = get_optional_null(sample, "flags_disp")
|
| 245 | |
| 246 | |
| 247 | |
| 248 | |
| 249 | |
| 250 | |
| 251 | print(common_start_str(comm, sample) + "%8s %21s" % (name, flags_disp), end=' ')
|
| 252 |
|
| 253 | def print_instructions_start(comm, sample):
|
| 254 | if "x" in get_optional_null(sample, "flags"):
|
| 255 | print(common_start_str(comm, sample) + "x", end=' ')
|
| 256 | else:
|
| 257 | print(common_start_str(comm, sample), end=' ')
|
| 258 |
|
| 259 | def disassem(insn, ip):
|
| 260 | inst = glb_disassembler.Instruction()
|
| 261 | glb_disassembler.SetMode(inst, 0) |
| 262 | buf = create_string_buffer(64)
|
| 263 | buf.value = insn
|
| 264 | return glb_disassembler.DisassembleOne(inst, addressof(buf), len(insn), ip)
|
| 265 |
|
| 266 | def print_common_ip(param_dict, sample, symbol, dso):
|
| 267 | ip = sample["ip"]
|
| 268 | offs = get_offset(param_dict, "symoff")
|
| 269 | if "cyc_cnt" in sample:
|
| 270 | cyc_cnt = sample["cyc_cnt"]
|
| 271 | insn_cnt = get_optional_zero(sample, "insn_cnt")
|
| 272 | ipc_str = " IPC: %#.2f (%u/%u)" % (insn_cnt / cyc_cnt, insn_cnt, cyc_cnt)
|
| 273 | else:
|
| 274 | ipc_str = ""
|
| 275 | if glb_insn and glb_disassembler is not None:
|
| 276 | insn = perf_sample_insn(perf_script_context)
|
| 277 | if insn and len(insn):
|
| 278 | cnt, text = disassem(insn, ip)
|
| 279 | byte_str = ("%x" % ip).rjust(16)
|
| 280 | if sys.version_info.major >= 3:
|
| 281 | for k in range(cnt):
|
| 282 | byte_str += " %02x" % insn[k]
|
| 283 | else:
|
| 284 | for k in xrange(cnt):
|
| 285 | byte_str += " %02x" % ord(insn[k])
|
| 286 | print("%-40s %-30s" % (byte_str, text), end=' ')
|
| 287 | print("%s%s (%s)" % (symbol, offs, dso), end=' ')
|
| 288 | else:
|
| 289 | print("%16x %s%s (%s)" % (ip, symbol, offs, dso), end=' ')
|
| 290 | if "addr_correlates_sym" in sample:
|
| 291 | addr = sample["addr"]
|
| 292 | dso = get_optional(sample, "addr_dso")
|
| 293 | symbol = get_optional(sample, "addr_symbol")
|
| 294 | offs = get_offset(sample, "addr_symoff")
|
| 295 | print("=> %x %s%s (%s)%s" % (addr, symbol, offs, dso, ipc_str))
|
| 296 | else:
|
| 297 | print(ipc_str)
|
| 298 |
|
| 299 | def print_srccode(comm, param_dict, sample, symbol, dso, with_insn):
|
| 300 | ip = sample["ip"]
|
| 301 | if symbol == "[unknown]":
|
| 302 | start_str = common_start_str(comm, sample) + ("%x" % ip).rjust(16).ljust(40)
|
| 303 | else:
|
| 304 | offs = get_offset(param_dict, "symoff")
|
| 305 | start_str = common_start_str(comm, sample) + (symbol + offs).ljust(40)
|
| 306 |
|
| 307 | if with_insn and glb_insn and glb_disassembler is not None:
|
| 308 | insn = perf_sample_insn(perf_script_context)
|
| 309 | if insn and len(insn):
|
| 310 | cnt, text = disassem(insn, ip)
|
| 311 | start_str += text.ljust(30)
|
| 312 |
|
| 313 | global glb_source_file_name
|
| 314 | global glb_line_number
|
| 315 | global glb_dso
|
| 316 |
|
| 317 | source_file_name, line_number, source_line = perf_sample_srccode(perf_script_context)
|
| 318 | if source_file_name:
|
| 319 | if glb_line_number == line_number and glb_source_file_name == source_file_name:
|
| 320 | src_str = ""
|
| 321 | else:
|
| 322 | if len(source_file_name) > 40:
|
| 323 | src_file = ("..." + source_file_name[-37:]) + " "
|
| 324 | else:
|
| 325 | src_file = source_file_name.ljust(41)
|
| 326 | if source_line is None:
|
| 327 | src_str = src_file + str(line_number).rjust(4) + " <source not found>"
|
| 328 | else:
|
| 329 | src_str = src_file + str(line_number).rjust(4) + " " + source_line
|
| 330 | glb_dso = None
|
| 331 | elif dso == glb_dso:
|
| 332 | src_str = ""
|
| 333 | else:
|
| 334 | src_str = dso
|
| 335 | glb_dso = dso
|
| 336 |
|
| 337 | glb_line_number = line_number
|
| 338 | glb_source_file_name = source_file_name
|
| 339 |
|
| 340 | print(start_str, src_str)
|
| 341 |
|
| 342 | def do_process_event(param_dict):
|
| 343 | sample = param_dict["sample"]
|
| 344 | raw_buf = param_dict["raw_buf"]
|
| 345 | comm = param_dict["comm"]
|
| 346 | name = param_dict["ev_name"]
|
| 347 | |
| 348 | |
| 349 | |
| 350 | |
| 351 | |
| 352 |
|
| 353 | |
| 354 | dso = get_optional(param_dict, "dso")
|
| 355 | symbol = get_optional(param_dict, "symbol")
|
| 356 |
|
| 357 | cpu = sample["cpu"]
|
| 358 | if cpu in glb_switch_str:
|
| 359 | print(glb_switch_str[cpu])
|
| 360 | del glb_switch_str[cpu]
|
| 361 |
|
| 362 | if name.startswith("instructions"):
|
| 363 | if glb_src:
|
| 364 | print_srccode(comm, param_dict, sample, symbol, dso, True)
|
| 365 | else:
|
| 366 | print_instructions_start(comm, sample)
|
| 367 | print_common_ip(param_dict, sample, symbol, dso)
|
| 368 | elif name.startswith("branches"):
|
| 369 | if glb_src:
|
| 370 | print_srccode(comm, param_dict, sample, symbol, dso, False)
|
| 371 | else:
|
| 372 | print_common_start(comm, sample, name)
|
| 373 | print_common_ip(param_dict, sample, symbol, dso)
|
| 374 | elif name == "ptwrite":
|
| 375 | print_common_start(comm, sample, name)
|
| 376 | print_ptwrite(raw_buf)
|
| 377 | print_common_ip(param_dict, sample, symbol, dso)
|
| 378 | elif name == "cbr":
|
| 379 | print_common_start(comm, sample, name)
|
| 380 | print_cbr(raw_buf)
|
| 381 | print_common_ip(param_dict, sample, symbol, dso)
|
| 382 | elif name == "mwait":
|
| 383 | print_common_start(comm, sample, name)
|
| 384 | print_mwait(raw_buf)
|
| 385 | print_common_ip(param_dict, sample, symbol, dso)
|
| 386 | elif name == "pwre":
|
| 387 | print_common_start(comm, sample, name)
|
| 388 | print_pwre(raw_buf)
|
| 389 | print_common_ip(param_dict, sample, symbol, dso)
|
| 390 | elif name == "exstop":
|
| 391 | print_common_start(comm, sample, name)
|
| 392 | print_exstop(raw_buf)
|
| 393 | print_common_ip(param_dict, sample, symbol, dso)
|
| 394 | elif name == "pwrx":
|
| 395 | print_common_start(comm, sample, name)
|
| 396 | print_pwrx(raw_buf)
|
| 397 | print_common_ip(param_dict, sample, symbol, dso)
|
| 398 | elif name == "psb":
|
| 399 | print_common_start(comm, sample, name)
|
| 400 | print_psb(raw_buf)
|
| 401 | print_common_ip(param_dict, sample, symbol, dso)
|
| 402 | elif name == "evt":
|
| 403 | print_common_start(comm, sample, name)
|
| 404 | print_evt(raw_buf)
|
| 405 | print_common_ip(param_dict, sample, symbol, dso)
|
| 406 | elif name == "iflag":
|
| 407 | print_common_start(comm, sample, name)
|
| 408 | print_iflag(raw_buf)
|
| 409 | print_common_ip(param_dict, sample, symbol, dso)
|
| 410 | else:
|
| 411 | print_common_start(comm, sample, name)
|
| 412 | print_common_ip(param_dict, sample, symbol, dso)
|
| 413 |
|
| 414 | def interleave_events(param_dict):
|
| 415 | global glb_cpu
|
| 416 | global glb_time
|
| 417 | global glb_output
|
| 418 | global glb_output_pos
|
| 419 |
|
| 420 | sample = param_dict["sample"]
|
| 421 | glb_cpu = sample["cpu"]
|
| 422 | ts = sample["time"]
|
| 423 |
|
| 424 | if glb_time != ts:
|
| 425 | glb_time = ts
|
| 426 | flush_stashed_output()
|
| 427 |
|
| 428 | glb_output_pos = 0
|
| 429 | with contextlib.redirect_stdout(io.StringIO()) as glb_output:
|
| 430 | do_process_event(param_dict)
|
| 431 |
|
| 432 | stash_output()
|
| 433 |
|
| 434 | def process_event(param_dict):
|
| 435 | try:
|
| 436 | if glb_args.interleave:
|
| 437 | interleave_events(param_dict)
|
| 438 | else:
|
| 439 | do_process_event(param_dict)
|
| 440 | except broken_pipe_exception:
|
| 441 | |
| 442 | sys.stdout = open(os.devnull, 'w')
|
| 443 | sys.exit(1)
|
| 444 |
|
| 445 | def auxtrace_error(typ, code, cpu, pid, tid, ip, ts, msg, cpumode, *x):
|
| 446 | if glb_args.interleave:
|
| 447 | flush_stashed_output()
|
| 448 | if len(x) >= 2 and x[0]:
|
| 449 | machine_pid = x[0]
|
| 450 | vcpu = x[1]
|
| 451 | else:
|
| 452 | machine_pid = 0
|
| 453 | vcpu = -1
|
| 454 | try:
|
| 455 | if machine_pid:
|
| 456 | print("VM:%5d VCPU:%03d %16s %5u/%-5u [%03u] %9u.%09u error type %u code %u: %s ip 0x%16x" %
|
| 457 | (machine_pid, vcpu, "Trace error", pid, tid, cpu, ts / 1000000000, ts %1000000000, typ, code, msg, ip))
|
| 458 | else:
|
| 459 | print("%16s %5u/%-5u [%03u] %9u.%09u error type %u code %u: %s ip 0x%16x" %
|
| 460 | ("Trace error", pid, tid, cpu, ts / 1000000000, ts %1000000000, typ, code, msg, ip))
|
| 461 | except broken_pipe_exception:
|
| 462 | |
| 463 | sys.stdout = open(os.devnull, 'w')
|
| 464 | sys.exit(1)
|
| 465 |
|
| 466 | def context_switch(ts, cpu, pid, tid, np_pid, np_tid, machine_pid, out, out_preempt, *x):
|
| 467 | if glb_args.interleave:
|
| 468 | flush_stashed_output()
|
| 469 | if out:
|
| 470 | out_str = "Switch out "
|
| 471 | else:
|
| 472 | out_str = "Switch In "
|
| 473 | if out_preempt:
|
| 474 | preempt_str = "preempt"
|
| 475 | else:
|
| 476 | preempt_str = ""
|
| 477 | if len(x) >= 2 and x[0]:
|
| 478 | machine_pid = x[0]
|
| 479 | vcpu = x[1]
|
| 480 | else:
|
| 481 | vcpu = None;
|
| 482 | if machine_pid == -1:
|
| 483 | machine_str = ""
|
| 484 | elif vcpu is None:
|
| 485 | machine_str = "machine PID %d" % machine_pid
|
| 486 | else:
|
| 487 | machine_str = "machine PID %d VCPU %d" % (machine_pid, vcpu)
|
| 488 | switch_str = "%16s %5d/%-5d [%03u] %9u.%09u %5d/%-5d %s %s" % \
|
| 489 | (out_str, pid, tid, cpu, ts / 1000000000, ts %1000000000, np_pid, np_tid, machine_str, preempt_str)
|
| 490 | if glb_args.all_switch_events:
|
| 491 | print(switch_str)
|
| 492 | else:
|
| 493 | global glb_switch_str
|
| 494 | glb_switch_str[cpu] = switch_str
|