Confirmed users
398
edits
TaskTracer: Difference between revisions
/* Labels
No edit summary |
(/* Labels) |
||
| (17 intermediate revisions by 5 users not shown) | |||
| Line 1: | Line 1: | ||
== Introduction == | == Introduction == | ||
TaskTracer | TaskTracer remembers the '''correlation''' between Tasks and Runnables, across threads and processes. | ||
By looking at a task, TaskTracer tells you: | By looking at a task, TaskTracer tells you: | ||
* The “source events” of this task. | * The “source events” of this task. | ||
** IO events: touch events, key events, wifi daemon signal | ** IO events: touch events, key events, wifi daemon signal | ||
* | * Who, the other task, does create a task. | ||
* The timing a task was dispatched, run, and stopped. | |||
== Get log files == | |||
Compile Gecko or Firefox with following line in mozconfig. | |||
ac_add_options --enable-tasktracer | |||
Start logging with Gecko Profiler Addon. There is an option in the | |||
control panel of the addon to enable TaskTracer. | |||
Attach gdb to Firefox process, the chrome process, and run following | |||
command in gdb. | |||
(gdb) call profiler_save_profile_to_file_async(0.0, "/abs/to/logfile") | |||
(gdb) continue | |||
Waiting for a couple seconds, the file would be created. | |||
== Dump log == | |||
Get [https://bitbucket.org/thinker/tttools tttools] | |||
python dumplog.py /path/to/logfile | |||
== Task == | |||
A task is dispatched to a task queue at the time (in ms) given by | |||
|dispatchTime| attribute of the |Task| object. It is an array because | |||
of a runnable can be dispatched and ran for several times. | |||
|begin| is the time that the runnable/task was started to run. |end| | |||
is the time where the task finish it's work. | |||
{'begin': [u'1472463888021'], | |||
'dispatchTime': [u'1472463888021'], | |||
'end': [u'1472463888021'], | |||
'label': [], | |||
'parent': u'0', | |||
'process': 22525, | |||
'sourceEventId': u'0', | |||
'sourceEventType': u'0', | |||
'taskId': u'96744138362318', | |||
'thread': 22525, | |||
'timeDuration': 0, | |||
'vptr': '??'}, | |||
== Load log in python == | |||
import tttools | |||
profileobject = tttools.loadRawProfile('/abs/to/logfile') | |||
== Parent tasks == | |||
Parent task of a task is the one create and dispatch the task. You | |||
can find the parent task, parent's parent, ... and all ancestors with | |||
the following Python instructions. | |||
taskIdsOfAncestors = profileobject.findAncestors(GivenTaskId) | |||
import pprint | |||
pprint.pprint(profileobject.findTasks(taskIdsOfAncestors)) | |||
== Followers == | |||
Followers of a task are tasks that is created by the given task or | |||
it's followers. | |||
taskIdsOfFollowers = profileobject.findFollowers(GivenTaskId) | |||
import pprint | |||
pprint.pprint(profileobject.findTasks(taskIdsOfFollowers)) | |||
== Blocker tasks == | |||
You can find what tasks are blocked by the different in time of | |||
|dispatchTime| and |begin|. | |||
tasks = profileobject.findTasks(profileobject.findAncestors(GivenTaskId)) | |||
for task in tasks: | |||
queuingTIme = long(task.begin[0]) - long(task.dispatchTime[0]) | |||
print 'task: %s, thread: %d, queuingTime: %d' % (task.taskId, | |||
task.thread, | |||
queuingTime) | |||
The more time a task staying in the queue, the more time the task is | |||
blocked by other tasks. You can find what other tasks blocked a task | |||
with following instructions. | |||
task = profileobject.findTask(BlockedTaskId) | |||
blockerIds = | |||
profileobject.findTasksStartInTimeThread(int(task.dispatchTime[0]), | |||
int(task.begin[0]), | |||
task.thread) | |||
blockers = profileobject.findTasks(blockerIds) | |||
pprint.pprint(blockers) | |||
== Labels == | |||
You may need to attach some information or strings on tasks and to see | |||
strings in the log to help you to identify specific tasks. Following | |||
C++ code in Gecko would add a label, i.e. a string, on the current | |||
running task of this thread. | |||
#ifdef MOZ_TASK_TRACER | |||
#include "GeckoTaskTracer.h" | |||
#endif | |||
... | |||
#ifdef MOZ_TASK_TRACER | |||
mozilla::tasktracer::AddLabel("Event [%s] ...", str...); | |||
#endif | |||
Javascript adds labels with a special prefix. | |||
console.log("#tt# Log message"); // #tt# is the prefix. | |||
For the case of labeling at begin and end of a scope, |AutoScopedLabel| is a helper class to do that. | |||
{ | |||
#ifdef MOZ_TASK_TRACER | |||
AutoScopedLabel label("Event [%s] ...", str...); // label "Begin Event [...]..." | |||
#endif | |||
// do something .... | |||
} // label "End Event [...]..." | |||
The "Begin ..." label would be added when the instance of |AutoScopedLabel| was created. And, "End ..." label would be added when the instance was destroyed. | |||
== DESIGN == | |||
TaskTracer has 5 types of logs in its log files, | |||
DISPATCH, BEGIN, END, VTABLE, and LABEL. | |||
They are used to remember | |||
== | - what the task created and dispatched a new task to | ||
a target thread, | |||
- the time a task was started to run at the target thread, | |||
- the time a task had done its works, | |||
- the type (vtalbe of the class) of the runnable of a given task, and | |||
- labels that denote what was happened in a task. | |||
=== TASK ID === | |||
Each type of logs has a time stamp to denote when it was happened, and | |||
a task ID to uniquely identify a tasks. To make the running code | |||
knowning which task is running at a thread, the ID of the running task | |||
is stored in the TLS, e.q. thread local storage, when the event loop | |||
of the thread starts to run it. That means when a new task was | |||
created and dispatched, TaskTracer got the task ID of the running task | |||
of current thread from TLS, and denote it as the creator/parent of the | |||
new one. | |||
The IDs of a task and its parent task (from TLS) were recorded in a | |||
DISPATCH log when it was dispatched to correlates a task and its | |||
parent task. | |||
When an IPC message was sent, a new task was created and dispatched at | |||
receiving side to handle the message. TaskTracer stores the task ID | |||
of the sender of a message in its header, and uses that ID as the | |||
parent task ID of the task handling the message at receiving site. | |||
With this, TaskTracer correlates tasks over processes. | |||
=== SOURCE EVENT ID AND TYPE === | |||
Not all tasks are always created by another task. For example, a | |||
mouse event would create and dispatch a task to handle it, but the | |||
mouse event itself is no task. TaskTracer calls mouse events or other | |||
events from the kernel as source events. Every source event has an | |||
unique ID to identify it, and assign a type to identify whether it is | |||
a mouse event, keyboard event, ..., or network event. They are source | |||
event IDs and source event types. | |||
The tasks created by source events have no parent task ID, the value of | |||
its parent task ID is identical to its task ID. With this rule, users | |||
know a task was created for handling a source event if its task ID is | |||
identical to its parent task ID. | |||
Source event ID and type would be stored in TLS of threads. They are | |||
also retrieved from TLS and stored in the new runnable of a new task | |||
when the new task is created/dispatched. When a new task was started | |||
to run, the source event ID and type stored on it will be retrieved | |||
and stored to TLS too. That means source event ID and type would | |||
passing along all tasks created for the source event directly or | |||
indirectly. That means they are also dispatched along IPC messages. | |||
=== VTABLE === | |||
For C++, every virtual class, that means a class having at least one | |||
virtual method, has a vtab to store entry points of its virtual | |||
methods. A VTABLE log contains the address of vtab of the concrete | |||
class of an instance of Runnable (a task). With the address of the | |||
vtab of a task, TaskTracer can get the concrete class name of the task | |||
by symbolicating. People can understand the purpose of a task by its | |||
name. | |||