intel-pt-events.py 14 KB

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