@@ Line 1: / Line 1: @@
 == Introduction ==
-TaskTracer aims at the '''correlation''' between Tasks and Runnables, across threads and processes.
+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
-* Where it is dispatched from.
+* Who, the other task, does create a task.
+* The timing a task was dispatched, run, and stopped.
+== Get log files ==
-== How to use Task Tracer ==
+Compile Gecko or Firefox with following line in mozconfig.
-== How to read the profile using Isis ==
+  ac_add_options --enable-tasktracer
-== Reference links ==
+Start logging with Gecko Profiler Addon.  There is an option in the
-* {{bug|908995}} - [B2G] Task tracer
+control panel of the addon to enable TaskTracer.
-** https://github.com/shellylin/gecko-dev/tree/tt-v4
-* {{bug|916409}} - Data retriever for task tracer
-* {{bug|956620}} - [B2G] Task tracer converter
-** https://github.com/ginayeh/task-tracer-converter
-* Isis
-** http://alivedise.github.io/isis/
-** https://github.com/alivedise/isis/tree/gh-pages
-== TODO ==
+Attach gdb to Firefox process, the chrome process, and run following
-* Integrate with built-in profiler.
+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.

TaskTracer: Difference between revisions

TaskTracer (view source)

Revision as of 08:30, 13 March 2017