diff options
-rw-r--r-- | tests/raw_trace.raw.txt | 7 | ||||
-rw-r--r-- | tests/raw_trace.txt | 6 | ||||
-rw-r--r-- | tests/test_baretrace.py | 4 | ||||
-rw-r--r-- | tests/test_ftrace.py | 38 | ||||
-rw-r--r-- | tests/test_sched.py | 3 | ||||
-rw-r--r-- | tests/trace_empty.txt | 32 | ||||
-rw-r--r-- | trappy/bare_trace.py | 2 | ||||
-rw-r--r-- | trappy/base.py | 13 | ||||
-rw-r--r-- | trappy/dynamic.py | 2 | ||||
-rw-r--r-- | trappy/ftrace.py | 131 | ||||
-rw-r--r-- | trappy/sched.py | 3 | ||||
-rw-r--r-- | trappy/systrace.py | 1 |
12 files changed, 92 insertions, 150 deletions
diff --git a/tests/raw_trace.raw.txt b/tests/raw_trace.raw.txt deleted file mode 100644 index f66d55b..0000000 --- a/tests/raw_trace.raw.txt +++ /dev/null @@ -1,7 +0,0 @@ -version = 6 -CPU 3 is empty -CPU 4 is empty -cpus=6 - ls-4734 [002] 106439.675591: sched_switch: prev_comm=trace-cmd prev_pid=4734 prev_prio=120 prev_state=1024 next_comm=migration/2 next_pid=18 next_prio=0 - migration/2-18 [002] 106439.675613: sched_switch: prev_comm=migration/2 prev_pid=18 prev_prio=0 prev_state=1 next_comm=trace-cmd next_pid=4732 next_prio=120 - trace-cmd-4730 [001] 106439.675718: sched_switch: prev_comm=trace-cmd prev_pid=4730 prev_prio=120 prev_state=1 next_comm=trace-cmd next_pid=4729 next_prio=120 diff --git a/tests/raw_trace.txt b/tests/raw_trace.txt index 4fbf4c9..f66d55b 100644 --- a/tests/raw_trace.txt +++ b/tests/raw_trace.txt @@ -2,6 +2,6 @@ version = 6 CPU 3 is empty CPU 4 is empty cpus=6 - ls-4734 [002] 106439.675591: sched_switch: trace-cmd:4734 [120] R ==> migration/2:18 [0] - migration/2-18 [002] 106439.675613: sched_switch: migration/2:18 [0] S ==> trace-cmd:4732 [120] - trace-cmd-4731 [001] 106439.675698: sched_switch: trace-cmd:4731 [120] S ==> trace-cmd:4730 [120] + ls-4734 [002] 106439.675591: sched_switch: prev_comm=trace-cmd prev_pid=4734 prev_prio=120 prev_state=1024 next_comm=migration/2 next_pid=18 next_prio=0 + migration/2-18 [002] 106439.675613: sched_switch: prev_comm=migration/2 prev_pid=18 prev_prio=0 prev_state=1 next_comm=trace-cmd next_pid=4732 next_prio=120 + trace-cmd-4730 [001] 106439.675718: sched_switch: prev_comm=trace-cmd prev_pid=4730 prev_prio=120 prev_state=1 next_comm=trace-cmd next_pid=4729 next_prio=120 diff --git a/tests/test_baretrace.py b/tests/test_baretrace.py index 33d872c..257754d 100644 --- a/tests/test_baretrace.py +++ b/tests/test_baretrace.py @@ -66,7 +66,7 @@ class TestBareTrace(unittest.TestCase): trace.add_parsed_event("load_event", self.dfr[1].copy()) basetime = self.dfr[0].index[0] - trace.normalize_time(basetime) + trace._normalize_time(basetime) expected_duration = self.dfr[1].index[-1] - basetime self.assertEquals(trace.get_duration(), expected_duration) @@ -80,7 +80,7 @@ class TestBareTrace(unittest.TestCase): prev_first_time = trace.pmu_counter.data_frame.index[0] basetime = 3 - trace.normalize_time(basetime) + trace._normalize_time(basetime) self.assertEquals(trace.basetime, basetime) diff --git a/tests/test_ftrace.py b/tests/test_ftrace.py index 2488484..9f09e8e 100644 --- a/tests/test_ftrace.py +++ b/tests/test_ftrace.py @@ -181,14 +181,14 @@ class TestFTrace(BaseTestThermal): def test_ftrace_normalize_time(self): - """FTrace().normalize_time() works accross all classes""" + """FTrace()._normalize_time() works accross all classes""" trace = trappy.FTrace(normalize_time=False) prev_inpower_basetime = trace.cpu_in_power.data_frame.index[0] prev_inpower_last = trace.cpu_in_power.data_frame.index[-1] - trace.normalize_time() + trace._normalize_time() self.assertEquals(round(trace.thermal.data_frame.index[0], 7), 0) @@ -377,34 +377,14 @@ class TestFTraceRawDat(utils_tests.SetupDirectory): shutil.move("trace.dat", arbitrary_name) trace = trappy.FTrace(arbitrary_name) - self.assertTrue(os.path.isfile("my_trace.raw.txt")) self.assertTrue(hasattr(trace, "sched_switch")) self.assertTrue(len(trace.sched_switch.data_frame) > 0) - def test_raw_created_if_dat_and_txt_exist(self): - """trace.raw.txt is created when both trace.dat and trace.txt exist""" - - # Create the trace.txt - cmd = ["trace-cmd", "report", "trace.dat"] - with open(os.devnull) as devnull: - out = subprocess.check_output(cmd, stderr=devnull) - - with open("trace.txt", "w") as fout: - fout.write(out) - - # Now check that the raw trace is created and analyzed when creating the trace - trace = trappy.FTrace() - - self.assertTrue(hasattr(trace, "sched_switch")) - self.assertTrue(len(trace.sched_switch.data_frame) > 0) - self.assertTrue("prev_comm" in trace.sched_switch.data_frame.columns) - class TestFTraceRawBothTxt(utils_tests.SetupDirectory): def __init__(self, *args, **kwargs): super(TestFTraceRawBothTxt, self).__init__( - [("raw_trace.txt", "trace.txt"), - ("raw_trace.raw.txt", "trace.raw.txt")], + [("raw_trace.txt", "trace.txt"),], *args, **kwargs) @@ -420,10 +400,8 @@ class TestFTraceRawBothTxt(utils_tests.SetupDirectory): """Test raw parsing for txt files arbitrary name""" arbitrary_name = "my_trace.txt" - arbitrary_name_raw = "my_trace.raw.txt" shutil.move("trace.txt", arbitrary_name) - shutil.move("trace.raw.txt", arbitrary_name_raw) trace = trappy.FTrace(arbitrary_name) self.assertTrue(hasattr(trace, "sched_switch")) @@ -500,14 +478,6 @@ class TestTraceDat(utils_tests.SetupDirectory): self.assert_thermal_in_trace("trace.txt") - def test_do_raw_txt_if_not_there(self): - """Create trace.raw.txt if it's not there""" - self.assertFalse(os.path.isfile("trace.raw.txt")) - - trappy.FTrace() - - self.assert_thermal_in_trace("trace.raw.txt") - def test_ftrace_arbitrary_trace_dat(self): """FTrace() works if asked to parse a binary trace with a filename other than trace.dat""" arbitrary_trace_name = "my_trace.dat" @@ -516,11 +486,9 @@ class TestTraceDat(utils_tests.SetupDirectory): dfr = trappy.FTrace(arbitrary_trace_name).thermal.data_frame self.assertTrue(os.path.exists("my_trace.txt")) - self.assertTrue(os.path.exists("my_trace.raw.txt")) self.assertTrue(len(dfr) > 0) self.assertFalse(os.path.exists("trace.dat")) self.assertFalse(os.path.exists("trace.txt")) - self.assertFalse(os.path.exists("trace.raw.txt")) def test_regenerate_txt_if_outdated(self): """Regenerate the trace.txt if it's older than the trace.dat""" diff --git a/tests/test_sched.py b/tests/test_sched.py index 6527779..89375c8 100644 --- a/tests/test_sched.py +++ b/tests/test_sched.py @@ -25,8 +25,7 @@ sys.path.append(os.path.join(utils_tests.TESTS_DIRECTORY, "..", "trappy")) class BaseTestSched(utils_tests.SetupDirectory): def __init__(self, *args, **kwargs): super(BaseTestSched, self).__init__( - [("trace_sched.txt", "trace.txt"), - ("trace_sched.txt", "trace.raw.txt")], + [("trace_sched.txt", "trace.txt"),], *args, **kwargs) diff --git a/tests/trace_empty.txt b/tests/trace_empty.txt index b35ba6f..8bf02f0 100644 --- a/tests/trace_empty.txt +++ b/tests/trace_empty.txt @@ -2,84 +2,52 @@ version = 6 cpus=5 trace-cmd-2461 [000] 34.896920: sched_stat_runtime: comm=trace-cmd pid=2461 runtime=7778999 [ns] vruntime=6087430069 [ns] trace-cmd-2461 [000] 34.896941: sched_stat_sleep: comm=sshd pid=2450 delay=1802051076 [ns] - trace-cmd-2461 [000] 34.896972: sched_wakeup: sshd:2450 [120] success=1 CPU:000 trace-cmd-2461 [000] 34.897022: sched_stat_wait: comm=sshd pid=2450 delay=0 [ns] - trace-cmd-2461 [000] 34.897053: sched_switch: trace-cmd:2461 [120] R ==> sshd:2450 [120] <idle>-0 [001] 34.897147: sched_stat_wait: comm=rcuos/0 pid=9 delay=0 [ns] - <idle>-0 [001] 34.897153: sched_switch: swapper/1:0 [120] R ==> rcuos/0:9 [120] rcuos/0-9 [001] 34.897169: sched_stat_runtime: comm=sshd pid=2450 runtime=258292 [ns] vruntime=6078688361 [ns] rcuos/0-9 [001] 34.897175: sched_stat_sleep: comm=rcu_sched pid=7 delay=26617125 [ns] - rcuos/0-9 [001] 34.897182: sched_wakeup: rcu_sched:7 [120] success=1 CPU:000 rcuos/0-9 [001] 34.897186: sched_stat_runtime: comm=rcuos/0 pid=9 runtime=445750 [ns] vruntime=6730976621 [ns] - rcuos/0-9 [001] 34.897230: sched_switch: rcuos/0:9 [120] S ==> swapper/1:0 [120] sshd-2450 [000] 34.897303: sched_stat_runtime: comm=sshd pid=2450 runtime=134042 [ns] vruntime=6078822403 [ns] sshd-2450 [000] 34.897313: sched_stat_wait: comm=rcu_sched pid=7 delay=134042 [ns] - sshd-2450 [000] 34.897319: sched_switch: sshd:2450 [120] S ==> rcu_sched:7 [120] rcu_sched-7 [000] 34.897329: sched_stat_runtime: comm=rcu_sched pid=7 runtime=25916 [ns] vruntime=6078455985 [ns] rcu_sched-7 [000] 34.897338: sched_stat_wait: comm=trace-cmd pid=2461 delay=418250 [ns] - rcu_sched-7 [000] 34.897343: sched_switch: rcu_sched:7 [120] S ==> trace-cmd:2461 [120] trace-cmd-2461 [000] 34.897641: sched_process_exit: comm=trace-cmd pid=2461 prio=120 trace-cmd-2461 [000] 34.897665: sched_stat_runtime: comm=trace-cmd pid=2461 runtime=335875 [ns] vruntime=6087765944 [ns] trace-cmd-2461 [000] 34.897675: sched_stat_runtime: comm=trace-cmd pid=2461 runtime=10459 [ns] vruntime=6087776403 [ns] trace-cmd-2461 [000] 34.897697: sched_stat_sleep: comm=bash pid=2459 delay=696151164 [ns] - trace-cmd-2461 [000] 34.897703: sched_wakeup: bash:2459 [120] success=1 CPU:001 trace-cmd-2461 [000] 34.897708: sched_stat_runtime: comm=trace-cmd pid=2461 runtime=33500 [ns] vruntime=6087809903 [ns] - trace-cmd-2461 [000] 34.897738: sched_switch: trace-cmd:2461 [120] x ==> swapper/0:0 [120] <idle>-0 [001] 34.898076: sched_stat_wait: comm=bash pid=2459 delay=0 [ns] - <idle>-0 [001] 34.898082: sched_switch: swapper/1:0 [120] R ==> bash:2459 [120] bash-2459 [001] 34.898188: sched_process_wait: comm=bash pid=0 prio=120 bash-2459 [001] 34.898653: sched_process_exit: comm=bash pid=2459 prio=120 bash-2459 [001] 34.898702: sched_stat_sleep: comm=sshd pid=2450 delay=1394541 [ns] - bash-2459 [001] 34.898708: sched_wakeup: sshd:2450 [120] success=1 CPU:000 <idle>-0 [000] 34.898720: sched_stat_wait: comm=sshd pid=2450 delay=0 [ns] bash-2459 [001] 34.898721: sched_stat_runtime: comm=bash pid=2459 runtime=1027542 [ns] vruntime=6723004163 [ns] - <idle>-0 [000] 34.898726: sched_switch: swapper/0:0 [120] R ==> sshd:2450 [120] bash-2459 [001] 34.898732: sched_stat_runtime: comm=bash pid=2459 runtime=11000 [ns] vruntime=6723015163 [ns] bash-2459 [001] 34.898745: sched_stat_runtime: comm=bash pid=2459 runtime=13458 [ns] vruntime=6723028621 [ns] - bash-2459 [001] 34.898758: sched_switch: bash:2459 [120] x ==> swapper/1:0 [120] sshd-2450 [000] 34.898825: sched_process_wait: comm=sshd pid=0 prio=120 sshd-2450 [000] 34.898927: sched_process_wait: comm=sshd pid=0 prio=120 sshd-2450 [000] 34.898983: sched_stat_runtime: comm=sshd pid=2450 runtime=285875 [ns] vruntime=6079108278 [ns] - sshd-2450 [000] 34.898996: sched_switch: sshd:2450 [120] S ==> swapper/0:0 [120] <idle>-0 [000] 34.899144: sched_stat_sleep: comm=rcu_sched pid=7 delay=1810584 [ns] - <idle>-0 [000] 34.899149: sched_wakeup: rcu_sched:7 [120] success=1 CPU:000 <idle>-0 [000] 34.899175: sched_stat_wait: comm=rcu_sched pid=7 delay=0 [ns] - <idle>-0 [000] 34.899180: sched_switch: swapper/0:0 [120] R ==> rcu_sched:7 [120] rcu_sched-7 [000] 34.899194: sched_stat_sleep: comm=rcuos/0 pid=9 delay=2004042 [ns] - rcu_sched-7 [000] 34.899200: sched_wakeup: rcuos/0:9 [120] success=1 CPU:001 rcu_sched-7 [000] 34.899205: sched_stat_runtime: comm=rcu_sched pid=7 runtime=65375 [ns] vruntime=6078875278 [ns] - rcu_sched-7 [000] 34.899216: sched_switch: rcu_sched:7 [120] S ==> swapper/0:0 [120] <idle>-0 [001] 34.899620: sched_stat_wait: comm=rcuos/0 pid=9 delay=0 [ns] - <idle>-0 [001] 34.899628: sched_switch: swapper/1:0 [120] R ==> rcuos/0:9 [120] rcuos/0-9 [001] 34.899770: sched_stat_sleep: comm=rcu_sched pid=7 delay=538708 [ns] - rcuos/0-9 [001] 34.899807: sched_wakeup: rcu_sched:7 [120] success=1 CPU:000 rcuos/0-9 [001] 34.899848: sched_stat_runtime: comm=rcuos/0 pid=9 runtime=653458 [ns] vruntime=6731630079 [ns] - rcuos/0-9 [001] 34.899877: sched_switch: rcuos/0:9 [120] S ==> swapper/1:0 [120] <idle>-0 [000] 34.899988: sched_stat_sleep: comm=sshd pid=2450 delay=1003959 [ns] - <idle>-0 [000] 34.899995: sched_wakeup: sshd:2450 [120] success=1 CPU:001 <idle>-0 [000] 34.900052: sched_stat_wait: comm=rcu_sched pid=7 delay=0 [ns] - <idle>-0 [000] 34.900058: sched_switch: swapper/0:0 [120] R ==> rcu_sched:7 [120] rcu_sched-7 [000] 34.900069: sched_stat_runtime: comm=rcu_sched pid=7 runtime=325042 [ns] vruntime=6079200320 [ns] - rcu_sched-7 [000] 34.900086: sched_switch: rcu_sched:7 [120] S ==> swapper/0:0 [120] <idle>-0 [001] 34.900452: sched_stat_wait: comm=sshd pid=2450 delay=0 [ns] - <idle>-0 [001] 34.900460: sched_switch: swapper/1:0 [120] R ==> sshd:2450 [120] sshd-2450 [001] 34.900756: sched_stat_sleep: comm=in:imuxsock pid=1767 delay=1926798326 [ns] - sshd-2450 [001] 34.900767: sched_wakeup: in:imuxsock:1767 [120] success=1 CPU:000 <idle>-0 [000] 34.901148: sched_stat_wait: comm=in:imuxsock pid=1767 delay=0 [ns] - <idle>-0 [000] 34.901155: sched_switch: swapper/0:0 [120] R ==> in:imuxsock:1767 [120] in:imuxsock-1767 [000] 34.901243: sched_stat_runtime: comm=in:imuxsock pid=1767 runtime=496084 [ns] vruntime=6079305987 [ns] in:imuxsock-1767 [000] 34.901250: sched_stat_sleep: comm=rs:main Q:Reg pid=1769 delay=1925639660 [ns] - in:imuxsock-1767 [000] 34.901256: sched_wakeup: rs:main Q:Reg:1769 [120] success=1 CPU:000 in:imuxsock-1767 [000] 34.901271: sched_stat_runtime: comm=in:imuxsock pid=1767 runtime=28500 [ns] vruntime=6079334487 [ns] in:imuxsock-1767 [000] 34.901282: sched_stat_wait: comm=rs:main Q:Reg pid=1769 delay=28500 [ns] - in:imuxsock-1767 [000] 34.901287: sched_switch: in:imuxsock:1767 [120] S ==> rs:main Q:Reg:1769 [120] sshd-2450 [001] 34.901431: sched_stat_runtime: comm=rs:main Q:Reg pid=1769 runtime=160500 [ns] vruntime=6078970403 [ns] sshd-2450 [001] 34.901437: sched_stat_sleep: comm=in:imuxsock pid=1767 delay=160500 [ns] - sshd-2450 [001] 34.901443: sched_wakeup: in:imuxsock:1767 [120] success=1 CPU:000 rs:main-1769 [000] 34.901447: sched_stat_runtime: comm=rs:main Q:Reg pid=1769 runtime=15833 [ns] vruntime=6078986236 [ns] rs:main-1769 [000] 34.901457: sched_stat_wait: comm=in:imuxsock pid=1767 delay=15833 [ns] - rs:main-1769 [000] 34.901462: sched_switch: rs:main Q:Reg:1769 [120] S ==> in:imuxsock:1767 [120] in:imuxsock-1767 [000] 34.901490: sched_stat_runtime: comm=in:imuxsock pid=1767 runtime=43125 [ns] vruntime=6079377612 [ns] in:imuxsock-1767 [000] 34.901495: sched_stat_sleep: comm=rs:main Q:Reg pid=1769 delay=43125 [ns] - in:imuxsock-1767 [000] 34.901501: sched_wakeup: rs:main Q:Reg:1769 [120] success=1 CPU:000 in:imuxsock-1767 [000] 34.901511: sched_stat_runtime: comm=in:imuxsock pid=1767 runtime=21333 [ns] vruntime=6079398945 [ns] diff --git a/trappy/bare_trace.py b/trappy/bare_trace.py index 2d4400b..e4fec48 100644 --- a/trappy/bare_trace.py +++ b/trappy/bare_trace.py @@ -67,7 +67,7 @@ class BareTrace(object): return filters - def normalize_time(self, basetime=None): + def _normalize_time(self, basetime=None): """Normalize the time of all the trace classes :param basetime: The offset which needs to be subtracted from diff --git a/trappy/base.py b/trappy/base.py index 4502c77..3c4c7bd 100644 --- a/trappy/base.py +++ b/trappy/base.py @@ -92,7 +92,7 @@ class Base(object): e.g. "sched_switch:") but it can be anything else for trace points generated using trace_printk(). - :param parse_raw: If :code:`True`, raw trace data (-R option) to + :param parse_raw: If :code:`True`, raw trace data (-r option) to trace-cmd will be used :param fallback: If :code:`True`, the parsing class will be used @@ -179,6 +179,12 @@ class Base(object): self.line_array.append(line) self.data_array.append(data) + def conv_to_int(self, value): + # Handle false-positives for negative numbers + if value.lstrip("-").isdigit(): + value = int(value) + return value + def generate_data_dict(self, data_str): data_dict = {} prev_key = None @@ -190,10 +196,7 @@ class Base(object): data_dict[prev_key] += ' ' + field continue (key, value) = field.split('=', 1) - try: - value = int(value) - except ValueError: - pass + value = self.conv_to_int(value) data_dict[key] = value prev_key = key return data_dict diff --git a/trappy/dynamic.py b/trappy/dynamic.py index f764232..5b094ce 100644 --- a/trappy/dynamic.py +++ b/trappy/dynamic.py @@ -81,7 +81,7 @@ def register_dynamic_ftrace(class_name, unique_word, scope="all", the parsing of events and group them together) :type scope: str - :param parse_raw: If, true, raw trace output (-R flag) + :param parse_raw: If, true, raw trace output (-r flag) will be used :type parse_raw: bool diff --git a/trappy/ftrace.py b/trappy/ftrace.py index 6a31ec3..e308398 100644 --- a/trappy/ftrace.py +++ b/trappy/ftrace.py @@ -66,9 +66,6 @@ subclassed by FTrace (for parsing FTrace coming from trace-cmd) and SysTrace.""" events=[], window=(0, None), abs_window=(0, None)): super(GenericFTrace, self).__init__(name) - if not hasattr(self, "needs_raw_parsing"): - self.needs_raw_parsing = False - self.class_definitions.update(self.dynamic_classes.items()) self.__add_events(listify(events)) @@ -85,14 +82,10 @@ subclassed by FTrace (for parsing FTrace coming from trace-cmd) and SysTrace.""" setattr(self, attr, trace_class) self.trace_classes.append(trace_class) - self.__parse_trace_file(self.trace_path, window, abs_window) - if self.needs_raw_parsing and (self.trace_path_raw is not None): - self.__parse_trace_file(self.trace_path_raw, window, abs_window, - raw=True) - self.finalize_objects() - - if normalize_time: - self.normalize_time() + # save parameters to complete init later + self.normalize_time = normalize_time + self.window = window + self.abs_window = abs_window @classmethod def register_parser(cls, cobject, scope): @@ -133,6 +126,13 @@ subclassed by FTrace (for parsing FTrace coming from trace-cmd) and SysTrace.""" if cobject == obj: del scope_classes[name] + def _do_parse(self): + self.__parse_trace_file(self.trace_path) + self.finalize_objects() + + if self.normalize_time: + self._normalize_time() + def __add_events(self, events): """Add events to the class_definitions @@ -165,23 +165,15 @@ subclassed by FTrace (for parsing FTrace coming from trace-cmd) and SysTrace.""" trace_class = DynamicTypeFactory(event_name, (Base,), kwords) self.class_definitions[event_name] = trace_class - def __populate_data(self, fin, cls_for_unique_word, window, abs_window): + def __populate_data(self, fin, cls_for_unique_word): """Append to trace data from a txt trace""" - def contains_unique_word(line, unique_words=cls_for_unique_word.keys()): - for unique_word in unique_words: - if unique_word in line: - return True - return False - actual_trace = itertools.dropwhile(self.trace_hasnt_started(), fin) actual_trace = itertools.takewhile(self.trace_hasnt_finished(), actual_trace) for line in actual_trace: - if not contains_unique_word(line): - self.lines += 1 - continue + trace_class = None for unique_word, cls in cls_for_unique_word.iteritems(): if unique_word in line: trace_class = cls @@ -189,7 +181,8 @@ subclassed by FTrace (for parsing FTrace coming from trace-cmd) and SysTrace.""" break else: if not trace_class: - raise FTraceParseError("No unique word in '{}'".format(line)) + self.lines += 1 + continue line = line[:-1] @@ -212,17 +205,18 @@ subclassed by FTrace (for parsing FTrace coming from trace-cmd) and SysTrace.""" if not self.basetime: self.basetime = timestamp - if (timestamp < window[0] + self.basetime) or \ - (timestamp < abs_window[0]): + if (timestamp < self.window[0] + self.basetime) or \ + (timestamp < self.abs_window[0]): self.lines += 1 continue - if (window[1] and timestamp > window[1] + self.basetime) or \ - (abs_window[1] and timestamp > abs_window[1]): + if (self.window[1] and timestamp > self.window[1] + self.basetime) or \ + (self.abs_window[1] and timestamp > self.abs_window[1]): return # Remove empty arrays from the trace - data_str = re.sub(r"[A-Za-z0-9_]+=\{\} ", r"", data_str) + if "={}" in data_str: + data_str = re.sub(r"[A-Za-z0-9_]+=\{\} ", r"", data_str) trace_class.append_data(timestamp, comm, pid, cpu, self.lines, data_str) self.lines += 1 @@ -258,7 +252,7 @@ is part of the trace. """ return lambda x: True - def __parse_trace_file(self, trace_file, window, abs_window, raw=False): + def __parse_trace_file(self, trace_file): """parse the trace and create a pandas DataFrame""" # Memoize the unique words to speed up parsing the trace file @@ -266,9 +260,6 @@ is part of the trace. for trace_name in self.class_definitions.iterkeys(): trace_class = getattr(self, trace_name) - if self.needs_raw_parsing and (trace_class.parse_raw != raw): - continue - unique_word = trace_class.unique_word cls_for_unique_word[unique_word] = trace_class @@ -279,7 +270,7 @@ is part of the trace. with open(trace_file) as fin: self.lines = 0 self.__populate_data( - fin, cls_for_unique_word, window, abs_window) + fin, cls_for_unique_word) except FTraceParseError as e: raise ValueError('Failed to parse ftrace file {}:\n{}'.format( trace_file, str(e))) @@ -549,13 +540,25 @@ class FTrace(GenericFTrace): def __init__(self, path=".", name="", normalize_time=True, scope="all", events=[], window=(0, None), abs_window=(0, None)): - self.trace_path, self.trace_path_raw = self.__process_path(path) - self.needs_raw_parsing = True - - self.__populate_metadata() - super(FTrace, self).__init__(name, normalize_time, scope, events, window, abs_window) + self.raw_events = [] + self.trace_path = self.__process_path(path) + self.__populate_metadata() + self._do_parse() + + def __warn_about_txt_trace_files(self, trace_dat, raw_txt, formatted_txt): + self.__get_raw_event_list() + warn_text = ( "You appear to be parsing both raw and formatted " + "trace files. TRAPpy now uses a unified format. " + "If you have the {} file, remove the .txt files " + "and try again. If not, you can manually move " + "lines with the following events from {} to {} :" + ).format(trace_dat, raw_txt, formatted_txt) + for raw_event in self.raw_events: + warn_text = warn_text+" \"{}\"".format(raw_event) + + raise RuntimeError(warn_text) def __process_path(self, basepath): """Process the path and return the path to the trace text file""" @@ -566,32 +569,42 @@ class FTrace(GenericFTrace): trace_name = os.path.join(basepath, "trace") trace_txt = trace_name + ".txt" - trace_raw = trace_name + ".raw.txt" + trace_raw_txt = trace_name + ".raw.txt" trace_dat = trace_name + ".dat" if os.path.isfile(trace_dat): - # Both TXT and RAW traces must always be generated - if not os.path.isfile(trace_txt) or \ - not os.path.isfile(trace_raw): + # Warn users if raw.txt files are present + if os.path.isfile(trace_raw_txt): + self.__warn_about_txt_trace_files(trace_dat, trace_raw_txt, trace_txt) + # TXT traces must always be generated + if not os.path.isfile(trace_txt): self.__run_trace_cmd_report(trace_dat) - # TXT (and RAW) traces must match the most recent binary trace + # TXT traces must match the most recent binary trace elif os.path.getmtime(trace_txt) < os.path.getmtime(trace_dat): self.__run_trace_cmd_report(trace_dat) - if not os.path.isfile(trace_raw): - trace_raw = None + return trace_txt - return trace_txt, trace_raw + def __get_raw_event_list(self): + self.raw_events = [] + # Generate list of events which need to be parsed in raw format + for event_class in (self.thermal_classes, self.sched_classes, self.dynamic_classes): + for trace_class in event_class.itervalues(): + raw = getattr(trace_class, 'parse_raw', None) + if raw: + name = getattr(trace_class, 'name', None) + if name: + self.raw_events.append(name) def __run_trace_cmd_report(self, fname): - """Run "trace-cmd report fname > fname.txt" - and "trace-cmd report -R fname > fname.raw.txt" + """Run "trace-cmd report [ -r raw_event ]* fname > fname.txt" - The resulting traces are stored in files with extension ".txt" - and ".raw.txt" respectively. If fname is "my_trace.dat", the - trace is stored in "my_trace.txt" and "my_trace.raw.txt". The - contents of the destination files are overwritten if they - exist. + The resulting trace is stored in files with extension ".txt". If + fname is "my_trace.dat", the trace is stored in "my_trace.txt". The + contents of the destination file is overwritten if it exists. + Trace events which require unformatted output (raw_event == True) + are added to the command line with one '-r <event>' each event and + trace-cmd then prints those events without formatting. """ from subprocess import check_output @@ -601,8 +614,12 @@ class FTrace(GenericFTrace): if not os.path.isfile(fname): raise IOError("No such file or directory: {}".format(fname)) - raw_trace_output = os.path.splitext(fname)[0] + ".raw.txt" trace_output = os.path.splitext(fname)[0] + ".txt" + # Ask for the raw event list and request them unformatted + self.__get_raw_event_list() + for raw_event in self.raw_events: + cmd.extend([ '-r', raw_event ]) + cmd.append(fname) with open(os.devnull) as devnull: @@ -613,17 +630,9 @@ class FTrace(GenericFTrace): raise OSError(2, "trace-cmd not found in PATH, is it installed?") else: raise - - # Add the -R flag to the trace-cmd - # for raw parsing - cmd.insert(-1, "-R") - raw_out = check_output(cmd, stderr=devnull) - with open(trace_output, "w") as fout: fout.write(out) - with open(raw_trace_output, "w") as fout: - fout.write(raw_out) def __populate_metadata(self): """Populates trace metadata""" diff --git a/trappy/sched.py b/trappy/sched.py index 4a68f6a..84e30be 100644 --- a/trappy/sched.py +++ b/trappy/sched.py @@ -104,9 +104,10 @@ class SchedSwitch(Base): """Parse sched_switch""" unique_word = "sched_switch:" + parse_raw = True def __init__(self): - super(SchedSwitch, self).__init__(parse_raw=True) + super(SchedSwitch, self).__init__(parse_raw=self.parse_raw) def create_dataframe(self): self.data_array = [line.replace(" ==> ", " ", 1) diff --git a/trappy/systrace.py b/trappy/systrace.py index 2404f92..c7e65e4 100644 --- a/trappy/systrace.py +++ b/trappy/systrace.py @@ -63,6 +63,7 @@ class SysTrace(GenericFTrace): super(SysTrace, self).__init__(name, normalize_time, scope, events, window, abs_window) + self._do_parse() try: self._cpus = 1 + self.sched_switch.data_frame["__cpu"].max() except AttributeError: |