[RFC] Systrace's custom events formatting #243

derkling · 2017-04-26T10:55:05Z

The Android run-time can inject interesting function profiling events from user-space which unfortunately are not formatted using the key=value pairs required by TRAPpy.

The format string it uses is expected by other tools, e.g. systrace, thus changing the formatting at the source can be much more complex than dealing with in in TRAPpy. Since TRAPpy learnt to parse systrace events, we can try to improve its skills by properly parsing these custom events too.

The basic idea is to add a simple call-back based mechanism which allows a specific parser (i.e. SysTrace ) to reformat a data string into a TRAPpy compliant format before processing it the usual way.

This is an initial prototype which I share to get feedback on the overall approach before going further to develop more complex functionalities. Thus, I've not yet added a test for this feature, however a simple example trace can contain these events:

RenderThread-9568  ( 9546) [006] ...1  3210.844141: tracing_mark_write: B|9546|flush drawing commands
hwuiTask1-9571 ( 9546) [007] ...1  3210.844145: tracing_mark_write: E
hwuiTask1-9571 ( 9546) [007] ...1  3210.844151: tracing_mark_write: B|9546|tessellateAmbientShadow
hwuiTask1-9571 ( 9546) [007] ...1  3210.844159: tracing_mark_write: E
hwuiTask1-9571 ( 9546) [007] ...1  3210.844162: tracing_mark_write: B|9546|tessellateSpotShadow
hwuiTask1-9571 ( 9546) [007] ...1  3210.844182: tracing_mark_write: E

As additional goals, not yet provided by this prototype, it would be nice to:

support the generation and registration on-the-fly of new dataframes from within the callback, which should allow to create separate dataframe for different classes of custom events
make sure the systrace viewer and the TRAPpy generated dataframes are on the same timeline, which will require to play with basetime and windows... but, since this is a more complex task, I would keep this topic for a different PR.

Some run-times (e.g. Android) inject interesting events from user-space which unfortunately are not formatted using the `key=value` pairs required by TRAPpy. The format string they use is expected by other tools, e.g. systrace. Since TRAPpy learnt to parse systrace events, let's prepare the ground for him to improve its skills. This adds a simple call-back based mechanism which allows a parser to reformat a data string into a TRAPpy compliant format before processing it the usual way. Signed-off-by: Patrick Bellasi <patrick.bellasi@arm.com>

Android injects function profiling envets from using tracing_mark strings which are not formatted according to the `key=value` pari expected by TRAPpy. Let's use our `formad_data` callback to give the a proper shape. Signed-off-by: Patrick Bellasi <patrick.bellasi@arm.com>

This event is not really useful and, so far, it's the only one properly formatted using `key=value` pairs. Let's ignore it while we find a better way to synchronize TRAPpy and Systrace viewer times. Signed-off-by: Patrick Bellasi <patrick.bellasi@arm.com>

bjackman

Reformatting into a string and then parsing that string doesn't seem like the cleanest way to achieve this.

Do you think it's possible to instead make start_match more flexible in FTrace.__populate_data, then allow overriding the data_dict generation in Base.generate_parsed_data?

So we would modify FTrace.__populate_data so that data_str can be the raw "B|9546|tessellateSpotShadow" (probably by having something that SysTrace overrides, so we don't change behaviour for regular ftrace). Then instead of converting that to a "key=value" string, parse it directly into {'key': 'value'} dicts at a later stage in the parsing (i.e. an overridden method called from Base.generate_parsed_data).

Would need some investigation but if it's possible do you think that's a cleaner solution?

Edited to add: Just noticed the "overridden method called from Base.generate_parsed_data" I referred to is exactly the generate_data_dict method @joelagnel added in his PR.

bjackman · 2017-04-26T12:34:51Z

trappy/systrace.py

+                match.group('func'), match.group('data'))
+            return data_str
+
+        raise ValueError('Unexpected systrace marker: {}'.format(data_str))


I don't think it should be an error, anyone could put stuff in tracing_mark_write. Maybe log a warning?

Agreed. Logging a warning would be better.

Right, that was mainly for me while it's in development to check that with many different traces I'm actually matching all the possible custom events. Will change it to a warning.

sinkap · 2017-04-26T12:51:46Z

trappy/systrace.py

+                match.group('func'), match.group('data'))
+            return data_str
+
+        raise ValueError('Unexpected systrace marker: {}'.format(data_str))


Agreed. Logging a warning would be better.

sinkap · 2017-04-26T12:52:50Z

trappy/systrace.py

+        raise ValueError('Unexpected systrace marker: {}'.format(data_str))
+        return data_str
+
+SYSTRACE_EVENT = re.compile(


Can you add a comment about what this regular expression does. I know regexes are cool, but really hard to read and get right 😄

Actually a sample from the trace here would be good.

sinkap

Yep, generate_data_dict would be the way to go. Also can you add/update test cases for your change?

sinkap · 2017-04-26T12:53:19Z

trappy/systrace.py

+        raise ValueError('Unexpected systrace marker: {}'.format(data_str))
+        return data_str
+
+SYSTRACE_EVENT = re.compile(


Actually a sample from the trace here would be good.

derkling · 2017-04-26T12:59:13Z

The approach @bjackman suggested was already briefly discussed with @JaviMerino and @credp, and it actually I think it can make much sense... I just not implemented it to push out what I had so far and trigger the discussion. Especially in view of @joelagnel PR #241 ... we need to avoid overlapping features and I was wondering if what I'm proposing here should be better implemented using client callbacks.

What do you think? Do you think it can still be valuable for the SysTrace parser to support directly this additional parsing logic?

bjackman · 2017-04-26T13:00:26Z

Still investigating @joelagnel's PR but I think SysTrace should parse it directly.

joelagnel · 2017-06-09T18:19:23Z

Sorry for the late review on this.
I agree with the discussed approach of using generate_data_dict from the tracer in question. So probably the tracer should pass this function as a callback to the 'class Base' event objects?

@derkling also yes I think there is overlap with #241 but for slightly different purpose, we should definitely use that mechanism, and I think its also good because it might make support for #241 easier. At the moment I am dedicated to solving this systrace parsing problem because we need it for automated trace analysis so lets work together on this and get it done.

bjackman · 2017-06-12T09:58:44Z

I agree with the discussed approach of using generate_data_dict from the tracer in question. So probably the tracer should pass this function as a callback to the 'class Base' event objects?

Why a callback? Can't it just be an override?

kdub · 2017-11-06T20:17:56Z

Some examples of a custom parser I wrote recently (#271), if it provides any inspiration.

derkling added 3 commits April 26, 2017 11:32

derkling added the enhancement label Apr 26, 2017

derkling requested review from JaviMerino, sinkap and bjackman April 26, 2017 10:55

bjackman reviewed Apr 26, 2017

View reviewed changes

sinkap reviewed Apr 26, 2017

View reviewed changes

sinkap suggested changes Apr 26, 2017

View reviewed changes

sinkap self-assigned this Apr 26, 2017

This was referenced Jun 9, 2017

[RFC] trappy: add support for event callbacks #241

Closed

systrace parsing new edition #249

Closed

sinkap force-pushed the master branch 3 times, most recently from 6f40d93 to a84dd23 Compare June 14, 2017 21:41

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[RFC] Systrace's custom events formatting #243

[RFC] Systrace's custom events formatting #243

derkling commented Apr 26, 2017

bjackman left a comment •

edited

Loading

bjackman Apr 26, 2017

sinkap Apr 26, 2017

derkling Apr 26, 2017

sinkap Apr 26, 2017

sinkap Apr 26, 2017

sinkap Apr 26, 2017

sinkap left a comment

sinkap Apr 26, 2017

derkling commented Apr 26, 2017

bjackman commented Apr 26, 2017

joelagnel commented Jun 9, 2017 •

edited

Loading

bjackman commented Jun 12, 2017

kdub commented Nov 6, 2017

[RFC] Systrace's custom events formatting #243

Are you sure you want to change the base?

[RFC] Systrace's custom events formatting #243

Conversation

derkling commented Apr 26, 2017

bjackman left a comment • edited Loading

Choose a reason for hiding this comment

bjackman Apr 26, 2017

Choose a reason for hiding this comment

sinkap Apr 26, 2017

Choose a reason for hiding this comment

derkling Apr 26, 2017

Choose a reason for hiding this comment

sinkap Apr 26, 2017

Choose a reason for hiding this comment

sinkap Apr 26, 2017

Choose a reason for hiding this comment

sinkap Apr 26, 2017

Choose a reason for hiding this comment

sinkap left a comment

Choose a reason for hiding this comment

sinkap Apr 26, 2017

Choose a reason for hiding this comment

derkling commented Apr 26, 2017

bjackman commented Apr 26, 2017

joelagnel commented Jun 9, 2017 • edited Loading

bjackman commented Jun 12, 2017

kdub commented Nov 6, 2017

bjackman left a comment •

edited

Loading

joelagnel commented Jun 9, 2017 •

edited

Loading