tracing/tracing/extras/importer/android/event_log_importer.html - Issue 1319013002: Android event log importer.

Side by Side Diff: tracing/tracing/extras/importer/android/event_log_importer.html

Issue 1319013002: Android event log importer. (Closed) Base URL: https://github.com/catapult-project/catapult.git@master

Patch Set: Created 5 years, 3 months ago

Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.

Jump to:

View unified diff | Download patch

OLD	NEW
(Empty)
	1 <!DOCTYPE html>

	2 <!--

	3 Copyright (c) 2015 The Chromium Authors. All rights reserved.

	4 Use of this source code is governed by a BSD-style license that can be

	5 found in the LICENSE file.

	6 -->

	7

	8 <link rel="import" href="/tracing/importer/importer.html">

	9 <link rel="import" href="/tracing/importer/simple_line_reader.html">

	10 <link rel="import" href="/tracing/model/activity.html">

	11 <link rel="import" href="/tracing/model/model.html">

	12

	13

	14 <script>

	15 /**

	16 * @fileoverview Imports android event log data into the trace model.

	17 * Android event log data contains information about activities that

	18 * are launched/paused, processes that are started, memory usage, etc.

	19 *

	20 * The current implementation only parses activity events, with the goal of

	21 * determining which Activity is running in the foreground for a process.

	22 *

	23 * This importer assumes the events arrive as a string. The unit tests provide

	24 * examples of the trace format.

	25 *
	dsinclair 2015/08/27 15:18:50 nit: remove blank line. nit: remove blank line. coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: remove blank line. Done.
	26 */

	27 'use strict';

	28

	29 tr.exportTo('tr.e.importer.android', function() {

	30 var Importer = tr.importer.Importer;

	31

	32 var ACTIVITY_STATE = {

	33 NONE: 'none',

	34 CREATED: 'created',

	35 STARTED: 'started',

	36 RESUMED: 'resumed',

	37 PAUSED: 'paused',

	38 STOPPED: 'stopped',

	39 DESTROYED: 'destroyed'

	40 };

	41

	42 var activityMap = {};

	43

	44 /**

	45 * Imports android event log data (adb logcat -b events)

	46 * @constructor

	47 */

	48 function EventLogImporter(model, events) {

	49 this.model_ = model;

	50 this.events_ = events;

	51 this.importPriority = 3;
	dsinclair 2015/08/27 15:18:50 nit: _ on importPriority nit: _ on importPriority coenen 2015/09/01 11:55:49 I think this is used externally to determine the o Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: _ on importPriority I think this is used externally to determine the order of import (other importers also declare this without _).
	52 }

	53

	54 // Generic format of event log entries.

	55 // Sample event log entry that this matches (split over 2 lines):

	56 // 08-11 13:12:31.405 880 2645 I am_focused_activity:

	57 // [0,com.google.android.googlequicksearchbox/com.google.android.launcher. GEL]
	Chris Craik 2015/08/27 17:09:05 "// @suppress longLineCheck" needed here? "// @suppress longLineCheck" needed here? coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 17:09:05, Chris Craik wrote: > "// @suppress longLineCheck" needed here? Done.
	58

	59 var eventLogActivityRE = new RegExp(

	60 '(\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}.\\d+)' +

	61 '\\s(\\d+)\\s(\\d+)\\s([A-Z])\\s' +
	dsinclair 2015/08/27 15:18:50 I think the s's on this line should be s+'s. It l I think the s's on this line should be s+'s. It looks like at least one space is required, yea? coenen 2015/09/01 11:55:49 Yeah agreed, done Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > I think the s*'s on this line should be s+'s. It looks like at least one space > is required, yea? Yeah agreed, done
	62 '(am_\\w+)\s:(.)');

	63

	64 var amCreateRE = new RegExp('\s\\[.,.,.,(.),.,.,.,.*\\]');
	dsinclair 2015/08/27 15:18:50 Having examples for each of these as was done on l Having examples for each of these as was done on line 57 would make determining the correctness of the RE's easier. coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > Having examples for each of these as was done on line 57 would make determining > the correctness of the RE's easier. Done.
	65 var amFocusedRE = new RegExp('\s\\[\\d+,(.)\\]');

	66 var amProcStartRE = new RegExp('\s\\[\\d+,\\d+,\\d+,.,activity,(.*)\\]');

	67 var amOnResumeRE = new RegExp('\s\\[\\d+,(.)\\]');

	68 var amOnPauseRE = new RegExp('\s\\[\\d+,(.)\\]');

	69 var amLaunchTimeRE = new RegExp('\s\\[\\d+,\\d+,(.),(\\d+),(\\d+)');

	70 var amDestroyRE = new RegExp('\s\\[\\d+,\\d+,\\d+,(.)\\]');

	71

	72 /**

	73 *
	dsinclair 2015/08/27 15:18:50 nit: remove blank line. nit: remove blank line. coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: remove blank line. Done.
	74 * @return {boolean} True when events is an android event log array.

	75 */

	76 EventLogImporter.canImport = function(events) {

	77 if (!(typeof(events) === 'string' \|\| events instanceof String))

	78 return false;

	79

	80 return eventLogActivityRE.test(events);

	81 };

	82

	83 EventLogImporter.prototype = {

	84 __proto__: Importer.prototype,

	85

	86 get model() {

	87 return this.model_;

	88 },

	89

	90 /**

	91 * @return {string} the full activity name (including package) from

	92 * a component

	93 */

	94 getFullActivityName: function(component) {

	95 var componentSplit = component.split('/');

	96 if (componentSplit[1].startsWith('.'))

	97 return componentSplit[0] + componentSplit[1];

	98

	99 return componentSplit[1];

	100 },

	101

	102 /**

	103 * @return {string} the process name of a component

	104 */

	105 getProcName: function(component) {

	106 var componentSplit = component.split('/');

	107 return componentSplit[0];

	108 },

	109

	110 findOrCreateActivity: function(activityName) {

	111 if (activityName in activityMap)

	112 return activityMap[activityName];

	113 var activity = {};

	114 activity.state = ACTIVITY_STATE.NONE;

	115 activity.name = activityName;

	116 activityMap[activityName] = activity;
	dsinclair 2015/08/27 15:18:50 var activity = { state: ACTIVITY_STATE.NONE, n var activity = { state: ACTIVITY_STATE.NONE, name: activityName, }; coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > var activity = { > state: ACTIVITY_STATE.NONE, > name: activityName, > }; Done.
	117 return activity;

	118 },

	119

	120 deleteActivity: function(activityName) {

	121 delete activityMap[activityName];

	122 },

	123

	124 handleCreateActivity: function(ts, pid, activityName) {
	dsinclair 2015/08/27 15:18:50 pid is passed into a bunch of these, but not used, pid is passed into a bunch of these, but not used, can it be removed from the signature of the methods that don't need it? coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > pid is passed into a bunch of these, but not used, can it be removed from the > signature of the methods that don't need it? Done.
	125 var activity = this.findOrCreateActivity(activityName);

	126 activity.state = ACTIVITY_STATE.CREATED;

	127 activity.createdTs = ts;

	128 },

	129

	130 handleFocusActivity: function(ts, pid, procName, activityName) {

	131 var activity = this.findOrCreateActivity(activityName);

	132 activity.lastFocusedTs = ts;

	133 },

	134

	135 handleProcStartForActivity: function(ts, pid, activityName) {

	136 var activity = this.findOrCreateActivity(activityName);

	137 activity.procStartTs = ts;

	138 },

	139

	140 handleOnResumeCalled: function(ts, pid, activityName) {

	141 var activity = this.findOrCreateActivity(activityName);

	142 activity.state = ACTIVITY_STATE.RESUMED;

	143 activity.lastResumeTs = ts;

	144 // On_resume_called shows the actual PID; use this
	dsinclair 2015/08/27 15:18:50 nit: on_remove_called (since that's the actual nam nit: on_remove_called (since that's the actual name). nit: period at the end of sentences. coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: on_remove_called (since that's the actual name). > > nit: period at the end of sentences. Done.
	145 // to link the activity up with a process later

	146 activity.pid = pid;

	147 },

	148

	149 handleOnPauseCalled: function(ts, pid, activityName) {

	150 var activity = this.findOrCreateActivity(activityName);

	151 activity.state = ACTIVITY_STATE.PAUSED;

	152 activity.lastPauseTs = ts;

	153 // Create a new AndroidActivity representing the foreground state,

	154 // but only if the pause happened within the model bounds

	155 if (ts > this.model_.bounds.min && ts < this.model_.bounds.max) {

	156 this.addActivityToProcess(activity);

	157 }
	dsinclair 2015/08/27 15:18:50 nit: don't need {}'s for single line body. nit: don't need {}'s for single line body. coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: don't need {}'s for single line body. Done.
	158 },

	159

	160 handleLaunchTime: function(ts, pid, activityName, launchTime) {

	161 var activity = this.findOrCreateActivity(activityName);

	162 activity.launchTime = launchTime;

	163 },

	164

	165 handleDestroyActivity: function(ts, pid, activityName) {

	166 this.deleteActivity(activityName);

	167 },

	168

	169 addActivityToProcess: function(activity) {

	170 if (activity.pid !== undefined) {
	dsinclair 2015/08/27 15:18:50 if (activity.pid === undefined) return; if (activity.pid === undefined) return; coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > if (activity.pid === undefined) > return; Done.
	171 var process = this.model_.getOrCreateProcess(activity.pid);

	172 // The range of the activity is the time from resume to time

	173 // of pause; limit the start time to the beginning of the model

	174 var range = tr.b.Range.fromExplicitRange(

	175 Math.max(this.model_.bounds.min, activity.lastResumeTs),

	176 activity.lastPauseTs);
	dsinclair 2015/08/27 15:18:50 Why does an activity only have one range? What hap Why does an activity only have one range? What happens if I switch between two activities a few times during a trace, won't this only record the last focus instead of all focused times? coenen 2015/09/01 11:55:49 With the current implementation, it'll add a separ Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > Why does an activity only have one range? What happens if I switch between two > activities a few times during a trace, won't this only record the last focus > instead of all focused times? With the current implementation, it'll add a separate activity instance for every pause. Focus/resume always come before pause, so they should be up to date. The reason I had Activity only implement one range is that every time an Activity is showing, it may have a different context (eg invoked for a different reason, or with different parameters). Not so much needed for Android, but I thought it would be a nicer abstraction for platforms in general.
	177 var newActivity = new tr.model.Activity(activity.name,

	178 'Android Activity', range,

	179 {created: activity.createdTs,

	180 procstart: activity.procStartTs,

	181 lastfocus: activity.lastFocusedTs});

	182 process.activities.push(newActivity);

	183 }

	184 },

	185

	186 parseAmLine_: function(line) {

	187 var match = eventLogActivityRE.exec(line);

	188 if (!match)

	189 return;

	190

	191 // Possible activity life-cycles:

	192 // 1) Launch from scratch:

	193 // - am_create_activity

	194 // - am_focused_activity

	195 // - am_proc_start

	196 // - am_proc_bound

	197 // - am_restart_activity

	198 // - am_on_resume_called

	199 // 2) Re-open existing activity

	200 // - am_focused_activity

	201 // - am_on_resume_called

	202

	203 // HACK: event log date format is "MM-DD" and doesn't contain the year;

	204 // to figure out the year, take the min bound of the model, convert

	205 // to real-time and use that as the year.

	206 // Working on getting Android event log to include the year.
	dsinclair 2015/08/27 15:18:50 Is there a bug for this we can link? Is there a bug for this we can link? coenen 2015/09/01 11:55:49 There is a CL for it here; https://android-review. There is a CL for it here; https://android-review.googlesource.com/#/c/168900/2 want me to put that or the internal bug in the comments here?
	207 var first_realtime_ts = this.model_.bounds.min -

	208 this.model_.realtime_to_monotonic_offset_ms;

	209 var year = new Date(first_realtime_ts).getFullYear();

	210 var ts = match[1].substring(0, 5) + '-' + year + ' ' +

	211 match[1].substring(5, match[1].length);

	212

	213 var monotonic_ts = Date.parse(ts) +

	214 this.model_.realtime_to_monotonic_offset_ms;

	215

	216 var pid = match[2];

	217 var action = match[5];

	218 var data = match[6];

	219 if (action === 'am_create_activity') {

	220 match = amCreateRE.exec(data);

	221 if (match && match.length >= 2) {

	222 this.handleCreateActivity(monotonic_ts, pid,

	223 this.getFullActivityName(match[1]));

	224 }

	225 } else if (action === 'am_focused_activity') {

	226 match = amFocusedRE.exec(data);

	227 if (match && match.length >= 2) {

	228 this.handleFocusActivity(monotonic_ts, pid,

	229 this.getProcName(match[1]), this.getFullActivityName(match[1]));

	230 }

	231 } else if (action === 'am_proc_start') {

	232 match = amProcStartRE.exec(data);

	233 if (match && match.length >= 2) {

	234 this.handleProcStartForActivity(monotonic_ts, pid,

	235 this.getFullActivityName(match[1]));

	236 }

	237 } else if (action === 'am_on_resume_called') {

	238 match = amOnResumeRE.exec(data);

	239 if (match && match.length >= 2) {

	240 this.handleOnResumeCalled(monotonic_ts, pid, match[1]);

	241 }
	dsinclair 2015/08/27 15:18:50 nit: {}'s nit: {}'s coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: {}'s Done.
	242 } else if (action === 'am_on_paused_called') {

	243 match = amOnPauseRE.exec(data);

	244 if (match && match.length >= 2) {

	245 this.handleOnPauseCalled(monotonic_ts, pid, match[1]);
	dsinclair 2015/08/27 15:18:50 nit: {}'s nit: {}'s coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > nit: {}'s Done.
	246 }

	247 } else if (action === 'am_activity_launch_time') {

	248 match = amLaunchTimeRE.exec(data);

	249 this.handleLaunchTime(monotonic_ts, pid,

	250 this.getFullActivityName(match[1]), match[2]);

	251 } else if (action === 'am_destroy_activity') {

	252 match = amDestroyRE.exec(data);

	253 if (match && match.length == 2) {

	254 this.handleDestroyActivity(monotonic_ts, pid,

	255 this.getFullActivityName(match[1]));

	256 }

	257 }

	258 },

	259

	260 importEvents: function(isSecondaryImport) {

	261 // Check if we have a mapping from real-time to CLOCK_MONOTONIC

	262 if (isNaN(this.model_.realtime_to_monotonic_offset_ms)) {

	263 console.log('Need a trace_event_clock_sync to map realtime.');
	dsinclair 2015/08/27 15:18:50 This should set an import error instead of logging This should set an import error instead of logging to the console. this.model_.importWarning({ type: 'event_log_clock_sync', message: 'Need a trace_event_clock_sync to map realtime clock.') }); Chris Craik 2015/08/27 17:09:05 I assume old devices won't have the trace event sy Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > This should set an import error instead of logging to the console. > > this.model_.importWarning({ > type: 'event_log_clock_sync', > message: 'Need a trace_event_clock_sync to map realtime clock.') > }); I assume old devices won't have the trace event sync, but will have these events (we just can't use them). How should that be treated? coenen 2015/09/01 11:55:49 Ok, changed to importWarning. I think we just refu Show quoted text On 2015/08/27 17:09:05, Chris Craik wrote: > On 2015/08/27 15:18:50, dsinclair wrote: > > This should set an import error instead of logging to the console. > > > > this.model_.importWarning({ > > type: 'event_log_clock_sync', > > message: 'Need a trace_event_clock_sync to map realtime clock.') > > }); > > I assume old devices won't have the trace event sync, but will have these events > (we just can't use them). How should that be treated? Ok, changed to importWarning. I think we just refuse to import in case it's missing. Anyway there shouldn't be trace files containing the event log but without the clock sync record, since the code to generate such combined trace files is not checked in yet. But they could be fed separately to the importers, in which case I think we should just bail out.
	264 return;

	265 }

	266 // Since the event log typically spans a much larger timeframe

	267 // than the ftrace data, we want to calculate the bounds of the existing

	268 // model, and dump all event log data outside of those bounds

	269 this.model_.updateBounds();

	270

	271 var lines = this.events_.split('\n');

	272 lines.forEach(this.parseAmLine_, this);

	273

	274 // Iterate over all created activities that are not destroyed yet

	275 for (var activityName in activityMap) {

	276 var activity = activityMap[activityName];

	277 // If we're still in the foreground, store the activity anyway

	278 if (activity.state == ACTIVITY_STATE.RESUMED) {

	279 // Set the pause timestamp to the end of the model bounds

	280 activity.lastPauseTs = this.model_.bounds.max;

	281 this.addActivityToProcess(activity);

	282 }

	283 }

	284 }

	285 };

	286

	287 tr.importer.Importer.register(EventLogImporter);
	dsinclair 2015/08/27 15:18:50 This was aliased above so just Importer should wor This was aliased above so just Importer should work. coenen 2015/09/01 11:55:49 Done. Show quoted text On 2015/08/27 15:18:50, dsinclair wrote: > This was aliased above so just Importer should work. Done.
	288

	289 return {

	290 EventLogImporter: EventLogImporter

	291 };

	292 });

	293 </script>

OLD	NEW

« no previous file with comments | « tracing/trace_viewer.gypi ('k') | tracing/tracing/extras/importer/linux_perf/ftrace_importer.html » ('j') | tracing/tracing/model/activity.html » ('J')