Add more information/labels for TaskTracer.

RESOLVED FIXED

Status

()

defect
RESOLVED FIXED
3 years ago
7 months ago

People

(Reporter: sinker, Assigned: sinker)

Tracking

(Blocks 1 bug)

Trunk
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox53 affected)

Details

Attachments

(10 attachments, 4 obsolete attachments)

23.25 KB, patch
Details | Diff | Splinter Review
10.23 KB, patch
sinker
: review+
Details | Diff | Splinter Review
2.08 KB, patch
Details | Diff | Splinter Review
3.82 KB, patch
Details | Diff | Splinter Review
1.54 KB, patch
Details | Diff | Splinter Review
2.61 KB, patch
Details | Diff | Splinter Review
1.88 KB, patch
Details | Diff | Splinter Review
5.78 KB, patch
Details | Diff | Splinter Review
1.91 KB, patch
sinker
: review+
cbook
: checkin+
Details | Diff | Splinter Review
9.04 KB, patch
sinker
: review+
cbook
: checkin+
Details | Diff | Splinter Review
Bug 1287392 has fixed TaskTracer, and make it work again.  It is worth to add some more information for TaskTracer to make it useful.
Posted patch add-sourceevent-for-http.diff (obsolete) — Splinter Review
WIP
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.
This patch handle runnables of the STS thread and the Cache thread for tasktracer.
Attachment #8813515 - Attachment is obsolete: true
Attachment #8816147 - Flags: review?(honzab.moz)
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
Attachment #8816147 - Flags: review?(honzab.moz) → review+
(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.
(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.
r=honzab
Attachment #8816147 - Attachment is obsolete: true
Attachment #8817691 - Flags: review+
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/66d47555ad22
Handle TaskTracer at STS thread and Cache thread. r=honzab
Keywords: checkin-needed
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?
Posted patch Add class AutoScopedLabel (obsolete) — Splinter Review
(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.
Attachment #8821989 - Flags: review?(cyu)
Attachment #8821994 - Flags: review?(cyu)
Attachment #8821994 - Flags: review?(wmccloskey)
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.
Attachment #8821994 - Flags: review?(cyu) → review+
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.
Attachment #8821989 - Flags: review?(cyu) → review+
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.
(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.
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 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
(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 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.
Attachment #8821994 - Flags: review?(wmccloskey) → review+
I have added basic ideas and the design of TaskTracer on https://wiki.mozilla.org/TaskTracer. 
Hope it will help you.
Attachment #8825251 - Flags: review?(cyu)
--
Attachment #8821989 [details] [diff] - Attachment is obsolete: true
Attachment #8821989 - Attachment is obsolete: true
--
Attachment #8821994 [details] [diff] - Attachment is obsolete: true
Attachment #8821994 - Attachment is obsolete: true
Comment on attachment 8825257 [details] [diff] [review]
Add class AutoScopedLabel

r=cyu
Attachment #8825257 - Flags: review+
Comment on attachment 8825258 [details] [diff] [review]
Add TaskTracer labels for IPC messages

r=cyu,billm
Attachment #8825258 - Flags: review+
Attachment #8825257 - Flags: checkin?
Attachment #8825258 - Flags: checkin?
Attachment #8825258 - Flags: checkin?
Thinker, what should land here ?  just Attachment #8825257 [details] [diff]
Flags: needinfo?(tlee)
Flags: needinfo?(tlee)
Attachment #8825258 - Flags: checkin?
(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!
Pushed by cbook@mozilla.com:
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
Attachment #8825257 - Flags: checkin? → checkin+
Attachment #8825258 - Flags: checkin? → checkin+
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.
Attachment #8825251 - Flags: review?(cyu)
The leave-open keyword is there and there is no activity for 6 months.
:gregtatum, maybe it's time to close this bug?
Flags: needinfo?(gtatum)
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.
Status: NEW → RESOLVED
Closed: 7 months ago
Flags: needinfo?(gtatum)
Resolution: --- → FIXED
Assignee: nobody → thinker.li
You need to log in before you can comment on or make changes to this bug.