tools/trace/parse_ipc_trace.py

   1 #!/usr/bin/env python
   2 # machtrace_parse.py
   3 # Parse Mach IPC kmsg data trace from XNU
   4 #
   5 # Jeremy C. Andrus <jeremy_andrus@apple.com>
   6 #
   7 from __future__ import division
   8
   9 import argparse
  10 import subprocess
  11 import sys
  12 import re
  13 from collections import deque
  14
  15 import os.path
  16
  17 from collections import defaultdict
  18
  19 g_verbose = 0
  20 g_min_messages = 10
  21 g_rolling_window = 200
  22
  23 def 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
  40 class 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
 144 class 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
 328 class 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
 334 class 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
 731 def 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
 764 def 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 #
 804 def 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
 907 if __name__ == '__main__':
 908     sys.exit(main())