diff --git a/docs/sources/devguide.rst b/docs/sources/devguide.rst index fcecf73..e501b77 100644 --- a/docs/sources/devguide.rst +++ b/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 diff --git a/timechart/backends/ftrace.py b/timechart/backends/ftrace.py index da3aa39..e7bfae9 100644 --- a/timechart/backends/ftrace.py +++ b/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"): diff --git a/timechart/colors.py b/timechart/colors.py index 8f64c03..1a20e38 100644 --- a/timechart/colors.py +++ b/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 diff --git a/timechart/model.py b/timechart/model.py index 1618d17..32ff949 100644 --- a/timechart/model.py +++ b/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 diff --git a/timechart/plot.py b/timechart/plot.py index a672ead..db04eff 100644 --- a/timechart/plot.py +++ b/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) diff --git a/timechart/plugins/binder.py b/timechart/plugins/binder.py new file mode 100644 index 0000000..42c88ef --- /dev/null +++ b/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) diff --git a/timechart/plugins/irq.py b/timechart/plugins/irq.py index f4b1eb1..0bfeae3 100644 --- a/timechart/plugins/irq.py +++ b/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) diff --git a/timechart/plugins/sched.py b/timechart/plugins/sched.py index 37ab122..d8302da 100644 --- a/timechart/plugins/sched.py +++ b/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) diff --git a/timechart/plugins/template.py b/timechart/plugins/template.py index 2e4310d..3971939 100644 --- a/timechart/plugins/template.py +++ b/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): diff --git a/timechart/plugins/tracing_mark_write.py b/timechart/plugins/tracing_mark_write.py new file mode 100644 index 0000000..4759136 --- /dev/null +++ b/timechart/plugins/tracing_mark_write.py @@ -0,0 +1,140 @@ +# 2013 September 10th Stephane GASPARINI/Sebastien MICHEL Creation +# +# to use with Android systrace/atrace markers (traceBegin, traceEnd java call or their C/C++ equivalent) +# tracing_mark_write: S|pid|usertag|value +# tracing_mark_write: F|pid|usertag|value +# tracing_mark_write: C|pid|usertag|value +# tracing_mark_write: B|pid|usertag +# tracing_mark_write: E + +from timechart.plugin import * +from timechart import colors +from timechart.model import tcProcess, _pretty_time +import logging + +debug = False +ctx = {} +ctx_start_ts = {} +ctx_start_usertag = {} + +class tracing_mark_write(plugin): + additional_colors = """ + tracing_mark_write_counter_bg #00ffff + tracing_mark_write_sync_bg #00ffBB + tracing_mark_write_async_bg #00ff77 + """ + additional_ftrace_parsers = [ + ('tracing_mark_write',"%s",'traceEvent'), + ('tracing_mark_write',r"%s\|%d\|%s",'traceEvent','pid','usertag'), + ('tracing_mark_write',r"%s\|%d\|%s\|%d",'traceEvent','pid','usertag','value'), + ] + additional_process_types = { + "tracing_mark_write_counter":(tcProcess, MISC_TRACES_CLASS), + "tracing_mark_write_sync":(tcProcess, USER_CLASS), + "tracing_mark_write_async":(tcProcess, USER_CLASS), + } + + @staticmethod + def do_event_tracing_mark_write(proj,event): + # doing sanity checking: when funtion tracer is activated + # could get corrupted tracing_mark_write event + if len(event.traceEvent) != 1 : + logging.warning("tracing_mark_write plug-ins: line %d malformed tracing_mark_write event - Ignoring", event.linenumber) + logging.warning("likely you had trace buffer underrun") + return + + if event.traceEvent == "B" or event.traceEvent == "E": + sync = "sync" + evtype = "sync" + elif event.traceEvent == "S" or event.traceEvent == "F": + sync = "async" + evtype = "async" + elif event.traceEvent == "C": + sync = "counter" + evtype = "counter" + + if sync == "async": + key=(event.common_comm,event.common_pid,event.value) + evtype=str(event.value) + elif sync == "sync": + key=(event.common_comm,event.common_pid,evtype) + + + # ####################### + # TraceBegin marker code + # ####################### + if event.traceEvent == "B" or event.traceEvent == "S": + + if not hasattr(event,'usertag') or not hasattr(event,'pid'): + logging.warning("tracing_mark_write plug-ins: line, %d malformed tracing_mark_write missing attribute- Ignoring", event.linenumber) + logging.warning("likely you had trace buffer underrun") + return + # 'tracing_mark_write: B|pid|usertag' found + try: + ctx[key] += 1 + except KeyError: + ctx[key] = 0 + process = proj.generic_find_process(event.common_pid,event.common_comm+"|"+evtype+"|"+("%03d" % ctx[key]),"tracing_mark_write_"+sync) + proj.generic_process_start(process,event,False) + # collect timestamp on user tag for late use on 'E' marker + ctx_start_ts[key,ctx[key]] = event.timestamp + ctx_start_usertag[key,ctx[key]] = event.usertag + process['comments'].append(event.usertag+"(Did not finish)") + if debug: + logging.debug("------------------------------------->\n") + if sync == "async": + logging.debug("key: (('%s', %s, %s), %s)", event.common_comm, event.common_pid, event.value, ctx[key]) + else: + logging.debug("key: (('%s', %s, %s), %s)", event.common_comm, event.common_pid, evtype, ctx[key]) + logging.debug("ctx %s" %(ctx)) + logging.debug("ctx_start_ts %s", (ctx_start_ts)) + logging.debug("ctx_start_usertag %s\n", (ctx_start_usertag)) + logging.debug("--\n") + + # ####################### + # TraceEnd marker code + # ####################### + elif event.traceEvent == "E" or event.traceEvent == "F": + try: + if debug: + logging.debug("--\n") + if sync == "async": + logging.debug("key: (('%s', %s, %s), %s)", event.common_comm, event.common_pid, event.value, ctx[key]) + else: + logging.debug("key: (('%s', %s, %s), %s)", event.common_comm, event.common_pid, evtype, ctx[key]) + logging.debug("ctx_start_ts %s", ctx_start_ts) + logging.debug("ctx_start_usertag %s", ctx_start_usertag) + logging.debug("ctx %s\n<-------------------------------------\n", ctx) + + process = proj.generic_find_process(event.common_pid,event.common_comm+"|"+evtype+"|"+("%03d" % ctx[key]),"tracing_mark_write_"+sync) + except KeyError: + # hit a TraceEnd before a TraceBegin marker + return + proj.generic_process_end(process,event,False) + + # compute duration and add comment to plot + try: + process['comments'].pop() + duration=event.timestamp-ctx_start_ts[key,ctx[key]] + process['comments'].append(ctx_start_usertag[key,ctx[key]]+"("+_pretty_time(duration)+")") + except IndexError: + # missing corresponding B marker in trace + logging.debug( "IndexError \n%s\n", event) + except KeyError: + logging.debug("KeyError \n%s\n", event) + ctx[key] -= 1 + + # ####################### + # TraceCounter marker code + # ####################### + elif event.traceEvent == "C": + process = proj.generic_find_process(-1,event.usertag,"tracing_mark_write_counter") + proj.generic_process_start(process,event,False) + process['comments'].append(str(event.value)) + + else : + # tracing_mark_write event malformed + logging.warning("tracing_mark_write plug-ins: line %d malformed tracing_mark_write event.traceEvent - Ignoring", event.linenumber) + return + +plugin_register(tracing_mark_write) diff --git a/timechart/plugins/wake_lock.py b/timechart/plugins/wake_lock.py index 1983f7b..a79d533 100644 --- a/timechart/plugins/wake_lock.py +++ b/timechart/plugins/wake_lock.py @@ -5,6 +5,7 @@ class wake_lock(plugin): additional_colors = """ wakelock_bg #D6F09D +wakelock_arrow #0000A0A0 """ additional_ftrace_parsers = [ ('wakelock_lock', 'name=%s type=%d', 'name', 'type'), @@ -17,12 +18,21 @@ class wake_lock(plugin): def do_event_wakelock_lock(proj,event): process = proj.generic_find_process(0,"wakelock:%s"%(event.name),"wakelock") proj.generic_process_start(process,event,False) - proj.wake_events.append(((event.common_comm,event.common_pid),(process['comm'],process['pid']),event.timestamp)) + current_task = { + 'comm' : event.common_comm, + 'pid' : event.common_pid, + } + proj.generic_add_wake(current_task, process, event.timestamp, "wakelock_arrow") @staticmethod def do_event_wakelock_unlock(proj,event): process = proj.generic_find_process(0,"wakelock:%s"%(event.name),"wakelock") proj.generic_process_end(process,event,False) - proj.wake_events.append(((event.common_comm,event.common_pid),(process['comm'],process['pid']),event.timestamp)) + current_task = { + 'comm' : event.common_comm, + 'pid' : event.common_pid, + } + proj.generic_add_wake(current_task, process, event.timestamp, "wakelock_arrow") + plugin_register(wake_lock) diff --git a/timechart/tests/test_db/tgidtrace.txt b/timechart/tests/test_db/tgidtrace.txt new file mode 100644 index 0000000..ff6f17a --- /dev/null +++ b/timechart/tests/test_db/tgidtrace.txt @@ -0,0 +1,137 @@ + id.defcontainer-3611 ( 3611) [000] ...1 20810.237004: tracing_mark_write: B|3611|serviceCreate\n\ + id.defcontainer-3611 ( 3611) [000] ...1 20810.243355: tracing_mark_write: E\n\ + id.defcontainer-3611 ( 3611) [000] ...1 20810.243432: tracing_mark_write: B|3611|serviceBind\n\ + id.defcontainer-3611 ( 3611) [000] ...1 20810.244116: tracing_mark_write: E\n\ + id.defcontainer-3611 ( 3611) [000] d..3 20810.244239: sched_switch: prev_comm=id.defcontainer prev_pid=3611 prev_prio=120 prev_state=S ==> next_comm=PackageManager next_pid=464 next_prio=130\n\ + Binder_A-862 ( 443) [000] d..5 20810.253535: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + Binder_A-862 ( 443) [000] d..3 20810.254261: sched_switch: prev_comm=Binder_A prev_pid=862 prev_prio=120 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.254307: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.254352: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.254379: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=android.vending next_pid=1664 next_prio=120\n\ + ActivityManager-460 ( 443) [000] d..5 20810.682057: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + ActivityManager-460 ( 443) [000] d..3 20810.682072: sched_switch: prev_comm=ActivityManager prev_pid=460 prev_prio=118 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.682106: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.682245: sched_wakeup: comm=FileObserver pid=463 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.682383: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=ActivityManager next_pid=460 next_prio=118\n\ + FileObserver-463 ( 443) [001] d..4 20810.682403: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + PackageManager-464 ( 443) [000] d..3 20810.682410: sched_switch: prev_comm=PackageManager prev_pid=464 prev_prio=130 prev_state=R ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.682417: sched_wakeup: comm=ActivityManager pid=460 prio=118 success=1 target_cpu=000\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.682529: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.682580: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.682585: tracing_mark_write: B|443|/system/app/GmsCore.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.683176: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.683192: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=ActivityManager next_pid=460 next_prio=118\n\ + FileObserver-463 ( 443) [001] d..4 20810.683227: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + ActivityManager-460 ( 443) [000] d..3 20810.683482: sched_switch: prev_comm=ActivityManager prev_pid=460 prev_prio=118 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.683488: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=PackageMonitor next_pid=469 next_prio=130\n\ + ActivityManager-460 ( 443) [000] d..4 20810.683517: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + ActivityManager-460 ( 443) [000] d..3 20810.683533: sched_switch: prev_comm=ActivityManager prev_pid=460 prev_prio=118 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.683787: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=ActivityManager next_pid=460 next_prio=118\n\ + FileObserver-463 ( 443) [001] d..4 20810.683799: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + PackageMonitor-469 ( 443) [000] d..3 20810.683805: sched_switch: prev_comm=PackageMonitor prev_pid=469 prev_prio=130 prev_state=R ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.683812: sched_wakeup: comm=ActivityManager pid=460 prio=118 success=1 target_cpu=000\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.683985: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=ActivityManager next_pid=460 next_prio=118\n\ + FileObserver-463 ( 443) [001] d..4 20810.684009: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + Binder_A-862 ( 443) [000] d..3 20810.692469: sched_switch: prev_comm=Binder_A prev_pid=862 prev_prio=120 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] ..s1 20810.692549: cpufreq_interactive_notyet: cpu=0 load=68 cur=2133000 actual=2133000 targ=1733000\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.692629: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.692665: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.692670: tracing_mark_write: B|443|/system/app/Email.apk\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.692969: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=launcher-loader next_pid=878 next_prio=120\n\ + Binder_8-791 ( 443) [001] d..4 20810.692980: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + putmethod.latin-702 ( 702) [000] d..3 20810.695358: sched_switch: prev_comm=putmethod.latin prev_pid=702 prev_prio=120 prev_state=D ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.695461: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696100: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696123: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696127: tracing_mark_write: B|443|/system/app/GoogleLoginService.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696454: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696764: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696807: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696828: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.696846: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.697464: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.697486: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.697490: tracing_mark_write: B|443|/system/app/Books.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.697929: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.698338: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.698357: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.698361: tracing_mark_write: B|443|/system/app/CalendarGoogle.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.698745: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699099: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699117: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699121: tracing_mark_write: B|443|/system/app/ChromeBookmarksSyncAdapter.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699222: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699490: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699505: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699510: tracing_mark_write: B|443|/system/app/ChromeWithBrowser.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.699925: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.700413: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.700429: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.700433: tracing_mark_write: B|443|/system/app/Exchange2.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.700571: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.701132: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.701148: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.701152: tracing_mark_write: B|443|/system/app/Gmail2.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.701638: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.702559: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=R+ ==> next_comm=Compiler next_pid=3688 next_prio=120\n\ + launcher-loader-878 ( 798) [000] d..3 20810.707074: sched_switch: prev_comm=launcher-loader prev_pid=878 prev_prio=120 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.707632: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.707657: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=R+ ==> next_comm=Binder_2 next_pid=1216 next_prio=120\n\ + Compiler-812 ( 798) [000] d..3 20810.728942: sched_switch: prev_comm=Compiler prev_pid=812 prev_prio=120 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.728958: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.728980: tracing_mark_write: B|443|/system/app/GoogleContactsSyncAdapter.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.729147: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.729644: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.729664: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.729668: tracing_mark_write: B|443|/system/app/GoogleDocs.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.730203: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.730703: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.730725: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.730729: tracing_mark_write: B|443|/system/app/GoogleServicesFramework.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.731011: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.731477: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.731499: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.731504: tracing_mark_write: B|443|/system/app/PlusOne.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.732458: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.733336: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.733358: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.733362: tracing_mark_write: B|443|/system/app/SocialGallery.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.733833: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.734288: tracing_mark_write: B|443|/system/framework/framework-res.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.734310: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.734315: tracing_mark_write: B|443|/system/app/Videos.apk\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.740328: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.740930: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.740966: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.741013: sched_wakeup: comm=logcat pid=171 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.741039: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.741059: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.741118: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.741136: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.741213: sched_wakeup: comm=logcat pid=171 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.741285: sched_wakeup: comm=Binder_3 pid=683 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.741526: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=PackageMonitor next_pid=469 next_prio=130\n\ + Binder_3-683 ( 443) [001] d..4 20810.741534: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + GC-776 ( 771) [000] d..3 20810.742875: sched_switch: prev_comm=GC prev_pid=776 prev_prio=120 prev_state=S ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.742884: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=PackageManager next_pid=464 next_prio=130\n\ + Binder_3-683 ( 443) [001] d..4 20810.746139: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + PackageManager-464 ( 443) [000] d..3 20810.746156: sched_switch: prev_comm=PackageManager prev_pid=464 prev_prio=130 prev_state=R+ ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.746659: sched_wakeup: comm=PackageMonitor pid=469 prio=130 success=1 target_cpu=000\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.746741: sched_wakeup: comm=Compiler pid=448 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] d..4 20810.746955: sched_wakeup: comm=logcat pid=171 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.746985: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.747034: tracing_mark_write: B|443|broadcastReceiveReg\n\ + er.ServerThread-457 ( 443) [000] d..5 20810.747141: sched_wakeup: comm=AppWidgetServic pid=598 prio=120 success=1 target_cpu=001\n\ + er.ServerThread-457 ( 443) [000] ...1 20810.747149: tracing_mark_write: E\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.747172: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=Binder_5 next_pid=768 next_prio=120\n\ + PackageMonitor-469 ( 443) [000] d..5 20810.800289: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + PackageMonitor-469 ( 443) [000] d..3 20810.800295: sched_switch: prev_comm=PackageMonitor prev_pid=469 prev_prio=130 prev_state=R+ ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.800328: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=PackageMonitor next_pid=469 next_prio=130\n\ + PackageMonitor-469 ( 443) [000] d..4 20810.800338: sched_wakeup: comm=er.ServerThread pid=457 prio=118 success=1 target_cpu=000\n\ + PackageMonitor-469 ( 443) [000] d..3 20810.800341: sched_switch: prev_comm=PackageMonitor prev_pid=469 prev_prio=130 prev_state=R+ ==> next_comm=er.ServerThread next_pid=457 next_prio=118\n\ + er.ServerThread-457 ( 443) [000] d..3 20810.800372: sched_switch: prev_comm=er.ServerThread prev_pid=457 prev_prio=118 prev_state=S ==> next_comm=PackageMonitor next_pid=469 next_prio=130\n\ +\n"; + + + + diff --git a/timechart/tests/test_ftrace.py b/timechart/tests/test_ftrace.py index 6051342..fdd975a 100644 --- a/timechart/tests/test_ftrace.py +++ b/timechart/tests/test_ftrace.py @@ -8,3 +8,11 @@ def test_retrace(self): def test_rpm(self): self.load_file("rpm-trace.txt.gz", "ftrace") self.assertHasProcess("rpm_cb:usb1:0 (76.0 us)") + def test_tgidtrace(self): + proj = self.load_file("tgidtrace.txt", "ftrace") + self.assertHasProcess("er.ServerThread:457 (23.6 ms)") + def test_tracing_mark_write(self): + proj = self.load_file("tgidtrace.txt", "ftrace") + self.assertHasProcess("id.defcontainer|sync|000:3611 (7.0 ms)") + self.assertHasProcess("er.ServerThread|sync|000:457 (64.9 ms)") + self.assertHasProcess("er.ServerThread|sync|001:457 (35.7 ms)") diff --git a/timechart/timechart.py b/timechart/timechart.py index 74f404e..a7a9a73 100755 --- a/timechart/timechart.py +++ b/timechart/timechart.py @@ -1,6 +1,7 @@ #!/usr/bin/python #------------------------------------------------------------------------------ import sys +import logging def main(): try: @@ -54,11 +55,19 @@ def devnull(*args): %prog [options] [trace.txt|trace.txt.gz|trace.txt.lzma|trace.dat] pytimechart - Fast graphical exploration and visualisation for linux kernel traces.""") + parser.add_option("-l", "--log", dest="loglevel", action="store", + help="change log level", + default=False) parser.add_option("-p", "--prof", dest="prof", action="store_true", help="activate profiling", default=False) (options, args) = parser.parse_args() + if options.loglevel: + numeric_level = getattr(logging, options.loglevel.upper(), None) + logging.basicConfig(format='%(levelname)s:%(asctime)s:%(message)s',level=numeric_level) + else: + logging.basicConfig(format='%(levelname)s:%(asctime)s:%(message)s',level=logging.ERROR) # Create the GUI (this does NOT start the GUI event loop). gui = GUI() if len(args) == 0: diff --git a/timechart/window.py b/timechart/window.py index ded15c7..b5f2955 100644 --- a/timechart/window.py +++ b/timechart/window.py @@ -103,7 +103,7 @@ def _selection_time_changed(self): import wx def open_dialog(): - dlg = wx.FileDialog(None, "Choose a file", "", "", "*.txt;*.gz;*.lzma;*.dat", wx.OPEN) + dlg = wx.FileDialog(None, "Choose a file", "", "", "*.txt;*.html;*.gz;*.lzma;*.dat", wx.OPEN) rv = None if dlg.ShowModal() == wx.ID_OK: filename=dlg.GetFilename()