1#!/usr/bin/python 2# 3# ppchcalls Summarize ppc hcalls stats. 4# 5# Initial version migrating perf based tool to ebpf with additional hcalls, 6# inspired by existing bcc tool for syscalls. 7# 8# 9 10from time import sleep, strftime 11import argparse 12import errno 13import itertools 14import sys 15import signal 16from bcc import BPF 17 18hcall_table = { 19 4: 'H_REMOVE', 20 8: 'H_ENTER', 21 12: 'H_READ', 22 16: 'H_CLEAR_MOD', 23 20: 'H_CLEAR_REF', 24 24: 'H_PROTECT', 25 28: 'H_GET_TCE', 26 32: 'H_PUT_TCE', 27 36: 'H_SET_SPRG0', 28 40: 'H_SET_DABR', 29 44: 'H_PAGE_INIT', 30 48: 'H_SET_ASR', 31 52: 'H_ASR_ON', 32 56: 'H_ASR_OFF', 33 60: 'H_LOGICAL_CI_LOAD', 34 64: 'H_LOGICAL_CI_STORE', 35 68: 'H_LOGICAL_CACHE_LOAD', 36 72: 'H_LOGICAL_CACHE_STORE', 37 76: 'H_LOGICAL_ICBI', 38 80: 'H_LOGICAL_DCBF', 39 84: 'H_GET_TERM_CHAR', 40 88: 'H_PUT_TERM_CHAR', 41 92: 'H_REAL_TO_LOGICAL', 42 96: 'H_HYPERVISOR_DATA', 43 100: 'H_EOI', 44 104: 'H_CPPR', 45 108: 'H_IPI', 46 112: 'H_IPOLL', 47 116: 'H_XIRR', 48 120: 'H_MIGRATE_DMA', 49 124: 'H_PERFMON', 50 220: 'H_REGISTER_VPA', 51 224: 'H_CEDE', 52 228: 'H_CONFER', 53 232: 'H_PROD', 54 236: 'H_GET_PPP', 55 240: 'H_SET_PPP', 56 244: 'H_PURR', 57 248: 'H_PIC', 58 252: 'H_REG_CRQ', 59 256: 'H_FREE_CRQ', 60 260: 'H_VIO_SIGNAL', 61 264: 'H_SEND_CRQ', 62 272: 'H_COPY_RDMA', 63 276: 'H_REGISTER_LOGICAL_LAN', 64 280: 'H_FREE_LOGICAL_LAN', 65 284: 'H_ADD_LOGICAL_LAN_BUFFER', 66 288: 'H_SEND_LOGICAL_LAN', 67 292: 'H_BULK_REMOVE', 68 304: 'H_MULTICAST_CTRL', 69 308: 'H_SET_XDABR', 70 312: 'H_STUFF_TCE', 71 316: 'H_PUT_TCE_INDIRECT', 72 332: 'H_CHANGE_LOGICAL_LAN_MAC', 73 336: 'H_VTERM_PARTNER_INFO', 74 340: 'H_REGISTER_VTERM', 75 344: 'H_FREE_VTERM', 76 348: 'H_RESET_EVENTS', 77 352: 'H_ALLOC_RESOURCE', 78 356: 'H_FREE_RESOURCE', 79 360: 'H_MODIFY_QP', 80 364: 'H_QUERY_QP', 81 368: 'H_REREGISTER_PMR', 82 372: 'H_REGISTER_SMR', 83 376: 'H_QUERY_MR', 84 380: 'H_QUERY_MW', 85 384: 'H_QUERY_HCA', 86 388: 'H_QUERY_PORT', 87 392: 'H_MODIFY_PORT', 88 396: 'H_DEFINE_AQP1', 89 400: 'H_GET_TRACE_BUFFER', 90 404: 'H_DEFINE_AQP0', 91 408: 'H_RESIZE_MR', 92 412: 'H_ATTACH_MCQP', 93 416: 'H_DETACH_MCQP', 94 420: 'H_CREATE_RPT', 95 424: 'H_REMOVE_RPT', 96 428: 'H_REGISTER_RPAGES', 97 432: 'H_DISABLE_AND_GET', 98 436: 'H_ERROR_DATA', 99 440: 'H_GET_HCA_INFO', 100 444: 'H_GET_PERF_COUNT', 101 448: 'H_MANAGE_TRACE', 102 456: 'H_GET_CPU_CHARACTERISTICS', 103 468: 'H_FREE_LOGICAL_LAN_BUFFER', 104 472: 'H_POLL_PENDING', 105 484: 'H_QUERY_INT_STATE', 106 580: 'H_ILLAN_ATTRIBUTES', 107 592: 'H_MODIFY_HEA_QP', 108 596: 'H_QUERY_HEA_QP', 109 600: 'H_QUERY_HEA', 110 604: 'H_QUERY_HEA_PORT', 111 608: 'H_MODIFY_HEA_PORT', 112 612: 'H_REG_BCMC', 113 616: 'H_DEREG_BCMC', 114 620: 'H_REGISTER_HEA_RPAGES', 115 624: 'H_DISABLE_AND_GET_HEA', 116 628: 'H_GET_HEA_INFO', 117 632: 'H_ALLOC_HEA_RESOURCE', 118 644: 'H_ADD_CONN', 119 648: 'H_DEL_CONN', 120 664: 'H_JOIN', 121 672: 'H_VASI_SIGNAL', 122 676: 'H_VASI_STATE', 123 680: 'H_VIOCTL', 124 688: 'H_ENABLE_CRQ', 125 696: 'H_GET_EM_PARMS', 126 720: 'H_SET_MPP', 127 724: 'H_GET_MPP', 128 732: 'H_REG_SUB_CRQ', 129 736: 'H_FREE_SUB_CRQ', 130 740: 'H_SEND_SUB_CRQ', 131 744: 'H_SEND_SUB_CRQ_INDIRECT', 132 748: 'H_HOME_NODE_ASSOCIATIVITY', 133 756: 'H_BEST_ENERGY', 134 764: 'H_XIRR_X', 135 768: 'H_RANDOM', 136 772: 'H_COP', 137 788: 'H_GET_MPP_X', 138 796: 'H_SET_MODE', 139 808: 'H_BLOCK_REMOVE', 140 856: 'H_CLEAR_HPT', 141 864: 'H_REQUEST_VMC', 142 876: 'H_RESIZE_HPT_PREPARE', 143 880: 'H_RESIZE_HPT_COMMIT', 144 892: 'H_REGISTER_PROC_TBL', 145 896: 'H_SIGNAL_SYS_RESET', 146 904: 'H_ALLOCATE_VAS_WINDOW', 147 908: 'H_MODIFY_VAS_WINDOW', 148 912: 'H_DEALLOCATE_VAS_WINDOW', 149 916: 'H_QUERY_VAS_WINDOW', 150 920: 'H_QUERY_VAS_CAPABILITIES', 151 924: 'H_QUERY_NX_CAPABILITIES', 152 928: 'H_GET_NX_FAULT', 153 936: 'H_INT_GET_SOURCE_INFO', 154 940: 'H_INT_SET_SOURCE_CONFIG', 155 944: 'H_INT_GET_SOURCE_CONFIG', 156 948: 'H_INT_GET_QUEUE_INFO', 157 952: 'H_INT_SET_QUEUE_CONFIG', 158 956: 'H_INT_GET_QUEUE_CONFIG', 159 960: 'H_INT_SET_OS_REPORTING_LINE', 160 964: 'H_INT_GET_OS_REPORTING_LINE', 161 968: 'H_INT_ESB', 162 972: 'H_INT_SYNC', 163 976: 'H_INT_RESET', 164 996: 'H_SCM_READ_METADATA', 165 1000: 'H_SCM_WRITE_METADATA', 166 1004: 'H_SCM_BIND_MEM', 167 1008: 'H_SCM_UNBIND_MEM', 168 1012: 'H_SCM_QUERY_BLOCK_MEM_BINDING', 169 1016: 'H_SCM_QUERY_LOGICAL_MEM_BINDING', 170 1020: 'H_SCM_UNBIND_ALL', 171 1024: 'H_SCM_HEALTH', 172 1048: 'H_SCM_PERFORMANCE_STATS', 173 1052: 'H_PKS_GET_CONFIG', 174 1056: 'H_PKS_SET_PASSWORD', 175 1060: 'H_PKS_GEN_PASSWORD', 176 1068: 'H_PKS_WRITE_OBJECT', 177 1072: 'H_PKS_GEN_KEY', 178 1076: 'H_PKS_READ_OBJECT', 179 1080: 'H_PKS_REMOVE_OBJECT', 180 1084: 'H_PKS_CONFIRM_OBJECT_FLUSHED', 181 1096: 'H_RPT_INVALIDATE', 182 1100: 'H_SCM_FLUSH', 183 1104: 'H_GET_ENERGY_SCALE_INFO', 184 1108: 'H_PKS_SIGNED_UPDATE', 185 1116: 'H_WATCHDOG', 186 # Platform specific hcalls used by KVM on PowerVM 187 1120: 'H_GUEST_GET_CAPABILITIES', 188 1124: 'H_GUEST_SET_CAPABILITIES', 189 1136: 'H_GUEST_CREATE', 190 1140: 'H_GUEST_CREATE_VCPU', 191 1144: 'H_GUEST_GET_STATE', 192 1148: 'H_GUEST_SET_STATE', 193 1152: 'H_GUEST_RUN_VCPU', 194 1156: 'H_GUEST_COPY_MEMORY', 195 1160: 'H_GUEST_DELETE', 196 # Platform-specific hcalls used by the Ultravisor 197 61184: 'H_SVM_PAGE_IN', 198 61188: 'H_SVM_PAGE_OUT', 199 61192: 'H_SVM_INIT_START', 200 61196: 'H_SVM_INIT_DONE', 201 61204: 'H_SVM_INIT_ABORT', 202 # Platform specific hcalls used by KVM 203 61440: 'H_RTAS', 204 # Platform specific hcalls used by QEMU/SLOF 205 61441: 'H_LOGICAL_MEMOP', 206 61442: 'H_CAS', 207 61443: 'H_UPDATE_DT', 208 # Platform specific hcalls provided by PHYP 209 61560: 'H_GET_24X7_CATALOG_PAGE', 210 61564: 'H_GET_24X7_DATA', 211 61568: 'H_GET_PERF_COUNTER_INFO', 212 # Platform-specific hcalls used for nested HV KVM 213 63488: 'H_SET_PARTITION_TABLE', 214 63492: 'H_ENTER_NESTED', 215 63496: 'H_TLB_INVALIDATE', 216 63500: 'H_COPY_TOFROM_GUEST', 217} 218 219def hcall_table_lookup(opcode): 220 if (opcode in hcall_table): 221 return hcall_table[opcode] 222 else: 223 return opcode 224 225if sys.version_info.major < 3: 226 izip_longest = itertools.izip_longest 227else: 228 izip_longest = itertools.zip_longest 229 230# signal handler 231def signal_ignore(signal, frame): 232 print() 233 234def handle_errno(errstr): 235 try: 236 return abs(int(errstr)) 237 except ValueError: 238 pass 239 240 try: 241 return getattr(errno, errstr) 242 except AttributeError: 243 raise argparse.ArgumentTypeError("couldn't map %s to an errno" % errstr) 244 245 246parser = argparse.ArgumentParser( 247 description="Summarize ppc hcall counts and latencies.") 248parser.add_argument("-p", "--pid", type=int, 249 help="trace only this pid") 250parser.add_argument("-t", "--tid", type=int, 251 help="trace only this tid") 252parser.add_argument("-i", "--interval", type=int, 253 help="print summary at this interval (seconds)") 254parser.add_argument("-d", "--duration", type=int, 255 help="total duration of trace, in seconds") 256parser.add_argument("-T", "--top", type=int, default=10, 257 help="print only the top hcalls by count or latency") 258parser.add_argument("-x", "--failures", action="store_true", 259 help="trace only failed hcalls (return < 0)") 260parser.add_argument("-e", "--errno", type=handle_errno, 261 help="trace only hcalls that return this error (numeric or EPERM, etc.)") 262parser.add_argument("-L", "--latency", action="store_true", 263 help="collect hcall latency") 264parser.add_argument("-m", "--milliseconds", action="store_true", 265 help="display latency in milliseconds (default: microseconds)") 266parser.add_argument("-P", "--process", action="store_true", 267 help="count by process and not by hcall") 268parser.add_argument("-l", "--list", action="store_true", 269 help="print list of recognized hcalls and exit") 270parser.add_argument("--hcall", type=str, 271 help="trace this hcall only (use option -l to get all recognized hcalls)") 272parser.add_argument("--ebpf", action="store_true", 273 help=argparse.SUPPRESS) 274args = parser.parse_args() 275if args.duration and not args.interval: 276 args.interval = args.duration 277if not args.interval: 278 args.interval = 99999999 279 280hcall_nr = -1 281if args.hcall is not None: 282 for key, value in hcall_table.items(): 283 if args.hcall == value: 284 hcall_nr = key 285 print("hcall %s , hcall_nr =%d" % (args.hcall, hcall_nr)) 286 break 287 if hcall_nr == -1: 288 print("Error: hcall '%s' not found. Exiting." % args.hcall) 289 sys.exit(1) 290 291if args.list: 292 for grp in izip_longest(*(iter(sorted(hcall_table.values())),) * 4): 293 print(" ".join(["%-25s" % s for s in grp if s is not None])) 294 sys.exit(0) 295 296text = """ 297#ifdef LATENCY 298struct data_t { 299 u64 count; 300 u64 min; 301 u64 max; 302 u64 total_ns; 303}; 304 305BPF_HASH(start, u64, u64); 306BPF_HASH(ppc_data, u32, struct data_t); 307#else 308BPF_HASH(ppc_data, u32, u64); 309#endif 310 311#ifdef LATENCY 312RAW_TRACEPOINT_PROBE(hcall_entry) { 313 // TP_PROTO(unsigned long opcode, unsigned long *args), 314 u64 pid_tgid = bpf_get_current_pid_tgid(); 315 u32 pid = pid_tgid >> 32; 316 u32 tid = (u32)pid_tgid; 317 318#ifdef FILTER_HCALL_NR 319if (ctx->args[0] != FILTER_HCALL_NR) 320 return 0; 321#endif 322 323#ifdef FILTER_PID 324 if (pid != FILTER_PID) 325 return 0; 326#endif 327 328#ifdef FILTER_TID 329 if (tid != FILTER_TID) 330 return 0; 331#endif 332 333 u64 t = bpf_ktime_get_ns(); 334 start.update(&pid_tgid, &t); 335 return 0; 336} 337#endif 338 339RAW_TRACEPOINT_PROBE(hcall_exit) { 340 // TP_PROTO(unsigned long opcode, long retval, unsigned long *retbuf) 341 u64 pid_tgid = bpf_get_current_pid_tgid(); 342 u32 pid = pid_tgid >> 32; 343 u32 tid = (u32)pid_tgid; 344 345#ifdef FILTER_HCALL_NR 346 if (ctx->args[0] != FILTER_HCALL_NR) 347 return 0; 348#endif 349 350#ifdef FILTER_PID 351 if (pid != FILTER_PID) 352 return 0; 353#endif 354 355#ifdef FILTER_TID 356 if (tid != FILTER_TID) 357 return 0; 358#endif 359 360#ifdef FILTER_FAILED 361 if (ctx->args[1] >= 0) 362 return 0; 363#endif 364 365#ifdef FILTER_ERRNO 366 if (ctx->args[1] != -FILTER_ERRNO) 367 return 0; 368#endif 369 370#ifdef BY_PROCESS 371 u32 key = pid_tgid >> 32; 372#else 373 u32 key = (unsigned long) ctx->args[0]; 374#endif 375 376#ifdef LATENCY 377 struct data_t *val, zero = {}; 378 u64 delta = 0; 379 u64 *start_ns = start.lookup(&pid_tgid); 380 if (!start_ns) 381 return 0; 382 383 val = ppc_data.lookup_or_try_init(&key, &zero); 384 if (val) { 385 val->count++; 386 delta = bpf_ktime_get_ns() - *start_ns; 387 if (val->min) { 388 if(val->min > delta) 389 val->min = delta; 390 } else { 391 val->min = delta; 392 } 393 if (val->max) { 394 if(val->max < delta) 395 val->max = delta; 396 } else { 397 val->max = delta; 398 } 399 val->total_ns += delta; 400 } 401#else 402 u64 *val, zero = 0; 403 val = ppc_data.lookup_or_try_init(&key, &zero); 404 if (val) { 405 ++(*val); 406 } 407#endif 408 return 0; 409} 410""" 411 412if args.pid: 413 text = ("#define FILTER_PID %d\n" % args.pid) + text 414elif args.tid: 415 text = ("#define FILTER_TID %d\n" % args.tid) + text 416if args.failures: 417 text = "#define FILTER_FAILED\n" + text 418if args.errno: 419 text = "#define FILTER_ERRNO %d\n" % abs(args.errno) + text 420if args.latency: 421 text = "#define LATENCY\n" + text 422if args.process: 423 text = "#define BY_PROCESS\n" + text 424if args.hcall is not None: 425 text = ("#define FILTER_HCALL_NR %d\n" % hcall_nr) + text 426if args.ebpf: 427 print(text) 428 exit() 429 430bpf = BPF(text=text) 431 432def print_stats(): 433 if args.latency: 434 ppc_print_latency_stats() 435 else: 436 print_ppc_count_stats() 437 438ppc_agg_colname = "PID COMM" if args.process else "PPC HCALL" 439min_time_colname = "MIN (ms)" if args.milliseconds else "MIN (us)" 440max_time_colname = "MAX (ms)" if args.milliseconds else "MAX (us)" 441avg_time_colname = "AVG (ms)" if args.milliseconds else "AVG (us)" 442 443def comm_for_pid(pid): 444 try: 445 return open("/proc/%d/comm" % pid, "r").read().strip() 446 except Exception: 447 return "[unknown]" 448 449def agg_colval(key): 450 if args.process: 451 return "%-6d %-15s" % (key.value, comm_for_pid(key.value)) 452 else: 453 return hcall_table_lookup(key.value) 454 455def print_ppc_count_stats(): 456 data = bpf["ppc_data"] 457 print("[%s]" % strftime("%H:%M:%S")) 458 print("%-45s %8s" % (ppc_agg_colname, "COUNT")) 459 for k, v in sorted(data.items(), key=lambda kv: -kv[1].value)[:args.top]: 460 if k.value == 0xFFFFFFFF: 461 continue # happens occasionally, we don't need it 462 print("%-45s %8d" % (agg_colval(k), v.value)) 463 print("") 464 data.clear() 465 466def ppc_print_latency_stats(): 467 data = bpf["ppc_data"] 468 print("[%s]" % strftime("%H:%M:%S")) 469 print("%-45s %8s %17s %17s %17s" % (ppc_agg_colname, "COUNT", 470 min_time_colname, max_time_colname, avg_time_colname)) 471 for k, v in sorted(data.items(), 472 key=lambda kv: -kv[1].count)[:args.top]: 473 if k.value == 0xFFFFFFFF: 474 continue # happens occasionally, we don't need it 475 print(("%-45s %8d " + ("%17.6f" if args.milliseconds else "%17.3f ") + 476 ("%17.6f" if args.milliseconds else "%17.3f ") + 477 ("%17.6f" if args.milliseconds else "%17.3f")) % 478 (agg_colval(k), v.count, 479 v.min / (1e6 if args.milliseconds else 1e3), 480 v.max / (1e6 if args.milliseconds else 1e3), 481 (v.total_ns / v.count) / (1e6 if args.milliseconds else 1e3))) 482 print("") 483 data.clear() 484 485if args.hcall is not None: 486 print("Tracing %sppc hcall '%s'... Ctrl+C to quit." % 487 ("failed " if args.failures else "", args.hcall)) 488else: 489 print("Tracing %sppc hcalls, printing top %d... Ctrl+C to quit." % 490 ("failed " if args.failures else "", args.top)) 491exiting = 0 if args.interval else 1 492seconds = 0 493while True: 494 try: 495 sleep(args.interval) 496 seconds += args.interval 497 except KeyboardInterrupt: 498 exiting = 1 499 signal.signal(signal.SIGINT, signal_ignore) 500 if args.duration and seconds >= args.duration: 501 exiting = 1 502 503 print_stats() 504 505 if exiting: 506 print("Detaching...") 507 exit() 508