495 lines · python
1# SPDX-License-Identifier: GPL-2.02# intel-pt-events.py: Print Intel PT Events including Power Events and PTWRITE3# Copyright (c) 2017-2021, Intel Corporation.4#5# This program is free software; you can redistribute it and/or modify it6# under the terms and conditions of the GNU General Public License,7# version 2, as published by the Free Software Foundation.8#9# This program is distributed in the hope it will be useful, but WITHOUT10# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or11# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for12# more details.13 14from __future__ import division, print_function15 16import io17import os18import sys19import struct20import argparse21import contextlib22 23from libxed import LibXED24from ctypes import create_string_buffer, addressof25 26sys.path.append(os.environ['PERF_EXEC_PATH'] + \27 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')28 29from perf_trace_context import perf_set_itrace_options, \30 perf_sample_insn, perf_sample_srccode31 32try:33 broken_pipe_exception = BrokenPipeError34except:35 broken_pipe_exception = IOError36 37glb_switch_str = {}38glb_insn = False39glb_disassembler = None40glb_src = False41glb_source_file_name = None42glb_line_number = None43glb_dso = None44glb_stash_dict = {}45glb_output = None46glb_output_pos = 047glb_cpu = -148glb_time = 049 50def get_optional_null(perf_dict, field):51 if field in perf_dict:52 return perf_dict[field]53 return ""54 55def get_optional_zero(perf_dict, field):56 if field in perf_dict:57 return perf_dict[field]58 return 059 60def get_optional_bytes(perf_dict, field):61 if field in perf_dict:62 return perf_dict[field]63 return bytes()64 65def get_optional(perf_dict, field):66 if field in perf_dict:67 return perf_dict[field]68 return "[unknown]"69 70def get_offset(perf_dict, field):71 if field in perf_dict:72 return "+%#x" % perf_dict[field]73 return ""74 75def 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_args82 global glb_insn83 global glb_src84 glb_args = ap.parse_args()85 if glb_args.insn_trace:86 print("Intel PT Instruction Trace")87 itrace = "i0nsepwxI"88 glb_insn = True89 elif glb_args.src_trace:90 print("Intel PT Source Trace")91 itrace = "i0nsepwxI"92 glb_insn = True93 glb_src = True94 else:95 print("Intel PT Branch Trace, Power Events, Event Trace and PTWRITE")96 itrace = "bepwxI"97 global glb_disassembler98 try:99 glb_disassembler = LibXED()100 except:101 glb_disassembler = None102 perf_set_itrace_options(perf_script_context, itrace)103 104def trace_end():105 if glb_args.interleave:106 flush_stashed_output()107 print("End")108 109def 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 112def stash_output():113 global glb_stash_dict114 global glb_output_pos115 output_str = glb_output.getvalue()[glb_output_pos:]116 n = len(output_str)117 if n:118 glb_output_pos += n119 if glb_cpu not in glb_stash_dict:120 glb_stash_dict[glb_cpu] = []121 glb_stash_dict[glb_cpu].append(output_str)122 123def flush_stashed_output():124 global glb_stash_dict125 while glb_stash_dict:126 cpus = list(glb_stash_dict.keys())127 # Output at most glb_args.interleave output strings per cpu128 for cpu in cpus:129 items = glb_stash_dict[cpu]130 countdown = glb_args.interleave131 while len(items) and countdown:132 sys.stdout.write(items[0])133 del items[0]134 countdown -= 1135 if not items:136 del glb_stash_dict[cpu]137 138def print_ptwrite(raw_buf):139 data = struct.unpack_from("<IQ", raw_buf)140 flags = data[0]141 payload = data[1]142 exact_ip = flags & 1143 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 151def print_cbr(raw_buf):152 data = struct.unpack_from("<BBBBII", raw_buf)153 cbr = data[0]154 f = (data[4] + 500) / 1000155 p = ((cbr * 1000 / data[2]) + 5) / 10156 print("%3u freq: %4u MHz (%3u%%)" % (cbr, f, p), end=' ')157 158def print_mwait(raw_buf):159 data = struct.unpack_from("<IQ", raw_buf)160 payload = data[1]161 hints = payload & 0xff162 extensions = (payload >> 32) & 0x3163 print("hints: %#x extensions: %#x" % (hints, extensions), end=' ')164 165def print_pwre(raw_buf):166 data = struct.unpack_from("<IQ", raw_buf)167 payload = data[1]168 hw = (payload >> 7) & 1169 cstate = (payload >> 12) & 0xf170 subcstate = (payload >> 8) & 0xf171 print("hw: %u cstate: %u sub-cstate: %u" % (hw, cstate, subcstate),172 end=' ')173 174def print_exstop(raw_buf):175 data = struct.unpack_from("<I", raw_buf)176 flags = data[0]177 exact_ip = flags & 1178 print("IP: %u" % (exact_ip), end=' ')179 180def print_pwrx(raw_buf):181 data = struct.unpack_from("<IQ", raw_buf)182 payload = data[1]183 deepest_cstate = payload & 0xf184 last_cstate = (payload >> 4) & 0xf185 wake_reason = (payload >> 8) & 0xf186 print("deepest cstate: %u last cstate: %u wake reason: %#x" %187 (deepest_cstate, last_cstate, wake_reason), end=' ')188 189def print_psb(raw_buf):190 data = struct.unpack_from("<IQ", raw_buf)191 offset = data[1]192 print("offset: %#x" % (offset), end=' ')193 194glb_cfe = ["", "INTR", "IRET", "SMI", "RSM", "SIPI", "INIT", "VMENTRY", "VMEXIT",195 "VMEXIT_INTR", "SHUTDOWN", "", "UINT", "UIRET"] + [""] * 18196glb_evd = ["", "PFA", "VMXQ", "VMXR"] + [""] * 60197 198def print_evt(raw_buf):199 data = struct.unpack_from("<BBH", raw_buf)200 typ = data[0] & 0x1f201 ip_flag = (data[0] & 0x80) >> 7202 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 = 4210 for i in range(evd_cnt):211 data = struct.unpack_from("<QQ", raw_buf)212 et = data[0] & 0x3f213 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 219def print_iflag(raw_buf):220 data = struct.unpack_from("<IQ", raw_buf)221 iflag = data[0] & 1222 old_iflag = iflag ^ 1223 via_branch = data[0] & 2224 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 231def 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 243def print_common_start(comm, sample, name):244 flags_disp = get_optional_null(sample, "flags_disp")245 # Unused fields:246 # period = sample["period"]247 # phys_addr = sample["phys_addr"]248 # weight = sample["weight"]249 # transaction = sample["transaction"]250 # cpumode = get_optional_zero(sample, "cpumode")251 print(common_start_str(comm, sample) + "%8s %21s" % (name, flags_disp), end=' ')252 253def 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 259def disassem(insn, ip):260 inst = glb_disassembler.Instruction()261 glb_disassembler.SetMode(inst, 0) # Assume 64-bit262 buf = create_string_buffer(64)263 buf.value = insn264 return glb_disassembler.DisassembleOne(inst, addressof(buf), len(insn), ip)265 266def 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 299def 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_name314 global glb_line_number315 global glb_dso316 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_line330 glb_dso = None331 elif dso == glb_dso:332 src_str = ""333 else:334 src_str = dso335 glb_dso = dso336 337 glb_line_number = line_number338 glb_source_file_name = source_file_name339 340 print(start_str, src_str)341 342def 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 # Unused fields:348 # callchain = param_dict["callchain"]349 # brstack = param_dict["brstack"]350 # brstacksym = param_dict["brstacksym"]351 # event_attr = param_dict["attr"]352 353 # Symbol and dso info are not always resolved354 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 414def interleave_events(param_dict):415 global glb_cpu416 global glb_time417 global glb_output418 global glb_output_pos419 420 sample = param_dict["sample"]421 glb_cpu = sample["cpu"]422 ts = sample["time"]423 424 if glb_time != ts:425 glb_time = ts426 flush_stashed_output()427 428 glb_output_pos = 0429 with contextlib.redirect_stdout(io.StringIO()) as glb_output:430 do_process_event(param_dict)431 432 stash_output()433 434def 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 # Stop python printing broken pipe errors and traceback442 sys.stdout = open(os.devnull, 'w')443 sys.exit(1)444 445def 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 = 0453 vcpu = -1454 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 # Stop python printing broken pipe errors and traceback463 sys.stdout = open(os.devnull, 'w')464 sys.exit(1)465 466def 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_pid486 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_str494 glb_switch_str[cpu] = switch_str495