The Design and Implementation of the FreeBSD Operating System, Second Edition
Now available: The Design and Implementation of the FreeBSD Operating System (Second Edition)


[ source navigation ] [ diff markup ] [ identifier search ] [ freetext search ] [ file search ] [ list types ] [ track identifier ]

FreeBSD/Linux Kernel Cross Reference
sys/tools/trace/parse_ipc_trace.py

Version: -  FREEBSD  -  FREEBSD-13-STABLE  -  FREEBSD-13-0  -  FREEBSD-12-STABLE  -  FREEBSD-12-0  -  FREEBSD-11-STABLE  -  FREEBSD-11-0  -  FREEBSD-10-STABLE  -  FREEBSD-10-0  -  FREEBSD-9-STABLE  -  FREEBSD-9-0  -  FREEBSD-8-STABLE  -  FREEBSD-8-0  -  FREEBSD-7-STABLE  -  FREEBSD-7-0  -  FREEBSD-6-STABLE  -  FREEBSD-6-0  -  FREEBSD-5-STABLE  -  FREEBSD-5-0  -  FREEBSD-4-STABLE  -  FREEBSD-3-STABLE  -  FREEBSD22  -  l41  -  OPENBSD  -  linux-2.6  -  MK84  -  PLAN9  -  xnu-8792 
SearchContext: -  none  -  3  -  10 

    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())

Cache object: 0832c5ac1493e62c114de9a75fb2e1d1


[ source navigation ] [ diff markup ] [ identifier search ] [ freetext search ] [ file search ] [ list types ] [ track identifier ]


This page is part of the FreeBSD/Linux Linux Kernel Cross-Reference, and was automatically generated using a modified version of the LXR engine.