1319669 - Add more information/labels for TaskTracer.

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Thinker Li [:sinker]]

Bug 1287392 has fixed TaskTracer, and make it work again.  It is worth to add some more information for TaskTracer to make it useful.

Comment 1

[Thinker Li [:sinker]]

Attachment: add-sourceevent-for-http.diff

WIP

Comment 2

[Thinker Li [:sinker]]

Attachment: labels-and-virtualtasks.diff

WIP

Comment 3

[Honza Bambas (:mayhemer)]

According the changes to CacheEntry and around, I think you more want to instrument the cache thread event queue.  I already do that in my backtrack patch.

Note that I want to return to backtrack and start landing it till the end of this year.

Comment 4

[Thinker Li [:sinker]]

Attachment: Handle TaskTracer at STS thread and Cache thread

This patch handle runnables of the STS thread and the Cache thread for tasktracer.

Comment 5

[Honza Bambas (:mayhemer)]

Comment on attachment 8816147 [details] [diff] [review]
Handle TaskTracer at STS thread and Cache thread

Review of attachment 8816147 [details] [diff] [review]:
-----------------------------------------------------------------

You know what's funny?  I'm soon going to start landing my backtrack patches that add very similar kind of instrumentation...

And FYI, I'm NOT going to use TaskTracer code for backtracking.  They will live together and do similar stuff...

But we can find some conclusion later for that.

::: netwerk/protocol/http/HttpChannelChild.cpp
@@ +45,5 @@
>  #endif
>  
> +#ifdef MOZ_TASK_TRACER
> +#include "GeckoTaskTracer.h"
> +using namespace mozilla::tasktracer;

don't use using please.  classify on all places.

@@ +1924,5 @@
> +  nsCOMPtr<nsIURI> uri;
> +  GetURI(getter_AddRefs(uri));
> +  nsAutoCString urispec;
> +  uri->GetSpec(urispec);
> +  AddLabel("HttpChannelChild::AsyncOpen %s", urispec.get());

is AddLabel part of the tt namespace?  if so, then please classify

Comment 6

[Thinker Li [:sinker]]

(In reply to Honza Bambas (:mayhemer) from comment #5)
> Comment on attachment 8816147 [details] [diff] [review]
> Handle TaskTracer at STS thread and Cache thread
> 
> Review of attachment 8816147 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> You know what's funny?  I'm soon going to start landing my backtrack patches
> that add very similar kind of instrumentation...

Maybe, we should call everyone working on instrumentation stuffs together at some point (a workweek maybe).  People can share ideas and work out an infrastructure that everybody can based on.
So far, at least everybody need ways of making labels, storing logs, and retrieving logs.

Comment 7

[Honza Bambas (:mayhemer)]

(In reply to Thinker Li [:sinker] from comment #6)
> (In reply to Honza Bambas (:mayhemer) from comment #5)
> > Comment on attachment 8816147 [details] [diff] [review]
> > Handle TaskTracer at STS thread and Cache thread
> > 
> > Review of attachment 8816147 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > You know what's funny?  I'm soon going to start landing my backtrack patches
> > that add very similar kind of instrumentation...
> 
> Maybe, we should call everyone working on instrumentation stuffs together at
> some point (a workweek maybe).  People can share ideas and work out an
> infrastructure that everybody can based on.
> So far, at least everybody need ways of making labels, storing logs, and
> retrieving logs.

Not a bad idea!  For now let's leave these two coexist together.  It may also show the differences and similarities.  We can always coalesce later.

I would also be super happy to find some way how to as-much-as-possible automatically track runnables and generally queued tasks.  I had to dive deeply to the js interpreter and compiler to link compilation et al tasks together.  And it of course breaks every now and so as the js code changes.  And that's only one example.

I think chromium has some base class that everything that is a task must derive from to allow exactly this kind of tracking automatically.  Maybe we should propose something similar.  But that is for larger discussion, definitely not in this bug.

Comment 8

[Thinker Li [:sinker]]

Attachment: Handle TaskTracer at STS thread and Cache thread

r=honzab

Comment 9

[Thinker Li [:sinker]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=824bbb51ebd041abaaabefeb4d23815c459e27f2

Comment 10

[Thinker Li [:sinker]]

please land attachment 8817691 [details] [diff] [review].  Thanks!

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/66d47555ad22
Handle TaskTracer at STS thread and Cache thread. r=honzab

Comment 12

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/66d47555ad22

Comment 13

[Markus Stange [:mstange]]

Comment on attachment 8817691 [details] [diff] [review]
Handle TaskTracer at STS thread and Cache thread

Review of attachment 8817691 [details] [diff] [review]:
-----------------------------------------------------------------

::: netwerk/protocol/http/HttpChannelChild.cpp
@@ +1925,5 @@
> +  nsAutoCString urispec;
> +  uri->GetSpec(urispec);
> +  tasktracer::AddLabel("HttpChannelChild::AsyncOpen %s", urispec.get());
> +#endif
> +  

Unnecessary empty line with white space

::: netwerk/protocol/http/nsHttpChannel.cpp
@@ +5656,5 @@
> +#ifdef MOZ_TASK_TRACER
> +    {
> +        uint64_t sourceEventId, parentTaskId;
> +        tasktracer::SourceEventType sourceEventType;
> +        GetCurTraceInfo(&sourceEventId, &parentTaskId, &sourceEventType);

These variables are unused. Is there a reason to call GetCurTraceInfo? Does it have side effects?

Comment 14

[Thinker Li [:sinker]]

Attachment: Add class AutoScopedLabel

Comment 15

[Thinker Li [:sinker]]

Attachment: Add TaskTracer labels for synchronized reflows

Comment 16

[Thinker Li [:sinker]]

Attachment: Add TaskTracer labels for nsScriptLoader

Comment 17

[Thinker Li [:sinker]]

Attachment: Add TaskTracer labels for speculative loads

Comment 18

[Thinker Li [:sinker]]

Attachment: Add TaskTracer labels for refresh driver

Comment 19

[Thinker Li [:sinker]]

Attachment: Add TaskTracer labels for IPC messages

Comment 20

[Thinker Li [:sinker]]

Attachment: Remove unused code

Comment 21

[Thinker Li [:sinker]]

(In reply to Markus Stange [:mstange] from comment #13)
> > +        tasktracer::SourceEventType sourceEventType;
> > +        GetCurTraceInfo(&sourceEventId, &parentTaskId, &sourceEventType);
> 
> These variables are unused. Is there a reason to call GetCurTraceInfo? Does
> it have side effects?

You are right!  I will remove it later.

Comment 22

[Cervantes Yu [:cyu] [:cervantes]]

Comment on attachment 8821994 [details] [diff] [review]
Add TaskTracer labels for IPC messages

Review of attachment 8821994 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM. Please address the following:

::: ipc/chromium/src/chrome/common/ipc_channel_posix.cc
@@ -543,5 @@
> -      SetCurTraceInfo(m.header()->source_event_id,
> -                      m.header()->parent_task_id,
> -                      m.header()->source_event_type);
> -#endif
> -

Please remove the #ifdef MOZ_TASK_TRACER at the beginning of this file. It's no longer used.

Comment 23

[Cervantes Yu [:cyu] [:cervantes]]

Comment on attachment 8821989 [details] [diff] [review]
Add class AutoScopedLabel

Review of attachment 8821989 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with the following addressed:

::: tools/profiler/tasktracer/GeckoTaskTracer.cpp
@@ +397,5 @@
> +    va_start(args, aFormat);
> +    label.AppendPrintf(aFormat, args);
> +    va_end(args);
> +    mLabel = strdup(label.get());
> +    AddLabel("Begin %s", mLabel);

I think you can use UniquePtr<nsCString> for mLabel. The you only have to construct one nsCString and avoids the strdup() call.

Comment 24

[Markus Stange [:mstange]]

I wonder if it would make sense to have PROFILER_LABEL and PROFILER_LABEL_PRINTF automatically add task tracer labels. Some of these annotations look like duplicated effort.

Comment 25

[Thinker Li [:sinker]]

(In reply to Markus Stange [:mstange] from comment #24)
> I wonder if it would make sense to have PROFILER_LABEL and
> PROFILER_LABEL_PRINTF automatically add task tracer labels. Some of these
> annotations look like duplicated effort.

I would say YES to the idea.  Once upon a time, IIRC, it was, but had been removed for some reason I have forget.

Comment 26

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Is there a comment somewhere that explains in detail how TaskTracer works? What is the purpose of the vtable stuff? I'm worried that we're accumulating a lot of similar facilities for labeling/tracing tasks.

Comment 27

[Markus Stange [:mstange]]

Comment on attachment 8821994 [details] [diff] [review]
Add TaskTracer labels for IPC messages

So this patch creates a new "task" for each MessageTask and additionally adds a label with the message name. Does the existing MessageChannel::MessageTask task still get added to the tasktracer log or does something prevent that?
Why did you decide to create a new task type (i.e. new calls to tasktracer::Log*()) instead of just adding a label to the existing MessageChannel::MessageTask tasks?

Here's a patch that just adds a tasktracer label for received IPC messages, in the same place where the PROFILER_LABEL for received messages is added: https://pastebin.mozilla.org/8956916

Comment 28

[Markus Stange [:mstange]]

(In reply to Bill McCloskey (:billm) from comment #26)
> Is there a comment somewhere that explains in detail how TaskTracer works?

I don't think so. There's a tiny bit of info on https://wiki.mozilla.org/TaskTracer and I found the switch at http://searchfox.org/mozilla-central/rev/51aa673e28802fe6ea89f4793721fc55334a6ac8/tools/profiler/tasktracer/GeckoTaskTracer.cpp#448 somewhat useful.

> What is the purpose of the vtable stuff?

It gives a "name" to each task tracer task. The scripts that postprocess the tasktracer output can symbolicate the vtable pointer of the dispatched Runnable instance to the class name of the concrete Runnable subclass.
The alternative would be to put strings all over the place or to add macros for Runnable subclasses that automatically add those strings.

> I'm worried that we're accumulating
> a lot of similar facilities for labeling/tracing tasks.

There are efforts underway to unify all of our data gathering, headed by Jim Blandy. We're currently in a state where we're exploring different data gathering systems in parallel, in order to inform what scenarios the unified system will need to support. I expect we'll have a bunch of data gathering duplication in the short term.

Comment 29

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Comment on attachment 8821994 [details] [diff] [review]
Add TaskTracer labels for IPC messages

Review of attachment 8821994 [details] [diff] [review]:
-----------------------------------------------------------------

OK. I don't really understand this, but I guess it's off by default. I really think we need better documentation for this though. I don't see how anyone else could usefully contribute to this code otherwise. What is the difference between the task ID and the source event ID, for example? Also, it seems like the API could be cleaner. Could AutoTaskTracerRun inherit from something that automatically calls the logging functions? You could just specify the message data to the constructor.

::: ipc/chromium/src/chrome/common/ipc_message.cc
@@ +145,5 @@
>  
>  #endif
>  
> +#ifdef MOZ_TASK_TRACER
> +void *MessageTask() {

This should be declared static so it doesn't pollute the global namespace.

Comment 30

[Thinker Li [:sinker]]

I have added basic ideas and the design of TaskTracer on https://wiki.mozilla.org/TaskTracer. 
Hope it will help you.

Comment 31

[Thinker Li [:sinker]]

Attachment: Explain data and types for TaskTracer

Comment 32

[Thinker Li [:sinker]]

Attachment: Add class AutoScopedLabel

--
Attachment #8821989 [details] [diff] - Attachment is obsolete: true

Comment 33

[Thinker Li [:sinker]]

Attachment: Add TaskTracer labels for IPC messages

--
Attachment #8821994 [details] [diff] - Attachment is obsolete: true

Comment 34

[Thinker Li [:sinker]]

Comment on attachment 8825257 [details] [diff] [review]
Add class AutoScopedLabel

r=cyu

Comment 35

[Thinker Li [:sinker]]

Comment on attachment 8825258 [details] [diff] [review]
Add TaskTracer labels for IPC messages

r=cyu,billm

Comment 36

[Carsten Book [:Tomcat]]

Thinker, what should land here ?  just Attachment #8825257 [details] [diff]

Comment 37

[Thinker Li [:sinker]]

(In reply to Carsten Book [:Tomcat] from comment #36)
> Thinker, what should land here ?  just Attachment #8825257 [details] [diff] [diff]

Carsten, please land #8825257 and #8825258.  Thank you!

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/064692826549
Add class AutoScopedLabel. r=cyu
https://hg.mozilla.org/integration/mozilla-inbound/rev/f220fb732f2c
Add TaskTracer labels for IPC messages. r=cyu,billm

Comment 39

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/064692826549
https://hg.mozilla.org/mozilla-central/rev/f220fb732f2c

Comment 40

[Cervantes Yu [:cyu] [:cervantes]]

Comment on attachment 8825251 [details] [diff] [review]
Explain data and types for TaskTracer

Review of attachment 8825251 [details] [diff] [review]:
-----------------------------------------------------------------

Cancel the request because I think there are big issues with the comments that need to be addressed.
Also, I suggest finding a 2nd opinion.

::: tools/profiler/tasktracer/GeckoTaskTracer.cpp
@@ +504,5 @@
> +/**
> + * Return an C string as the prefix for TaskTracer labels.
> + *
> + * This prefix would be checked by console.log() to figure out if a
> + * log should be handled as a TaskTracer label.  It helps Web content

nit: s/a log/a log entry/.
Remove the extra space before "It helps Web content..."

::: tools/profiler/tasktracer/GeckoTaskTracerImpl.h
@@ +13,5 @@
>  
>  namespace mozilla {
>  namespace tasktracer {
>  
> +// Following type are structures used for keeping logs internally.

nit: types.

@@ +55,5 @@
> +/**
> + * Keeping logs internally.
> + *
> + * To make memory management easiler and more efficient, this union is
> + * used for all types of logs for internal.  It would be converted to

nit: for all internal log types.

@@ +56,5 @@
> + * Keeping logs internally.
> + *
> + * To make memory management easiler and more efficient, this union is
> + * used for all types of logs for internal.  It would be converted to
> + * JSON to export to external representation.  See GetLoggedData().

nit: extra white space before "See GetLoggedData()".

@@ +75,5 @@
>  
> +/**
> + * TaskTracer's per-thread information.
> + *
> + * Every thread has an instance of TraceInfo stored in TLS.  It

nit: extra white space.

@@ +76,5 @@
> +/**
> + * TaskTracer's per-thread information.
> + *
> + * Every thread has an instance of TraceInfo stored in TLS.  It
> + * contains status of the thread for TaskTracer, including information

There are inconsistencies in the use of "information", and "status" here. Please make it consistently "info" or "status".

Also this keeps the status of TaskTracer for the thread, not the status of the thread for TaskTracer.

@@ +132,5 @@
>                       SourceEventType aSourceEventType);
>  
>  /**
>   * Logging functions of different trace actions.
>   */

This comment block doesn't belong here. Following this comment block is an enum, not logging functions.

@@ +135,5 @@
>   * Logging functions of different trace actions.
>   */
>  enum ActionType {
> +  /**
> +   * A new task had been created and dispatched.

Please be consistent in tense. I'd suggest using the present tense all the way. It'll make the statements concise.

I would say: "A new task is created and dispatched."

@@ +138,5 @@
> +  /**
> +   * A new task had been created and dispatched.
> +   *
> +   * It contains a timestamp, task id, parent task id, source event
> +   * id, and source event type.  See LogDispatch().

nit: extra space. Please remove all double space betw sentences. This looks weird.

@@ +149,5 @@
> +   * socket events, any event that comes from kernel.  Usually, there
> +   * is a task created for handling the source event.  As it happen,
> +   * the handling task has no parent task ID, the value of its parent
> +   * task ID would be identical to its task ID, and a new source event
> +   * ID would be generated and assigned.

The 2 paragraphs should not be here. They explains how TaskTracer works internally. Putting them before an enum value is strange.

@@ +155,1 @@
>    ACTION_DISPATCH = 0,

Please add one empty line after each enum value.

@@ +155,4 @@
>    ACTION_DISPATCH = 0,
> +  /**
> +   * The time that the target thread started to run a task.
> +   *

This enum value doesn't denote the "time". It denotes the action.

@@ +162,4 @@
>    ACTION_BEGIN,
> +  /**
> +   * The time that a task had done.
> +   *

Same here.

@@ +196,5 @@
>  void LogEnd(uint64_t aTaskId, uint64_t aSourceEventId);
>  
> +/**
> + * Keep the address of the vtab of the concrete class of a task.
> + *

nit: This is terse: lots of "of". Consider rephrasing.

Comment 41

[BugBot [:suhaib / :marco/ :calixte]]

The leave-open keyword is there and there is no activity for 6 months.
:gregtatum, maybe it's time to close this bug?

Comment 42

[Greg Tatum [:gregtatum] (REO Fx132)]

Closing as resolved, as some work was landed, the title is pretty open-ended, but no work is actively planned for this. Feel free to file new bugs with TaskTracer work as needed.