MozillaWiki

TaskTracer: Difference between revisions

Page Discussion

TaskTracer (view source)

Revision as of 07:42, 9 December 2016

914 bytes removed ,  9 December 2016
update for changes of tasktracer
(update for changes of tasktracer)
Line 1: Line 1:
== Introduction ==
== 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:
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
* 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 TaskTracer ==
Compile Gecko or Firefox with following line in mozconfig.
see https://bitbucket.org/thinker/tttools


=== mozilla-central ===
  ac_add_options --enable-tasktracer
'''1. Build and flash (built-in)'''


  cd B2G
Start logging with Gecko Profiler Addon. There is an option in the
export MOZ_TASK_TRACER=1; ./build.sh gecko
control panel of the addon to enable TaskTracer.
./flash.sh gecko


'''2. Get TaskTracer Converter'''
Attach gdb to Firefox process, the chrome process, and run following
command in gdb.


https://bugzilla.mozilla.org/show_bug.cgi?id=1098217
  (gdb) call mozilla_sampler_save_profile_to_file_async(0.0, "/abs/to/logfile")
  (gdb) continue


Since Converter hasn't been landed yet, please manually download the patch and apply to your B2G repo.
Waiting for a couple seconds, the file would be created.


'''3. Start profiling'''
== Dump log ==
  python dumplog.py /path/to/logfile


./profile.sh start -f tasktracer
== Task ==


You can still combine the "tasktracer" feature with other supported flags of "start" command. For example, <code> ./profile.sh start -f tasktracer,js,leaf -i 50</code> will start profiling on all processes with tasktracer and default features, and longer the sampling interval to 50 milliseconds.
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.


Please note that because TaskTracer is design to record the correlation of tasks between threads and processes, enabling this feature will start profiling on all processes, which says, later commands such as <code>./profile.sh start -p aProcessName</code> will be invalid.
|begin| is the time that the runnable/task was started to run. |end|
is the time where the task finish it's work.


'''4. Capture profiling results'''
  {'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': '??'},


./profile.sh capture


In additional to the original results of GeckoProfiler, turning on <code>-f tasktracer</code> should find a section of TaskTracer data inserted into each output files. The first recording period is from the time of <code>./profile.sh start</code> till the time of first <code>./profile.sh capture</code>, the next recording period is then from the time of this <code>capture</code> till the next <code>capture</code>...and so on.
== Load log in python ==
  import tttools
  profileobject = tttools.loadRawProfile('/abs/to/logfile')


<code>./profile.sh stop</code> kills all processes and reboots b2g.
== Parent tasks ==


=== v1.3T ===
Parent task of a task is the one create and dispatch the task. You
1. Get the source code of TaskTracer.
can find the parent task, parent's parent, ... and all ancestors with
the following Python instructions.


git clone https://github.com/shellylin/gecko-dev/tree/tt-1.3t
  taskIdsOfAncestors = profileobject.findAncestors(GivenTaskId)
  import pprint
  pprint.pprint(profileobject.findTasks(taskIdsOfAncestors))


2. Build and flash to a real device.
== Followers ==


cd B2G
Followers of a task are tasks that is created by the given task or
export MOZ_TASK_TRACER=1; ./build.sh gecko
it's followers.
./flash.sh gecko


3. Get the source code of data retriever and data converter.
  taskIdsOfFollowers = profileobject.findFollowers(GivenTaskId)
  import pprint
  pprint.pprint(profileobject.findTasks(taskIdsOfFollowers))


git clone https://github.com/ginayeh/task-tracer-converter
== Blocker tasks ==


4. Start profiling.
You can find what tasks are blocked by the different in time of
|dispatchTime| and |begin|.


cd task-tracer-converter
  tasks = profileobject.findTasks(profileobject.findAncestors(GivenTaskId))
./tasktracer.sh start
  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)


5. Stop profiling.
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.


   ./tasktracer.sh stop
   task = profileobject.findTask(BlockedTaskId)
  blockerIds =
    profileobject.findTasksStartInTimeThread(int(task.dispatchTime[0]),
                                            int(task.begin[0]),
    task.thread)
  blockers = profileobject.findTasks(blockerIds)
  pprint.pprint(blockers)


The raw log is written into ''task_tracer_data.logcat''.
== Labels ==


6. Get memory maps from the real device.
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
mkdir mmaps
C++ code in Gecko would add a label, i.e. a string, on the current
./tasktracer.sh get_mmaps
running task of this thread.
 
The memory maps pulled out from the real device are put under mmaps directory automatically.
 
7. Prepare data for extracting class/task name.
 
  ./prepare-data.sh mmaps ''$objdir''
 
Two intermediate files are generated for later use: ''mem_offset'', ''symbol''.
 
8. Convert raw log to JSON format.
 
python task_tracer_converter.py -i task_tracer_data.logcat [-o task_tracer_data.json] [-w]
 
Default output filename: ''task_tracer_data.json''.
 
== How to add TaskTracer labels ==
 
Our ''ultimate'' goal is to leverage labels or debugging information that already existed in the gecko code base. As in current phase, we provide a quick and easy way for developers to add debugging messages.
 
=== For Gecko developers ===


  #ifdef MOZ_TASK_TRACER
   #include "GeckoTaskTracer.h"
   #include "GeckoTaskTracer.h"
   mozilla::tasktracer::AddLabel(msg_with_printf_format_string);
  #endif
 
  ...
For example, <code> AddLabel("Function %d is called %d times.", name, count); </code>
   mozilla::tasktracer::AddLabel("Event [%s] ...", str...);
[[image:GeckoLabel.png|none|thumb|1000px|[[help:contents|Screenshot of labels displayed in Nephthys, each label represented as a red dot on the task. Message of label is shown at the bottom of task info on left.]]]]
===For Gaia developers===
 
Simply prefix '''#tt#''' to your console.log message, message can still be found in adb logcat.
 
  console.log("#tt#"+console_log_format_string);
 
[[image:GaiaLabel.png|none|thumb|1000px|[[help:contents|Screenshot of labels add from javascript files.]]]]
 
In frank, <code>AddLabel()</code> functions like printf and console.log.
 
== How to read the profile using Nephthys ==
 
Import the json file to Nephthys, http://alivedise.github.io/nephthys/


== Work in progress ==
Javascript adds labels with a special prefix.
<bugzilla>
{
"f1":"blocked",
"o1":"equals",
"v1":"995058"
}
</bugzilla>
== Reference links ==
* {{bug|995058}} - [Meta] TaskTracer and Nephthys
* Nephthys
** http://alivedise.github.io/nephthys/
** https://github.com/alivedise/nephthys/tree/gh-pages
* FoxGuide
** https://addons.mozilla.org/en-US/firefox/addon/foxguide/


== TODO ==
  console.log("#tt# Log message"); // #tt# is the prefix.
* Thread pool
* CpuTime
* Integrate with Cleopatra
* Nested loop
* Ruler
Thinker
Confirmed users
398

edits

Retrieved from "https://wiki.mozilla.org/Special:MobileDiff/1156610"