systrace marks and binder transaction integration

docs/sources/devguide.rst

@@ -120,7 +120,7 @@ a project class instance is passed to your event callbacks. You can use followin
 
    Used to stop a process event. The timestamp is taken in the event object
 
-* proj.generic_add_wake(caller, callee, event)
+* proj.generic_add_wake(caller, callee, timestamp, color_name)
 
    Used to generate a wake event. This translate into arrows that go from one process to another, at a particular time. Usefull to show process interactions
 

timechart/backends/ftrace.py

@@ -94,9 +94,9 @@ def parse_ftrace(filename,callback):
     last_percent = 0
     # the base regular expressions
     event_re = re.compile(
-        r'\s*(.+)-([0-9]+)\s+\[([0-9]+)\][^:]*\s+([0-9.]+): ([^:]*): (.*)')
+        r'\s*(.+)-([0-9]+)\s+(\(([^\)]+)\)\s+)?\[([0-9]+)\][^:]*\s+([0-9.]+): ([^:]*): ([^\\]*)')
     function_re = re.compile(
-        r'\s*(.+)-([0-9]+)\s+\[([0-9]+)\][^:]*\s+([0-9.]+): (.*) <-(.*)')
+        r'\s*(.+)-([0-9]+)\s+(\(([^\)]+)\)\s+)?\[([0-9]+)\][^:]*\s+([0-9.]+): (.*) <-([^\\]*)')
     last_timestamp = 0
     linenumber = 0
     for line in fid:
@@ -111,15 +111,20 @@ def parse_ftrace(filename,callback):
         res = event_re.match(line)
         if res:
             groups = res.groups()
-            event_name = groups[4]
+            event_name = groups[6]
+            try:
+                tgid = int(groups[3])
+            except:
+                tgid = 0
             event = {
                 'linenumber': linenumber,
                 'common_comm' : groups[0],
                 'common_pid' :  int(groups[1]),
-                'common_cpu' : int(groups[2]),
-                'timestamp' : int(float(groups[3])*1000000),
+                'common_tgid' : tgid,
+                'common_cpu' : int(groups[4]),
+                'timestamp' : int(float(groups[5])*1000000),
                 'event' : event_name,
-                'event_arg' : groups[5]
+                'event_arg' : groups[7]
                 }
             last_timestamp = event['timestamp']
             to_match = event['event_arg']
@@ -139,11 +144,12 @@ def parse_ftrace(filename,callback):
                 'linenumber': linenumber,
                 'common_comm' : res.group(1),
                 'common_pid' :  int(res.group(2)),
-                'common_cpu' : int(res.group(3)),
-                'timestamp' : int(float(res.group(4))*1000000),
+                'common_tgid' : tgid,
+                'common_cpu' : int(res.group(5)),
+                'timestamp' : int(float(res.group(6))*1000000),
                 'event':'function',
-                'callee' : res.group(5),
-                'caller' : res.group(6)
+                'callee' : res.group(7),
+                'caller' : res.group(8)
                 }
             callback(Event(event))
             continue
@@ -169,6 +175,8 @@ def load_ftrace(fn):
 
 
 def detect_ftrace(fn):
+    if fn.endswith(".html"):
+        return load_ftrace
     if fn.endswith(".txt"):
         return load_ftrace
     if fn.endswith(".txt.gz"):

timechart/colors.py

@@ -30,7 +30,11 @@ def _to_traits(color):
     r = int(color[1:3],16)/256.
     g = int(color[3:5],16)/256.
     b = int(color[5:7],16)/256.
-    return r,g,b
+    if (len(color) == 9):
+        a = int(color[7:9],16)/256.
+    else:
+        a = 1
+    return r,g,b,a
 
 def add_color(colorname, color):
     _tc_colors_by_name[colorname] = (color,len(_tc_colors_by_id))
@@ -47,8 +51,8 @@ def parse_colors(color_text):
         if len(line)==2:
             colorname, color = line
             if pending_colors:
-                r1,g1,b1 = last_color
-                r2,g2,b2 = _to_traits(color)
+                r1,g1,b1,a1 = last_color
+                r2,g2,b2,a2 = _to_traits(color)
                 n = len(pending_colors)+2
                 for i in xrange(1,n-1):
                     r = r1+(r2-r1)*i/n

timechart/model.py

@@ -271,6 +271,11 @@ def get_selection_text(self,start,end):
         return self.get_partial_text(self.filename, low_line, high_line)
 ######### generic parsing part ##########
 
+    def generic_get_current_comm(self,pid):
+        try:
+            return self.current_comm_process[pid]
+        except:
+            return "<...>"
 
     def generic_find_process(self,pid,comm,ptype,same_pid_match_timestamp=0):
         if self.tmp_process.has_key((pid,comm)):
@@ -282,9 +287,12 @@ def generic_find_process(self,pid,comm,ptype,same_pid_match_timestamp=0):
                     if len(p['start_ts'])>0 and p['start_ts'][-1] > same_pid_match_timestamp:
                         p['comm'] = comm
                         self.tmp_process[(pid,comm)] = p
+                        self.current_comm_process[pid] = comm
                         del self.tmp_process[k]
                         return p
         tmp = {'type':ptype,'comm':comm,'pid':pid,'start_ts':[],'end_ts':[],'types':[],'cpus':[],'comments':[]}
+        if not pid==0 and ptype == "user_process":
+            self.current_comm_process[pid] = comm
         if not (pid==0 and ptype == "user_process"):
             self.tmp_process[(pid,comm)] = tmp
         return tmp
@@ -346,8 +354,8 @@ def generic_process_single_event(self,process,event):
         process['cpus'].append(event.common_cpu)
         process['end_ts'].append(event.timestamp)
 
-    def generic_add_wake(self,caller, callee, event):
-        self.wake_events.append(((caller['comm'],caller['pid']),(callee['comm'],callee['pid']),event.timestamp))
+    def generic_add_wake(self,caller, callee, timestamp, color):
+        self.wake_events.append(((caller['comm'],caller['pid']),(callee['comm'],callee['pid']),timestamp,colors.get_traits_color_by_name(color)))
 
     def do_function_default(self,event):
         process = self.generic_find_process(0,"kernel function:%s"%(event.callee),"function")
@@ -366,6 +374,7 @@ def start_parsing(self, get_partial_text):
         self.tmp_c_states = []
         self.tmp_p_states = []
         self.tmp_process = {}
+        self.current_comm_process = {}
         self.timestamps = []
         self.linenumbers = []
         self.cur_process_by_pid = {}
@@ -406,7 +415,7 @@ def finish_parsing(self):
             t.types = numpy.array(tc['types'])
             i+=1
             p_states.append(t)
-        self.wake_events = numpy.array(self.wake_events,dtype=[('waker',tuple),('wakee',tuple),('time','uint64')])
+        self.wake_events = numpy.array(self.wake_events,dtype=[('waker',tuple),('wakee',tuple),('time','uint64'),('type',tuple)])
         self.p_states=p_states
         processes = []
         last_ts = 0

timechart/plot.py

@@ -318,10 +318,10 @@ def _draw_freqchart(self,gc,tc,label,y):
     def _draw_wake_ups(self,gc,processes_y):
         low_i = searchsorted(self.proj.wake_events['time'],self.index_mapper.range.low)
         high_i = searchsorted(self.proj.wake_events['time'],self.index_mapper.range.high)
-        gc.set_stroke_color((0,0,0,.6))
         for i in xrange(low_i,high_i):
-            waker,wakee,ts = self.proj.wake_events[i]
+            waker,wakee,ts,color = self.proj.wake_events[i]
             if processes_y.has_key(wakee) and processes_y.has_key(waker):
+                gc.set_stroke_color(color)
                 y1 = processes_y[wakee]
                 y2 = processes_y[waker]
                 x,y = self.map_screen(array((ts,y1)))
@@ -340,8 +340,8 @@ def _draw_wake_ups(self,gc,processes_y):
                 gc.line_to(x-3,y+dy)
                 gc.move_to(x,y)
                 gc.line_to(x+3,y+dy)
+                gc.draw_path()
 
-        gc.draw_path()
     def _draw_bg(self,gc,y,color):
         gc.set_alpha(1)
         gc.set_line_width(0)

timechart/plugins/binder.py

@@ -0,0 +1,50 @@
+# 2013 September 12th   Sebastien MICHEL Creation
+#
+# To see Android binder transactions on ftrace:
+# for event in binder/binder_transaction binder/binder_transaction_received
+# do
+#    adb shell "echo 1 > /d/tracing/events/$event/enable"
+# done
+
+from timechart.plugin import *
+from timechart import colors
+from timechart.model import tcProcess
+import logging
+
+debug = False
+ctx = {}
+
+class binder(plugin):
+
+    additional_colors = """
+    binder_arrow		  #ff0000A0
+    """
+
+    additional_ftrace_parsers = [
+    ('binder_transaction','transaction=%d dest_node=%d dest_proc=%d dest_thread=%d reply=%d flags=%s code=%s','transaction_id','dest_node','dest_proc','dest_thread','reply','flags','code'),
+    ('binder_transaction_received','transaction=%d','transaction_id'),
+    ]
+
+    @staticmethod
+    def do_event_binder_transaction(proj,event):
+        if debug: logging.debug("binder_send: %d", event.transaction_id)
+        ctx[event.transaction_id] = {
+                'comm' : proj.generic_get_current_comm(event.common_pid),
+                'pid'  : event.common_pid,
+                }
+
+    @staticmethod
+    def do_event_binder_transaction_received(proj,event):
+        if debug: logging.debug("binder_recv: %d", event.transaction_id)
+        try:
+            caller = ctx[event.transaction_id]
+            callee = {
+                    'comm' : proj.generic_get_current_comm(event.common_pid),
+                    'pid'  : event.common_pid,
+                    }
+            proj.generic_add_wake(caller, callee, event.timestamp, "binder_arrow")
+        except KeyError:
+            logging.warning("binder parsing error (not sender found for %s(last comm:%s)-%d transaction=%d)", event.common_comm, proj.generic_get_current_comm(event.common_pid), event.common_pid, event.transaction_id)
+            return
+
+plugin_register(binder)

timechart/plugins/irq.py

@@ -4,6 +4,7 @@
 
 class irq(plugin):
     additional_colors = """
+    irq_arrow      #00A000A0
 """
     additional_ftrace_parsers = [
         ('softirq_entry','softirq=%d action=%s','vec','name'),
@@ -107,7 +108,11 @@ def do_event_softirq_raise(self,event):
         softirqname = "softirq:%d:%s"%(event.vec,event.name)
         if p_stack:
             p = p_stack[-1]
-            self.wake_events.append(((p['comm'],p['pid']),(softirqname,0),event.timestamp))
+            callee = {
+                    'comm' : softirqname,
+                    'pid'  : 0,
+                    }
+            self.generic_add_wake(p, callee, event.timestamp, "irq_arrow")
         else:
             p = self.generic_find_process(0,softirqname+" raise","softirq")
             self.generic_process_single_event(p,event)

timechart/plugins/sched.py

@@ -4,6 +4,7 @@
 
 class sched(plugin):
     additional_colors = """
+    sched_wakeup_arrow      #000000A0
 """
     additional_ftrace_parsers = [
         ]
@@ -31,11 +32,19 @@ def do_event_sched_switch(self,event):
     @staticmethod
     def do_event_sched_wakeup(self,event):
         p_stack = self.cur_process[event.common_cpu]
+        callee = {
+                'comm' : event.comm,
+                'pid'  : event.pid,
+                }
         if p_stack:
             p = p_stack[-1]
-            self.wake_events.append(((p['comm'],p['pid']),(event.comm,event.pid),event.timestamp))
+            self.generic_add_wake(p, callee, event.timestamp, "sched_wakeup_arrow")
         else:
-            self.wake_events.append(((event.common_comm,event.common_pid),(event.comm,event.pid),event.timestamp))
+            current_task = {
+                    'comm' : event.common_comm,
+                    'pid'  : event.common_pid,
+                    }
+            self.generic_add_wake(current_task, callee, event.timestamp, "sched_wakeup_arrow")
 
 
 plugin_register(sched)

timechart/plugins/template.py

@@ -6,6 +6,7 @@
 class template(plugin):
     additional_colors = """
 template_bg		      #80ff80
+function_calls        #00A000A0
 """
     additional_ftrace_parsers = [
         ]
@@ -24,11 +25,11 @@ def do_function_my_start_function(proj,event):
 
         # the function caller
         caller = proj.generic_find_process(0,event.caller,"template")
-        proj.generic_add_wake(caller, process,event)
+        proj.generic_add_wake(caller, process,event.timestamp, "function_calls")
 
         # the calling process
         pidcaller = proj.generic_find_process(event.common_pid,event.common_comm,"template")
-        proj.generic_add_wake(pidcaller, process,event)
+        proj.generic_add_wake(pidcaller, process,event.timestamp, "function_calls")
 
     @staticmethod
     def do_function_my_stop_function(proj,event):