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         #ltype = []
 468         #if edge.flags & (edge.F_DST_NDFLTQ | edge.F_SRC_NDFLTQ):
 469         #    ltype.append('dotted')
 470         #if edge.flags & edge.F_APP_SRC:
 471         #    ltype.append('bold')
 472         #if len(ltype) > 0:
 473         #    attrs += ',style="' + reduce(lambda a, v: a + ',' + v, ltype) + '"'
 474         #
 475         #if edge.data('ool') > (edge.data('std') + edge.data('vcpy')):
 476         #    attrs += ",color=blue"
 477         #if edge.data('vcpy') > (edge.data('ool') + edge.data('std')):
 478         #    attrs += ",color=green"
 479
 480         ofile.write("\t{:s} [{:s}];\n".format(nm, attrs))
 481
 482     def print_follow_graph(self, ofile, follow, visited = None):
 483         ofile.write("digraph {:s} {{\n".format(self.name))
 484         ofile.write("\tsplines=ortho;\n")
 485         if not visited:
 486             visited = []
 487         for f in follow:
 488             sys.stderr.write("following {}\n".format(f))
 489         lvl = 0
 490         printedges = {}
 491         while len(follow) > 0:
 492             cnodes = []
 493             for nm, e in self.edges.iteritems():
 494                 nicename = e.src.nicename
 495                 # Find all nodes to which 'follow' nodes communicate
 496                 if e.src.nicename in follow:
 497                     printedges[nm] = e
 498                     if not e.selfedge() and not e.dst in cnodes:
 499                         cnodes.append(e.dst)
 500             visited.extend(follow)
 501             follow = []
 502             for n in cnodes:
 503                 if not n.nicename in visited:
 504                     follow.append(n.nicename)
 505             lvl += 1
 506             for f in follow:
 507                 sys.stderr.write("{}following {}\n".format('  |--'*lvl, f))
 508         # END: while len(follow)
 509         for k, v in self.nodes.iteritems():
 510             if v.nicename in visited:
 511                 self.print_dot_node(ofile, v)
 512         for nm, edge in printedges.iteritems():
 513             self.print_dot_edge(nm, edge, ofile)
 514         ofile.write("}\n\n")
 515
 516     def print_graph(self, ofile, follow):
 517         ofile.write("digraph {:s} {{\n".format(self.name))
 518         ofile.write("\tsplines=ortho;\n")
 519         for k, v in self.nodes.iteritems():
 520             self.print_dot_node(ofile, v)
 521         for nm, edge in self.edges.iteritems():
 522             self.print_dot_edge(nm, edge, ofile)
 523         ofile.write("}\n\n")
 524
 525     def print_nodegrid(self, ofile, type='msg', dfilter=None):
 526         showdata = False
 527         dfname = dfilter
 528         if not dfname:
 529             dfname = 'all'
 530         if type == 'data':
 531             showdata = True
 532             ofile.write("{} Data sent between nodes.\nRow == SOURCE; Column == DESTINATION\n".format(dfname))
 533         else:
 534             ofile.write("{} Messages sent between nodes.\nRow == SOURCE; Column == DESTINATION\n".format(dfname))
 535
 536         if not dfilter:
 537             dfilter = IPCEdge.DTYPES
 538         ofile.write(' ,' + ','.join(self.nodes.keys()) + '\n')
 539         for snm, src in self.nodes.iteritems():
 540             odata = []
 541             for dnm, dst in self.nodes.iteritems():
 542                 enm = self.edgename(src, dst)
 543                 e = self.edges.get(enm)
 544                 if e and enm in src.outgoing.keys():
 545                     if showdata:
 546                         dsize = reduce(lambda accum, t: accum + e.dtype(t), dfilter, 0)
 547                         odata.append('{:d}'.format(dsize))
 548                     else:
 549                         nmsg = reduce(lambda accum, t: accum + e.mtype(t), dfilter, 0)
 550                         odata.append('{:d}'.format(nmsg))
 551                 else:
 552                     odata.append('0')
 553             ofile.write(snm + ',' + ','.join(odata) + '\n')
 554
 555     def print_datasummary(self, ofile):
 556         m = {}
 557         for type in IPCEdge.DTYPES:
 558             m[type] = [0, 0]
 559         for k, v in self.edges.iteritems():
 560             for t in IPCEdge.DTYPES:
 561                 m[t][0] += v.mtype(t)
 562                 m[t][1] += v.dtype(t)
 563         tdata = 0
 564         tmsgs = 0
 565         for f in IPCEdge.DFLAVORS:
 566             tdata += self.totals['D'+f]
 567             tmsgs += self.totals['n'+f]
 568         # we account for 0-sized messages differently
 569         tmsgs += self.msgs[0]['std']
 570         ofile.write("Nodes:{:d}\nEdges:{:d}\n".format(len(self.nodes),len(self.edges)))
 571         ofile.write("Total Messages,{}\nTotal Data,{}\n".format(tmsgs, tdata))
 572         ofile.write("Flavor,Messages,Data,\n")
 573         for f in IPCEdge.DFLAVORS:
 574             ofile.write("{:s},{:d},{:d}\n".format(f, self.totals['n'+f], self.totals['D'+f]))
 575         ofile.write("Style,Messages,Data,\n")
 576         for t in IPCEdge.DTYPES:
 577             ofile.write("{:s},{:d},{:d}\n".format(t, m[t][0], m[t][1]))
 578
 579     def print_freqdata(self, ofile, gnuplot = False):
 580         flavoridx = {}
 581         ostr = "Message Size"
 582         idx = 1
 583         for f in IPCEdge.DFLAVORS:
 584             ostr += ',{fmt:s} Freq,{fmt:s} CDF,{fmt:s} Data CDF,{fmt:s} Cumulative Data'.format(fmt=f)
 585             idx += 1
 586             flavoridx[f] = idx
 587             idx += 3
 588         ostr += ',#Unique SVC pairs\n'
 589         ofile.write(ostr)
 590
 591         lastmsg = 0
 592         maxmsgs = {}
 593         totalmsgs = {}
 594         Tdata = {}
 595         for f in IPCEdge.DFLAVORS:
 596             maxmsgs[f] = 0
 597             totalmsgs[f] = 0
 598             Tdata[f] = 0
 599
 600         for k, v in sorted(self.msgs.iteritems()):
 601             lastmsg = k
 602             _nmsgs = {}
 603             for f in IPCEdge.DFLAVORS:
 604                 _nmsgs[f] = v[f]
 605                 if v[f] > maxmsgs[f]:
 606                     maxmsgs[f] = v[f]
 607                 if k > 0:
 608                     Tdata[f] += v[f] * k
 609                     totalmsgs[f] += v[f]
 610
 611             cdf = {f:0 for f in IPCEdge.DFLAVORS}
 612             dcdf = {f:0 for f in IPCEdge.DFLAVORS}
 613             if k > 0: # Only use messages with data size > 0
 614                 for f in IPCEdge.DFLAVORS:
 615                     if self.totals['n'+f] > 0:
 616                         cdf[f] = int(100 * totalmsgs[f] / self.totals['n'+f])
 617                     if self.totals['D'+f] > 0:
 618                         dcdf[f] = int(100 * Tdata[f] / self.totals['D'+f])
 619
 620             ostr = "{:d}".format(k)
 621             for f in IPCEdge.DFLAVORS:
 622                 ostr += ",{:d},{:d},{:d},{:d}".format(_nmsgs[f],cdf[f],dcdf[f],Tdata[f])
 623             ostr += ",{:d}\n".format(len(v['enames']))
 624             ofile.write(ostr)
 625
 626         if not gnuplot:
 627             return
 628
 629         colors = [ 'blue', 'red', 'green', 'black', 'grey', 'yellow' ]
 630         idx = 0
 631         flavorcolor = {}
 632         maxdata = 0
 633         maxmsg = max(maxmsgs.values())
 634         for f in IPCEdge.DFLAVORS:
 635             flavorcolor[f] = colors[idx]
 636             if self.totals['D'+f] > maxdata:
 637                 maxdata = self.totals['D'+f]
 638             idx += 1
 639
 640         sys.stderr.write("Creating GNUPlot...\n")
 641
 642         cdf_data_fmt = """\
 643         set terminal postscript eps enhanced color solid 'Courier' 12
 644         set border 3
 645         set size 1.5, 1.5
 646         set xtics nomirror
 647         set ytics nomirror
 648         set xrange [1:2048]
 649         set yrange [0:100]
 650         set ylabel font 'Courier,14' "Total Message CDF\\n(% of total number of messages)"
 651         set xlabel font 'Courier,14' "Message Size (bytes)"
 652         set datafile separator ","
 653         set ytics ( '0' 0, '10' 10, '20' 20, '30' 30, '40' 40, '50' 50, '60' 60, '70' 70, '80' 80, '90' 90, '100' 100)
 654         plot """
 655         plots = []
 656         for f in IPCEdge.DFLAVORS:
 657             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]))
 658         cdf_data_fmt += ', \\\n'.join(plots)
 659
 660         dcdf_data_fmt = """\
 661         set terminal postscript eps enhanced color solid 'Courier' 12
 662         set border 3
 663         set size 1.5, 1.5
 664         set xtics nomirror
 665         set ytics nomirror
 666         set xrange [1:32768]
 667         set yrange [0:100]
 668         set ylabel font 'Courier,14' "Total Data CDF\\n(% of total data transmitted)"
 669         set xlabel font 'Courier,14' "Message Size (bytes)"
 670         set datafile separator ","
 671         set ytics ( '0' 0, '10' 10, '20' 20, '30' 30, '40' 40, '50' 50, '60' 60, '70' 70, '80' 80, '90' 90, '100' 100)
 672         plot """
 673         plots = []
 674         for f in IPCEdge.DFLAVORS:
 675             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]))
 676         dcdf_data_fmt += ', \\\n'.join(plots)
 677
 678         freq_data_fmt = """\
 679         set terminal postscript eps enhanced color solid 'Courier' 12
 680         set size 1.5, 1.5
 681         set xrange [1:32768]
 682         set yrange [0:9000]
 683         set x2range [1:32768]
 684         set y2range [0:{maxdata:d}]
 685         set xtics nomirror
 686         set ytics nomirror
 687         set y2tics
 688         set autoscale y2
 689         set grid x y2
 690         set ylabel font 'Courier,14' "Number of Messages"
 691         set y2label font 'Courier,14' "Data Transferred (bytes)"
 692         set xlabel font 'Courier,14' "Message Size (bytes)"
 693         set datafile separator ","
 694         set tics out
 695         set boxwidth 1
 696         set style fill solid
 697         plot """
 698         plots = []
 699         for f in IPCEdge.DFLAVORS:
 700             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]))
 701             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]))
 702         freq_data_fmt += ', \\\n'.join(plots)
 703         try:
 704             new_file = re.sub(r'(.*)\.\w+$', r'\1_cdf.plot', ofile.name)
 705             sys.stderr.write("\t{:s}...\n".format(new_file))
 706             plotfile = open(new_file, 'w')
 707             plotfile.write(cdf_data_fmt.format(lastmsg=lastmsg, maxdata=maxdata, maxmsg=maxmsg, csvfile=ofile.name))
 708             plotfile.flush()
 709             plotfile.close()
 710
 711             new_file = re.sub(r'(.*)\.\w+$', r'\1_dcdf.plot', ofile.name)
 712             sys.stderr.write("\t{:s}...\n".format(new_file))
 713             plotfile = open(new_file, 'w')
 714             plotfile.write(dcdf_data_fmt.format(lastmsg=lastmsg, maxdata=maxdata, maxmsg=maxmsg, csvfile=ofile.name))
 715             plotfile.flush()
 716             plotfile.close()
 717
 718             new_file = re.sub(r'(.*)\.\w+$', r'\1_hist.plot', ofile.name)
 719             sys.stderr.write("\t{:s}...\n".format(new_file))
 720             plotfile = open(new_file, 'w')
 721             plotfile.write(freq_data_fmt.format(lastmsg=lastmsg, maxdata=maxdata, maxmsg=maxmsg, csvfile=ofile.name))
 722             plotfile.flush()
 723             plotfile.close()
 724         except:
 725             sys.stderr.write("\nFailed to write gnuplot script!\n");
 726         return
 727
 728
 729 def convert_raw_tracefiles(args):
 730     if not args.raw or len(args.raw) < 1:
 731         return
 732
 733     if not args.tracefile:
 734         args.tracefile = []
 735
 736     for rawfile in args.raw:
 737         sys.stderr.write("Converting RAW tracefile '{:s}'...\n".format(rawfile.name))
 738         if args.tbfreq and len(args.tbfreq) > 0:
 739             args.tbfreq = " -F " + args.tbfreq
 740         else:
 741             args.tbfreq = ""
 742         tfile = re.sub(r'(.*)(\.\w+)*$', r'\1.ascii', rawfile.name)
 743         cmd = 'trace -R {:s}{:s} -o {:s}'.format(rawfile.name, args.tbfreq, tfile)
 744         if args.tracecodes and len(args.tracecodes) > 0:
 745             cmd += " -N {}".format(args.tracecodes[0])
 746         elif os.path.isfile('bsd/kern/trace.codes'):
 747             cmd += " -N bsd/kern/trace.codes"
 748         if args.traceargs and len(args.traceargs) > 0:
 749             cmd += ' '.join(args.traceargs)
 750         (ret, outstr) = RunCommand(cmd)
 751         if ret != 0:
 752             os.stderr.write("Couldn't convert raw trace file. ret=={:d}\nE: {:s}\n".format(ret, outstr))
 753             sys.exit(ret)
 754
 755         if not os.path.isfile(tfile):
 756             sys.stderr.write("Failure to convert raw trace file '{:s}'\ncmd: '{:s}'\n".format(args.raw[0].name, cmd))
 757             sys.exit(1)
 758         args.tracefile.append(open(tfile, 'r'))
 759     # END: for rawfile in args.raw
 760
 761
 762 def parse_tracefile_line(line, exclude, include, exflags, incflags, active_proc, graph, base=16):
 763     val = line.split()
 764     if len(val) < 10:
 765         return
 766     if val[2] == "proc_exec" or val[2] == "TRACE_DATA_EXEC":
 767         pid = int(val[3], base)
 768         active_proc[pid] = val[9]
 769     if val[2] == "MACH_IPC_kmsg_info":
 770         sendpid = int(val[3], base)
 771         destpid = int(val[4], base)
 772         if sendpid == 0:
 773             src = "kernel_task"
 774         elif sendpid in active_proc:
 775             src = active_proc[sendpid]
 776         else:
 777             src = "{:d}".format(sendpid)
 778         if destpid == 0:
 779             dst = "kernel_task"
 780         elif destpid in active_proc:
 781             dst = active_proc[destpid]
 782         else:
 783             dst = "{:d}".format(destpid)
 784         if exclude and len(exclude) > 0 and (src in exclude or dst in exclude):
 785             return
 786         if include and len(include) > 0 and (not (src in include or dst in include)):
 787             return
 788         flags = int(val[6], 16)
 789         if exflags or incflags:
 790             if exflags and (flags & int(exflags[0], 0)):
 791                 return
 792             if incflags and (flags & int(incflags[0], 0)) != int(incflags[0], 0):
 793                 return
 794         # create a graph edge
 795         if (flags & IPCEdge.F_TRACED):
 796             graph.addmsg(src, sendpid, dst, destpid, val[5], val[6], float(val[0]))
 797     # END: MACH_IPC_kmsg_info
 798
 799 #
 800 # Main
 801 #
 802 def main(argv=sys.argv):
 803     """ Main program entry point.
 804
 805         Trace file output lines look like this:
 806         {abstime} {delta} MACH_IPC_kmsg_info {src_pid} {dst_pid} {msg_len} {flags} {threadid} {cpu} {proc_name}
 807         e.g.
 808         4621921.2  33.8(0.0)  MACH_IPC_kmsg_info  ac  9d  c  230002  b2e  1  MobileMail
 809
 810         Or like this:
 811         {abstime} {delta} proc_exec {pid} 0 0 0 {threadid} {cpu} {proc_name}
 812         e.g.
 813         4292212.3  511.2  proc_exec c8  0  0  0  b44  0  voiced
 814     """
 815     global g_verbose
 816
 817     parser = argparse.ArgumentParser(description='Parse an XNU Mach IPC kmsg ktrace file')
 818
 819     # output a DOT formatted graph file
 820     parser.add_argument('--printgraph', '-g', dest='graph', default=None, type=argparse.FileType('w'), help='Output a DOT connectivity graph from the trace data')
 821     parser.add_argument('--graphname', dest='name', default='ipcgraph', help='A name for the DOT graph output')
 822     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)')
 823
 824     # output a CDF of message data
 825     parser.add_argument('--printfreq', '-f', dest='freq', default=None, type=argparse.FileType('w'), help='Output a frequency distribution of message data (in CSV format)')
 826     parser.add_argument('--gnuplot', dest='gnuplot', action='store_true', help='Write out a gnuplot file along with the frequency distribution data')
 827
 828     # output a simple summary of message data
 829     parser.add_argument('--printsummary', '-s', dest='summary', default=None, type=argparse.FileType('w'), help='Output a summary of all messages in the trace data')
 830
 831     # Output a CSV grid of node data/messages
 832     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)')
 833     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')
 834     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')
 835
 836     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.')
 837     parser.add_argument('--tbfreq', '-T', dest='tbfreq', default=None, help='The value of sysctl hw.tbfrequency run on the device')
 838     parser.add_argument('--device', '-D', dest='device', nargs=1, metavar='DEV', help='The name of the iOS device reachable via "ssh DEV"')
 839     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)')
 840     parser.add_argument('--traceargs', dest='traceargs', nargs='+', metavar='TRACE_OPT', help='Extra options to the "trace" program run on the host')
 841
 842     parser.add_argument('--psfile', dest='psfile', nargs='+', type=argparse.FileType('r'), help='Process list file output by ios_trace_ipc.sh')
 843
 844     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.')
 845     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.')
 846     parser.add_argument('--exflags', dest='exflags', metavar='0xFLAGS', nargs=1, help='Messages with any of these flags bits set will be discarded')
 847     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')
 848
 849     parser.add_argument('--verbose', '-v', dest='verbose', action='count', help='be verbose (can be used multiple times)')
 850     parser.add_argument('tracefile', nargs='*', type=argparse.FileType('r'), help='Input trace file')
 851
 852     args = parser.parse_args()
 853
 854     g_verbose = args.verbose
 855
 856     if not args.graph and not args.freq and not args.summary and not args.nodegrid:
 857         sys.stderr.write("Please select at least one output format: [-gfsn] {file}\n")
 858         sys.exit(1)
 859
 860     convert_raw_tracefiles(args)
 861
 862     graph = IPCGraph(args.name, args.tbfreq)
 863
 864     nfiles = len(args.tracefile)
 865     idx = 0
 866     while idx < nfiles:
 867         active_proc = {}
 868         # Parse a ps output file (generated by ios_trace_ipc.sh)
 869         # This pre-fills the active_proc list
 870         if args.psfile and len(args.psfile) > idx:
 871             sys.stderr.write("Parsing {:s}...\n".format(args.psfile[idx].name))
 872             for line in args.psfile[idx]:
 873                 if line.strip() == '':
 874                     continue
 875                 parse_tracefile_line(line.strip(), None, None, None, None, active_proc, graph, 10)
 876         # END: for line in psfile
 877
 878         sys.stderr.write("Parsing {:s}...\n".format(args.tracefile[idx].name))
 879         for line in args.tracefile[idx]:
 880             if line.strip() == '':
 881                 continue
 882             parse_tracefile_line(line.strip(), args.exclude, args.include, args.exflags, args.incflags, active_proc, graph)
 883         # END: for line in tracefile
 884         idx += 1
 885     # END: foreach tracefile/psfile
 886
 887     if args.graph:
 888         if args.follow and len(args.follow) > 0:
 889             sys.stderr.write("Writing follow-graph to {:s}...\n".format(args.graph.name))
 890             graph.print_follow_graph(args.graph, args.follow)
 891         else:
 892             sys.stderr.write("Writing graph output to {:s}...\n".format(args.graph.name))
 893             graph.print_graph(args.graph, args.follow)
 894     if args.freq:
 895         sys.stderr.write("Writing CDF data to {:s}...\n".format(args.freq.name))
 896         graph.print_freqdata(args.freq, args.gnuplot)
 897     if args.summary:
 898         sys.stderr.write("Writing summary data to {:s}...\n".format(args.summary.name))
 899         graph.print_datasummary(args.summary)
 900     if args.nodegrid:
 901         nm = args.ngridtype
 902         sys.stderr.write("Writing node grid data to {:s}...]\n".format(args.nodegrid.name))
 903         graph.print_nodegrid(args.nodegrid, args.ngridtype, args.ngridfilter)
 904
 905 if __name__ == '__main__':
 906     sys.exit(main())