TaskTracer

Introduction

TaskTracer remembers the correlation between Tasks and Runnables, across threads and processes.

By looking at a task, TaskTracer tells you:

• The “source events” of this task.
  • 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 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.