1#!/usr/bin/env python 2# machtrace_parse.py 3# Parse Mach IPC kmsg data trace from XNU 4# 5# Jeremy C. Andrus <[email protected]> 6# 7from __future__ import division 8 9import argparse 10import subprocess 11import sys 12import re 13from collections import deque 14 15import os.path 16 17from collections import defaultdict 18 19g_verbose = 0 20g_min_messages = 10 21g_rolling_window = 200 22 23def RunCommand(cmd_string): 24 """ 25 returns: (int,str) : exit_code and output_str 26 """ 27 global g_verbose 28 if g_verbose > 1: 29 sys.stderr.write("\tCMD:{}\n".format(cmd_string)) 30 output_str = "" 31 exit_code = 0 32 try: 33 output_str = subprocess.check_output(cmd_string, shell=True) 34 except subprocess.CalledProcessError, e: 35 exit_code = e.returncode 36 finally: 37 return (exit_code, output_str.strip()) 38 39 40class IPCNode: 41 """ Class interface to a graph node representing a logical service name. 42 In general, this should correspond to a unique binary on the system 43 which could be started / stopped as different PIDs throughout the life 44 of the system. 45 """ 46 def __init__(self, name = ''): 47 global g_verbose 48 self.nname = "L_" + name.replace(".", "_").replace("-", "_") 49 self.nicename = name 50 self.outgoing = {} 51 self.incoming = {} 52 self.msg_stat = {'o.num':0, 'o.first':0.0, 'o.last':0.0, 'o.window':deque(), 'o.avg':0, 'o.peak':0, \ 53 'i.num':0, 'i.first':0.0, 'i.last':0.0, 'i.window':deque(), 'i.avg':0, 'i.peak':0} 54 self.pidset = {} 55 self.scalefactor = 100.0 56 if g_verbose > 0: 57 sys.stderr.write(' New node: "{}"{}\n'.format(self.nname, ' '*50)) 58 59 def add_outgoing_edge(self, edge, time): 60 self.outgoing[edge.ename()] = [edge, time] 61 62 def add_incoming_edge(self, edge, time): 63 self.incoming[edge.ename()] = [edge, time] 64 65 def addpid(self, pid, time): 66 if not pid in self.pidset: 67 self.pidset[pid] = [time, 0] 68 self.pidset[pid][1] = time 69 70 def incoming_msg(self, size, time_us): 71 global g_min_messages 72 global g_rolling_window 73 num = self.msg_stat['i.num'] + 1 74 self.msg_stat['i.num'] = num 75 time_us = float(time_us) 76 if self.msg_stat['i.first'] == 0.0: 77 self.msg_stat['i.first'] = time_us 78 self.msg_stat['i.last'] = time_us 79 else: 80 self.msg_stat['i.last'] = time_us 81 if num > g_min_messages: 82 avg = (num * self.scalefactor) / (time_us - self.msg_stat['i.first']) 83 self.msg_stat['i.avg'] = avg 84 85 self.msg_stat['i.window'].append(time_us) 86 if len(self.msg_stat['i.window']) > g_rolling_window: 87 self.msg_stat['i.window'].popleft() 88 n = len(self.msg_stat['i.window']) 89 ravg = float(len(self.msg_stat['i.window']) * self.scalefactor) / \ 90 (self.msg_stat['i.window'][-1] - self.msg_stat['i.window'][0]) 91 if ravg > self.msg_stat['i.peak']: 92 self.msg_stat['i.peak'] = ravg 93 94 def outgoing_msg(self, size, time_us): 95 global g_min_messages 96 global g_rolling_window 97 num = self.msg_stat['o.num'] + 1 98 self.msg_stat['o.num'] = num 99 time_us = float(time_us) 100 if self.msg_stat['o.first'] == 0.0: 101 self.msg_stat['o.first'] = time_us 102 self.msg_stat['o.last'] = time_us 103 else: 104 self.msg_stat['o.last'] = time_us 105 if num > g_min_messages: 106 avg = (num * self.scalefactor) / (time_us - self.msg_stat['o.first']) 107 self.msg_stat['o.avg'] = avg 108 109 self.msg_stat['o.window'].append(time_us) 110 if len(self.msg_stat['o.window']) > g_rolling_window: 111 self.msg_stat['o.window'].popleft() 112 n = len(self.msg_stat['o.window']) 113 ravg = float(len(self.msg_stat['o.window']) * self.scalefactor) / \ 114 (self.msg_stat['o.window'][-1] - self.msg_stat['o.window'][0]) 115 if ravg > self.msg_stat['o.peak']: 116 self.msg_stat['o.peak'] = ravg 117 118 def nmsgs(self): 119 return self.msg_stat['o.num'], self.msg_stat['i.num'] 120 121 def recycled(self): 122 return len(self.pidset) 123 124 def label(self, timebase = 1000000.0): 125 oavg = float(self.msg_stat['o.avg']) / self.scalefactor 126 opeak = float(self.msg_stat['o.peak']) / self.scalefactor 127 oactive = self.msg_stat['o.last'] - self.msg_stat['o.first'] 128 iavg = float(self.msg_stat['i.avg']) / self.scalefactor 129 ipeak = float(self.msg_stat['i.peak']) / self.scalefactor 130 iactive = self.msg_stat['i.last'] - self.msg_stat['i.first'] 131 if timebase > 0.0: 132 oavg = oavg * timebase 133 opeak = opeak * timebase 134 oactive = oactive / timebase 135 iavg = iavg * timebase 136 ipeak = ipeak * timebase 137 iactive = iactive / timebase 138 return "{:s}\\no:{:d}/({:d}:{:.1f}s)/{:.1f}:{:.1f})\\ni:{:d}({:d}:{:.1f}s)/{:.1f}:{:.1f})\\nR:{:d}"\ 139 .format(self.nicename, \ 140 len(self.outgoing), self.msg_stat['o.num'], oactive, oavg, opeak, \ 141 len(self.incoming), self.msg_stat['i.num'], iactive, iavg, ipeak, \ 142 len(self.pidset)) 143 144class IPCEdge: 145 """ Class interface to an graph edge representing two services / programs 146 communicating via Mach IPC. Note that this communication could 147 use many different PIDs. The connected graph nodes (see IPCNode) 148 represent logical services on the system which could be instantiated 149 as many different PIDs depending on the lifecycle of the process 150 (dictated in part by launchd). 151 """ 152 153 F_TRACED = 0x00000100 154 F_COMPLEX = 0x00000200 155 F_OOLMEM = 0x00000400 156 F_VCPY = 0x00000800 157 F_PCPY = 0x00001000 158 F_SND64 = 0x00002000 159 F_RAISEIMP = 0x00004000 160 F_APP_SRC = 0x00008000 161 F_APP_DST = 0x00010000 162 F_DAEMON_SRC = 0x00020000 163 F_DAEMON_DST = 0x00040000 164 F_DST_NDFLTQ = 0x00080000 165 F_SRC_NDFLTQ = 0x00100000 166 F_DST_SONCE = 0x00200000 167 F_SRC_SONCE = 0x00400000 168 F_CHECKIN = 0x00800000 169 F_ONEWAY = 0x01000000 170 F_IOKIT = 0x02000000 171 F_SNDRCV = 0x04000000 172 F_DSTQFULL = 0x08000000 173 F_VOUCHER = 0x10000000 174 F_TIMER = 0x20000000 175 F_SEMA = 0x40000000 176 F_PORTS_MASK = 0x000000FF 177 178 DTYPES = [ 'std', 'xpc', 'iokit', 'std.reply', 'xpc.reply', 'iokit.reply' ] 179 DFLAVORS = [ 'std', 'ool', 'vcpy', 'iokit' ] 180 181 def __init__(self, src = IPCNode(), dst = IPCNode(), data = '0', flags = '0', time = 0.0): 182 self.src = src 183 self.dst = dst 184 self.flags = 0 185 self.dweight = 0 186 self.pweight = 0 187 self.weight = 0 188 self._data = { 'std':0, 'ool':0, 'vcpy':0, 'iokit':0 } 189 self._dtype = { 'std':0, 'xpc':0, 'iokit':0, 'std.reply':0, 'xpc.reply':0, 'iokit.reply':0 } 190 self._msgs = { 'std':0, 'ool':0, 'vcpy':0, 'iokit':0 } 191 self._mtype = { 'std':0, 'xpc':0, 'iokit':0, 'std.reply':0, 'xpc.reply':0, 'iokit.reply':0 } 192 self.ports = 0 193 self.task64 = False 194 self.task32 = False 195 self.src.add_outgoing_edge(self, time) 196 self.dst.add_incoming_edge(self, time) 197 self.addmsg(data, flags, time) 198 199 def ename(self): 200 return self.src.nname + " -> " + self.dst.nname 201 202 def msgdata(self): 203 return self._data, self._dtype 204 205 def data(self, flavor = None): 206 if not flavor: 207 return sum(self._data.itervalues()) 208 elif flavor in self._data: 209 return self._data[flavor] 210 else: 211 return 0 212 213 def dtype(self, type): 214 if not type: 215 return sum(self._dtype.itervalues()) 216 elif type in self._dtype: 217 return self._dtype[type] 218 else: 219 return 0 220 221 def msgs(self, flavor = None): 222 if not flavor: 223 return sum(self._msgs.itervalues()) 224 elif flavor in self._msgs: 225 return self._msgs[flavor] 226 else: 227 return 0 228 229 def mtype(self, type): 230 if not type: 231 return sum(self._mtype.itervalues()) 232 elif type in self._mtype: 233 return self._mtype[type] 234 else: 235 return 0 236 237 def selfedge(self): 238 if self.src.nname == self.dst.nname: 239 return True 240 return False 241 242 def addmsg(self, data_hex_str, flags_str, time): 243 global g_verbose 244 f = int(flags_str, 16) 245 self.flags |= f 246 df = {f:0 for f in self.DFLAVORS} 247 dt = {t:0 for t in self.DTYPES} 248 if not f & self.F_TRACED: 249 return df, dt 250 self.weight += 1 251 if f & self.F_SND64: 252 self.task64 = True 253 else: 254 self.task32 = True 255 if not f & self.F_COMPLEX: 256 self.dweight += 1 257 df['std'] = int(data_hex_str, 16) 258 if f & self.F_IOKIT: 259 df['iokit'] = df['std'] 260 df['std'] = 0 261 self._data['iokit'] += df['iokit'] 262 self._msgs['iokit'] += 1 263 else: 264 self._data['std'] += df['std'] 265 self._msgs['std'] += 1 266 elif f & self.F_OOLMEM: 267 self.dweight += 1 268 df['ool'] = int(data_hex_str, 16) 269 if f & self.F_IOKIT: 270 df['iokit'] = df['ool'] 271 df['ool'] = 0 272 self._data['iokit'] += df['iokit'] 273 self._msgs['iokit'] += 1 274 elif f & self.F_VCPY: 275 df['vcpy'] = df['ool'] 276 df['ool'] = 0 277 self._data['vcpy'] += df['vcpy'] 278 self._msgs['vcpy'] += 1 279 else: 280 self._data['ool'] += df['ool'] 281 self._msgs['ool'] += 1 282 # Complex messages can contain ports and data 283 if f & self.F_COMPLEX: 284 nports = f & self.F_PORTS_MASK 285 if nports > 0: 286 self.pweight += 1 287 self.ports += nports 288 dsize = sum(df.values()) 289 if f & self.F_DST_SONCE: 290 if f & self.F_IOKIT: 291 dt['iokit.reply'] = dsize 292 self._dtype['iokit.reply'] += dsize 293 self._mtype['iokit.reply'] += 1 294 elif f & (self.F_DST_NDFLTQ | self.F_SRC_NDFLTQ): 295 dt['xpc.reply'] = dsize 296 self._dtype['xpc.reply'] += dsize 297 self._mtype['xpc.reply'] += 1 298 else: 299 dt['std.reply'] = dsize 300 self._dtype['std.reply'] += dsize 301 self._mtype['std.reply'] += 1 302 elif f & self.F_IOKIT: 303 dt['iokit'] = dsize 304 self._dtype['iokit'] += dsize 305 self._mtype['iokit'] += 1 306 elif f & (self.F_DST_NDFLTQ | self.F_SRC_NDFLTQ): 307 dt['xpc'] = dsize 308 self._dtype['xpc'] += dsize 309 self._mtype['xpc'] += 1 310 else: 311 dt['std'] = dsize 312 self._dtype['std'] += dsize 313 self._mtype['std'] += 1 314 self.src.outgoing_msg(dsize, time) 315 self.dst.incoming_msg(dsize, time) 316 if g_verbose > 2: 317 sys.stderr.write(' {}->{} ({}/{}){}\r'.format(self.src.nname, self.dst.nname, df['ool'], df['std'], ' ' *50)) 318 return df, dt 319 320 def avgmsg(self): 321 avgsz = self.data() / self.dweight 322 msgs_with_data = self.dweight / self.weight 323 avgports = self.ports / self.pweight 324 msgs_with_ports = self.pweight / self.weight 325 return (avgsz, msgs_with_data, avgports, msgs_with_ports) 326 327 328class EdgeError(Exception): 329 """ IPCEdge exception class 330 """ 331 def __init__(self, edge, nm): 332 self.msg = "Edge {} (w:{}) didn't match incoming name {}!".format(edge.ename(), edge.weight, nm) 333 334class IPCGraph: 335 """ Class interface to a directed graph of IPC interconnectivity 336 """ 337 def __init__(self, name = '', timebase = 0.0): 338 global g_verbose 339 if len(name) == 0: 340 self.name = 'ipcgraph' 341 else: 342 self.name = name 343 if g_verbose > 0: 344 sys.stderr.write('Creating new IPCGraph named {}...\n'.format(self.name)) 345 self.nodes = {} 346 self.edges = {} 347 self.msgs = defaultdict(lambda: {f:0 for f in IPCEdge.DFLAVORS}) 348 self.msgtypes = defaultdict(lambda: {t:0 for t in IPCEdge.DTYPES}) 349 self.nmsgs = 0 350 self.totals = {} 351 self.maxdweight = 0 352 for f in IPCEdge.DFLAVORS: 353 self.totals['n'+f] = 0 354 self.totals['D'+f] = 0 355 if timebase and timebase > 0.0: 356 self.timebase = timebase 357 else: 358 self.timebase = 0.0 359 360 def __iter__(self): 361 return edges 362 363 def edgename(self, src, dst): 364 if src and dst: 365 return src.nname + ' -> ' + dst.nname 366 return '' 367 368 def addmsg(self, src_str, src_pid, dst_str, dst_pid, data_hex_str, flags_str, time): 369 src = None 370 dst = None 371 for k, v in self.nodes.iteritems(): 372 if not src and k == src_str: 373 src = v 374 if not dst and k == dst_str: 375 dst = v 376 if src and dst: 377 break 378 if not src: 379 src = IPCNode(src_str) 380 self.nodes[src_str] = src; 381 if not dst: 382 dst = IPCNode(dst_str) 383 self.nodes[dst_str] = dst 384 src.addpid(src_pid, time) 385 dst.addpid(dst_pid, time) 386 387 nm = self.edgename(src, dst) 388 msgdata = {} 389 msgDtype = {} 390 e = self.edges.get(nm) 391 if e != None: 392 if e.ename() != nm: 393 raise EdgeError(e,nm) 394 msgdata, msgDtype = e.addmsg(data_hex_str, flags_str, time) 395 else: 396 e = IPCEdge(src, dst, data_hex_str, flags_str, time) 397 msgdata, msgDtype = e.msgdata() 398 self.edges[nm] = e 399 400 if self.maxdweight < e.dweight: 401 self.maxdweight = e.dweight 402 403 if sum(msgdata.values()) == 0: 404 self.msgs[0]['std'] += 1 405 self.msgtypes[0]['std'] += 1 406 if not 'enames' in self.msgs[0]: 407 self.msgs[0]['enames'] = [ nm ] 408 elif not nm in self.msgs[0]['enames']: 409 self.msgs[0]['enames'].append(nm) 410 else: 411 for k,d in msgdata.iteritems(): 412 if d > 0: 413 self.msgs[d][k] += 1 414 self.totals['n'+k] += 1 415 self.totals['D'+k] += d 416 if not 'enames' in self.msgs[d]: 417 self.msgs[d]['enames'] = [ nm ] 418 elif not nm in self.msgs[d]['enames']: 419 self.msgs[d]['enames'].append(nm) 420 for k,d in msgDtype.iteritems(): 421 if d > 0: 422 self.msgtypes[d][k] += 1 423 self.nmsgs += 1 424 if self.nmsgs % 1024 == 0: 425 sys.stderr.write(" {:d}...\r".format(self.nmsgs)); 426 427 def print_dot_node(self, ofile, node): 428 omsgs, imsgs = node.nmsgs() 429 recycled = node.recycled() * 5 430 tcolor = 'black' 431 if recycled >= 50: 432 tcolor = 'white' 433 if recycled == 5: 434 bgcolor = 'white' 435 elif recycled <= 100: 436 bgcolor = 'grey{:d}'.format(100 - recycled) 437 else: 438 bgcolor = 'red' 439 ofile.write("\t{:s} [style=filled,fontcolor={:s},fillcolor={:s},label=\"{:s}\"];\n"\ 440 .format(node.nname, tcolor, bgcolor, node.label())) 441 442 def print_dot_edge(self, nm, edge, ofile): 443 #weight = 100 * edge.dweight / self.maxdweight 444 ##if weight < 1: 445 # weight = 1 446 weight = edge.dweight 447 penwidth = edge.weight / 512 448 if penwidth < 0.5: 449 penwidth = 0.5 450 if penwidth > 7.99: 451 penwidth = 8 452 attrs = "weight={},penwidth={}".format(round(weight,2), round(penwidth,2)) 453 454 if edge.flags & edge.F_RAISEIMP: 455 attrs += ",arrowhead=dot" 456 457 xpc = edge.dtype('xpc') + edge.dtype('xpc.reply') 458 iokit = edge.dtype('iokit') + edge.dtype('iokit.reply') 459 std = edge.dtype('std') + edge.dtype('std.reply') 460 if xpc > (iokit + std): 461 attrs += ',color=blue' 462 elif iokit > (std + xpc): 463 attrs += ',color=red' 464 465 if edge.data('vcpy') > (edge.data('ool') + edge.data('std')): 466 attrs += ',style="dotted"' 467 """ # block comment 468 ltype = [] 469 if edge.flags & (edge.F_DST_NDFLTQ | edge.F_SRC_NDFLTQ): 470 ltype.append('dotted') 471 if edge.flags & edge.F_APP_SRC: 472 ltype.append('bold') 473 if len(ltype) > 0: 474 attrs += ',style="' + reduce(lambda a, v: a + ',' + v, ltype) + '"' 475 476 if edge.data('ool') > (edge.data('std') + edge.data('vcpy')): 477 attrs += ",color=blue" 478 if edge.data('vcpy') > (edge.data('ool') + edge.data('std')): 479 attrs += ",color=green" 480 """ 481 482 ofile.write("\t{:s} [{:s}];\n".format(nm, attrs)) 483 484 def print_follow_graph(self, ofile, follow, visited = None): 485 ofile.write("digraph {:s} {{\n".format(self.name)) 486 ofile.write("\tsplines=ortho;\n") 487 if not visited: 488 visited = [] 489 for f in follow: 490 sys.stderr.write("following {}\n".format(f)) 491 lvl = 0 492 printedges = {} 493 while len(follow) > 0: 494 cnodes = [] 495 for nm, e in self.edges.iteritems(): 496 nicename = e.src.nicename 497 # Find all nodes to which 'follow' nodes communicate 498 if e.src.nicename in follow: 499 printedges[nm] = e 500 if not e.selfedge() and not e.dst in cnodes: 501 cnodes.append(e.dst) 502 visited.extend(follow) 503 follow = [] 504 for n in cnodes: 505 if not n.nicename in visited: 506 follow.append(n.nicename) 507 lvl += 1 508 for f in follow: 509 sys.stderr.write("{}following {}\n".format(' |--'*lvl, f)) 510 # END: while len(follow) 511 for k, v in self.nodes.iteritems(): 512 if v.nicename in visited: 513 self.print_dot_node(ofile, v) 514 for nm, edge in printedges.iteritems(): 515 self.print_dot_edge(nm, edge, ofile) 516 ofile.write("}\n\n") 517 518 def print_graph(self, ofile, follow): 519 ofile.write("digraph {:s} {{\n".format(self.name)) 520 ofile.write("\tsplines=ortho;\n") 521 for k, v in self.nodes.iteritems(): 522 self.print_dot_node(ofile, v) 523 for nm, edge in self.edges.iteritems(): 524 self.print_dot_edge(nm, edge, ofile) 525 ofile.write("}\n\n") 526 527 def print_nodegrid(self, ofile, type='msg', dfilter=None): 528 showdata = False 529 dfname = dfilter 530 if not dfname: 531 dfname = 'all' 532 if type == 'data': 533 showdata = True 534 ofile.write("{} Data sent between nodes.\nRow == SOURCE; Column == DESTINATION\n".format(dfname)) 535 else: 536 ofile.write("{} Messages sent between nodes.\nRow == SOURCE; Column == DESTINATION\n".format(dfname)) 537 538 if not dfilter: 539 dfilter = IPCEdge.DTYPES 540 ofile.write(' ,' + ','.join(self.nodes.keys()) + '\n') 541 for snm, src in self.nodes.iteritems(): 542 odata = [] 543 for dnm, dst in self.nodes.iteritems(): 544 enm = self.edgename(src, dst) 545 e = self.edges.get(enm) 546 if e and enm in src.outgoing.keys(): 547 if showdata: 548 dsize = reduce(lambda accum, t: accum + e.dtype(t), dfilter, 0) 549 odata.append('{:d}'.format(dsize)) 550 else: 551 nmsg = reduce(lambda accum, t: accum + e.mtype(t), dfilter, 0) 552 odata.append('{:d}'.format(nmsg)) 553 else: 554 odata.append('0') 555 ofile.write(snm + ',' + ','.join(odata) + '\n') 556 557 def print_datasummary(self, ofile): 558 m = {} 559 for type in IPCEdge.DTYPES: 560 m[type] = [0, 0] 561 for k, v in self.edges.iteritems(): 562 for t in IPCEdge.DTYPES: 563 m[t][0] += v.mtype(t) 564 m[t][1] += v.dtype(t) 565 tdata = 0 566 tmsgs = 0 567 for f in IPCEdge.DFLAVORS: 568 tdata += self.totals['D'+f] 569 tmsgs += self.totals['n'+f] 570 # we account for 0-sized messages differently 571 tmsgs += self.msgs[0]['std'] 572 ofile.write("Nodes:{:d}\nEdges:{:d}\n".format(len(self.nodes),len(self.edges))) 573 ofile.write("Total Messages,{}\nTotal Data,{}\n".format(tmsgs, tdata)) 574 ofile.write("Flavor,Messages,Data,\n") 575 for f in IPCEdge.DFLAVORS: 576 ofile.write("{:s},{:d},{:d}\n".format(f, self.totals['n'+f], self.totals['D'+f])) 577 ofile.write("Style,Messages,Data,\n") 578 for t in IPCEdge.DTYPES: 579 ofile.write("{:s},{:d},{:d}\n".format(t, m[t][0], m[t][1])) 580 581 def print_freqdata(self, ofile, gnuplot = False): 582 flavoridx = {} 583 ostr = "Message Size" 584 idx = 1 585 for f in IPCEdge.DFLAVORS: 586 ostr += ',{fmt:s} Freq,{fmt:s} CDF,{fmt:s} Data CDF,{fmt:s} Cumulative Data'.format(fmt=f) 587 idx += 1 588 flavoridx[f] = idx 589 idx += 3 590 ostr += ',#Unique SVC pairs\n' 591 ofile.write(ostr) 592 593 lastmsg = 0 594 maxmsgs = {} 595 totalmsgs = {} 596 Tdata = {} 597 for f in IPCEdge.DFLAVORS: 598 maxmsgs[f] = 0 599 totalmsgs[f] = 0 600 Tdata[f] = 0 601 602 for k, v in sorted(self.msgs.iteritems()): 603 lastmsg = k 604 _nmsgs = {} 605 for f in IPCEdge.DFLAVORS: 606 _nmsgs[f] = v[f] 607 if v[f] > maxmsgs[f]: 608 maxmsgs[f] = v[f] 609 if k > 0: 610 Tdata[f] += v[f] * k 611 totalmsgs[f] += v[f] 612 613 cdf = {f:0 for f in IPCEdge.DFLAVORS} 614 dcdf = {f:0 for f in IPCEdge.DFLAVORS} 615 if k > 0: # Only use messages with data size > 0 616 for f in IPCEdge.DFLAVORS: 617 if self.totals['n'+f] > 0: 618 cdf[f] = int(100 * totalmsgs[f] / self.totals['n'+f]) 619 if self.totals['D'+f] > 0: 620 dcdf[f] = int(100 * Tdata[f] / self.totals['D'+f]) 621 622 ostr = "{:d}".format(k) 623 for f in IPCEdge.DFLAVORS: 624 ostr += ",{:d},{:d},{:d},{:d}".format(_nmsgs[f],cdf[f],dcdf[f],Tdata[f]) 625 ostr += ",{:d}\n".format(len(v['enames'])) 626 ofile.write(ostr) 627 628 if not gnuplot: 629 return 630 631 colors = [ 'blue', 'red', 'green', 'black', 'grey', 'yellow' ] 632 idx = 0 633 flavorcolor = {} 634 maxdata = 0 635 maxmsg = max(maxmsgs.values()) 636 for f in IPCEdge.DFLAVORS: 637 flavorcolor[f] = colors[idx] 638 if self.totals['D'+f] > maxdata: 639 maxdata = self.totals['D'+f] 640 idx += 1 641 642 sys.stderr.write("Creating GNUPlot...\n") 643 644 cdf_data_fmt = """\ 645 set terminal postscript eps enhanced color solid 'Courier' 12 646 set border 3 647 set size 1.5, 1.5 648 set xtics nomirror 649 set ytics nomirror 650 set xrange [1:2048] 651 set yrange [0:100] 652 set ylabel font 'Courier,14' "Total Message CDF\\n(% of total number of messages)" 653 set xlabel font 'Courier,14' "Message Size (bytes)" 654 set datafile separator "," 655 set ytics ( '0' 0, '10' 10, '20' 20, '30' 30, '40' 40, '50' 50, '60' 60, '70' 70, '80' 80, '90' 90, '100' 100) 656 plot """ 657 plots = [] 658 for f in IPCEdge.DFLAVORS: 659 plots.append("'{{csvfile:s}}' using 1:{:d} title '{:s} Messages' with lines lw 2 lt 1 lc rgb \"{:s}\"".format(flavoridx[f]+1, f, flavorcolor[f])) 660 cdf_data_fmt += ', \\\n'.join(plots) 661 662 dcdf_data_fmt = """\ 663 set terminal postscript eps enhanced color solid 'Courier' 12 664 set border 3 665 set size 1.5, 1.5 666 set xtics nomirror 667 set ytics nomirror 668 set xrange [1:32768] 669 set yrange [0:100] 670 set ylabel font 'Courier,14' "Total Data CDF\\n(% of total data transmitted)" 671 set xlabel font 'Courier,14' "Message Size (bytes)" 672 set datafile separator "," 673 set ytics ( '0' 0, '10' 10, '20' 20, '30' 30, '40' 40, '50' 50, '60' 60, '70' 70, '80' 80, '90' 90, '100' 100) 674 plot """ 675 plots = [] 676 for f in IPCEdge.DFLAVORS: 677 plots.append("'{{csvfile:s}}' using 1:{:d} title '{:s} Message Data' with lines lw 2 lt 1 lc rgb \"{:s}\"".format(flavoridx[f]+2, f, flavorcolor[f])) 678 dcdf_data_fmt += ', \\\n'.join(plots) 679 680 freq_data_fmt = """\ 681 set terminal postscript eps enhanced color solid 'Courier' 12 682 set size 1.5, 1.5 683 set xrange [1:32768] 684 set yrange [0:9000] 685 set x2range [1:32768] 686 set y2range [0:{maxdata:d}] 687 set xtics nomirror 688 set ytics nomirror 689 set y2tics 690 set autoscale y2 691 set grid x y2 692 set ylabel font 'Courier,14' "Number of Messages" 693 set y2label font 'Courier,14' "Data Transferred (bytes)" 694 set xlabel font 'Courier,14' "Message Size (bytes)" 695 set datafile separator "," 696 set tics out 697 set boxwidth 1 698 set style fill solid 699 plot """ 700 plots = [] 701 for f in IPCEdge.DFLAVORS: 702 plots.append("'{{csvfile:s}}' using 1:{:d} axes x1y1 title '{:s} Messages' with boxes lt 1 lc rgb \"{:s}\"".format(flavoridx[f], f, flavorcolor[f])) 703 plots.append("'{{csvfile:s}}' using 1:{:d} axes x2y2 title '{:s} Data' with line lt 1 lw 2 lc rgb \"{:s}\"".format(flavoridx[f]+3, f, flavorcolor[f])) 704 freq_data_fmt += ', \\\n'.join(plots) 705 try: 706 new_file = re.sub(r'(.*)\.\w+$', r'\1_cdf.plot', ofile.name) 707 sys.stderr.write("\t{:s}...\n".format(new_file)) 708 plotfile = open(new_file, 'w') 709 plotfile.write(cdf_data_fmt.format(lastmsg=lastmsg, maxdata=maxdata, maxmsg=maxmsg, csvfile=ofile.name)) 710 plotfile.flush() 711 plotfile.close() 712 713 new_file = re.sub(r'(.*)\.\w+$', r'\1_dcdf.plot', ofile.name) 714 sys.stderr.write("\t{:s}...\n".format(new_file)) 715 plotfile = open(new_file, 'w') 716 plotfile.write(dcdf_data_fmt.format(lastmsg=lastmsg, maxdata=maxdata, maxmsg=maxmsg, csvfile=ofile.name)) 717 plotfile.flush() 718 plotfile.close() 719 720 new_file = re.sub(r'(.*)\.\w+$', r'\1_hist.plot', ofile.name) 721 sys.stderr.write("\t{:s}...\n".format(new_file)) 722 plotfile = open(new_file, 'w') 723 plotfile.write(freq_data_fmt.format(lastmsg=lastmsg, maxdata=maxdata, maxmsg=maxmsg, csvfile=ofile.name)) 724 plotfile.flush() 725 plotfile.close() 726 except: 727 sys.stderr.write("\nFailed to write gnuplot script!\n"); 728 return 729 730 731def convert_raw_tracefiles(args): 732 if not args.raw or len(args.raw) < 1: 733 return 734 735 if not args.tracefile: 736 args.tracefile = [] 737 738 for rawfile in args.raw: 739 sys.stderr.write("Converting RAW tracefile '{:s}'...\n".format(rawfile.name)) 740 if args.tbfreq and len(args.tbfreq) > 0: 741 args.tbfreq = " -F " + args.tbfreq 742 else: 743 args.tbfreq = "" 744 tfile = re.sub(r'(.*)(\.\w+)*$', r'\1.ascii', rawfile.name) 745 cmd = 'trace -R {:s}{:s} -o {:s}'.format(rawfile.name, args.tbfreq, tfile) 746 if args.tracecodes and len(args.tracecodes) > 0: 747 cmd += " -N {}".format(args.tracecodes[0]) 748 elif os.path.isfile('bsd/kern/trace.codes'): 749 cmd += " -N bsd/kern/trace.codes" 750 if args.traceargs and len(args.traceargs) > 0: 751 cmd += ' '.join(args.traceargs) 752 (ret, outstr) = RunCommand(cmd) 753 if ret != 0: 754 os.stderr.write("Couldn't convert raw trace file. ret=={:d}\nE: {:s}\n".format(ret, outstr)) 755 sys.exit(ret) 756 757 if not os.path.isfile(tfile): 758 sys.stderr.write("Failure to convert raw trace file '{:s}'\ncmd: '{:s}'\n".format(args.raw[0].name, cmd)) 759 sys.exit(1) 760 args.tracefile.append(open(tfile, 'r')) 761 # END: for rawfile in args.raw 762 763 764def parse_tracefile_line(line, exclude, include, exflags, incflags, active_proc, graph, base=16): 765 val = line.split() 766 if len(val) < 10: 767 return 768 if val[2] == "proc_exec" or val[2] == "TRACE_DATA_EXEC": 769 pid = int(val[3], base) 770 active_proc[pid] = val[9] 771 if val[2] == "MACH_IPC_kmsg_info": 772 sendpid = int(val[3], base) 773 destpid = int(val[4], base) 774 if sendpid == 0: 775 src = "kernel_task" 776 elif sendpid in active_proc: 777 src = active_proc[sendpid] 778 else: 779 src = "{:d}".format(sendpid) 780 if destpid == 0: 781 dst = "kernel_task" 782 elif destpid in active_proc: 783 dst = active_proc[destpid] 784 else: 785 dst = "{:d}".format(destpid) 786 if exclude and len(exclude) > 0 and (src in exclude or dst in exclude): 787 return 788 if include and len(include) > 0 and (not (src in include or dst in include)): 789 return 790 flags = int(val[6], 16) 791 if exflags or incflags: 792 if exflags and (flags & int(exflags[0], 0)): 793 return 794 if incflags and (flags & int(incflags[0], 0)) != int(incflags[0], 0): 795 return 796 # create a graph edge 797 if (flags & IPCEdge.F_TRACED): 798 graph.addmsg(src, sendpid, dst, destpid, val[5], val[6], float(val[0])) 799 # END: MACH_IPC_kmsg_info 800 801# 802# Main 803# 804def main(argv=sys.argv): 805 """ Main program entry point. 806 807 Trace file output lines look like this: 808 {abstime} {delta} MACH_IPC_kmsg_info {src_pid} {dst_pid} {msg_len} {flags} {threadid} {cpu} {proc_name} 809 e.g. 810 4621921.2 33.8(0.0) MACH_IPC_kmsg_info ac 9d c 230002 b2e 1 MobileMail 811 812 Or like this: 813 {abstime} {delta} proc_exec {pid} 0 0 0 {threadid} {cpu} {proc_name} 814 e.g. 815 4292212.3 511.2 proc_exec c8 0 0 0 b44 0 voiced 816 """ 817 global g_verbose 818 819 parser = argparse.ArgumentParser(description='Parse an XNU Mach IPC kmsg ktrace file') 820 821 # output a DOT formatted graph file 822 parser.add_argument('--printgraph', '-g', dest='graph', default=None, type=argparse.FileType('w'), help='Output a DOT connectivity graph from the trace data') 823 parser.add_argument('--graphname', dest='name', default='ipcgraph', help='A name for the DOT graph output') 824 parser.add_argument('--graphfollow', dest='follow', nargs='+', metavar='NAME', help='Graph only the transitive closure of services / processes which communicate with the given service(s)') 825 826 # output a CDF of message data 827 parser.add_argument('--printfreq', '-f', dest='freq', default=None, type=argparse.FileType('w'), help='Output a frequency distribution of message data (in CSV format)') 828 parser.add_argument('--gnuplot', dest='gnuplot', action='store_true', help='Write out a gnuplot file along with the frequency distribution data') 829 830 # output a simple summary of message data 831 parser.add_argument('--printsummary', '-s', dest='summary', default=None, type=argparse.FileType('w'), help='Output a summary of all messages in the trace data') 832 833 # Output a CSV grid of node data/messages 834 parser.add_argument('--printnodegrid', '-n', dest='nodegrid', default=None, type=argparse.FileType('w'), help='Output a CSV grid of all messages/data sent between nodes (defaults to # messages)') 835 parser.add_argument('--ngridtype', dest='ngridtype', default=None, choices=['msgs', 'data'], help='Used with the --printnodegrid argument, this option control whether the grid will be # of messages sent between nodes, or amount of data sent between nodes') 836 parser.add_argument('--ngridfilter', dest='ngridfilter', default=None, nargs='+', choices=IPCEdge.DTYPES, help='Used with the --printnodegrid argument, this option controls the type of messages or data counted') 837 838 parser.add_argument('--raw', '-R', dest='raw', nargs='+', type=argparse.FileType('r'), metavar='tracefile', help='Process a raw tracefile using the "trace" utility on the host. This requires an ssh connection to the device, or a manual specification of the tbfrequency.') 839 parser.add_argument('--tbfreq', '-T', dest='tbfreq', default=None, help='The value of sysctl hw.tbfrequency run on the device') 840 parser.add_argument('--device', '-D', dest='device', nargs=1, metavar='DEV', help='The name of the iOS device reachable via "ssh DEV"') 841 parser.add_argument('--tracecodes', '-N', dest='tracecodes', nargs=1, metavar='TRACE.CODES', help='Path to a custom trace.codes file. By default, the script will look for bsd/kern/trace.codes from the current directory)') 842 parser.add_argument('--traceargs', dest='traceargs', nargs='+', metavar='TRACE_OPT', help='Extra options to the "trace" program run on the host') 843 844 parser.add_argument('--psfile', dest='psfile', nargs='+', type=argparse.FileType('r'), help='Process list file output by ios_trace_ipc.sh') 845 846 parser.add_argument('--exclude', dest='exclude', metavar='NAME', nargs='+', help='List of services to exclude from processing. Any messages sent to or originating from these services will be discarded.') 847 parser.add_argument('--include', dest='include', metavar='NAME', nargs='+', help='List of services to include in processing. Only messages sent to or originating from these services will be processed.') 848 parser.add_argument('--exflags', dest='exflags', metavar='0xFLAGS', nargs=1, help='Messages with any of these flags bits set will be discarded') 849 parser.add_argument('--incflags', dest='incflags', metavar='0xFLAGS', nargs=1, type=int, help='Only messages with all of these flags bits set will be processed') 850 851 parser.add_argument('--verbose', '-v', dest='verbose', action='count', help='be verbose (can be used multiple times)') 852 parser.add_argument('tracefile', nargs='*', type=argparse.FileType('r'), help='Input trace file') 853 854 args = parser.parse_args() 855 856 g_verbose = args.verbose 857 858 if not args.graph and not args.freq and not args.summary and not args.nodegrid: 859 sys.stderr.write("Please select at least one output format: [-gfsn] {file}\n") 860 sys.exit(1) 861 862 convert_raw_tracefiles(args) 863 864 graph = IPCGraph(args.name, args.tbfreq) 865 866 nfiles = len(args.tracefile) 867 idx = 0 868 while idx < nfiles: 869 active_proc = {} 870 # Parse a ps output file (generated by ios_trace_ipc.sh) 871 # This pre-fills the active_proc list 872 if args.psfile and len(args.psfile) > idx: 873 sys.stderr.write("Parsing {:s}...\n".format(args.psfile[idx].name)) 874 for line in args.psfile[idx]: 875 if line.strip() == '': 876 continue 877 parse_tracefile_line(line.strip(), None, None, None, None, active_proc, graph, 10) 878 # END: for line in psfile 879 880 sys.stderr.write("Parsing {:s}...\n".format(args.tracefile[idx].name)) 881 for line in args.tracefile[idx]: 882 if line.strip() == '': 883 continue 884 parse_tracefile_line(line.strip(), args.exclude, args.include, args.exflags, args.incflags, active_proc, graph) 885 # END: for line in tracefile 886 idx += 1 887 # END: foreach tracefile/psfile 888 889 if args.graph: 890 if args.follow and len(args.follow) > 0: 891 sys.stderr.write("Writing follow-graph to {:s}...\n".format(args.graph.name)) 892 graph.print_follow_graph(args.graph, args.follow) 893 else: 894 sys.stderr.write("Writing graph output to {:s}...\n".format(args.graph.name)) 895 graph.print_graph(args.graph, args.follow) 896 if args.freq: 897 sys.stderr.write("Writing CDF data to {:s}...\n".format(args.freq.name)) 898 graph.print_freqdata(args.freq, args.gnuplot) 899 if args.summary: 900 sys.stderr.write("Writing summary data to {:s}...\n".format(args.summary.name)) 901 graph.print_datasummary(args.summary) 902 if args.nodegrid: 903 nm = args.ngridtype 904 sys.stderr.write("Writing node grid data to {:s}...]\n".format(args.nodegrid.name)) 905 graph.print_nodegrid(args.nodegrid, args.ngridtype, args.ngridfilter) 906 907if __name__ == '__main__': 908 sys.exit(main()) 909