1089514 - Task Tracer: Some traced tasks/runnables have record of dispatch, but no records of execution

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Shelly Lin [:shelly]]

From the logging results, we found that some (almost half?) of the traced tasks have record of dispatch, but no records of task begin and task end, which indicates that these tasks are dispatched but never been executed.

Comment 1

[Shelly Lin [:shelly]]

Attachment: Fix in FakeTracedTask

Comment 2

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Patch 1: Don't create a taskId for FakeTracedTask().

Comment 3

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Log virtual table pointer in CreateSourceEvent.

Comment 4

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

Attachment: [Debug only] Log tasks that doesn't have vptr printed

Comment 5

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: [Debug only] Log tasks that doesn't have vptr printed.

Comment 6

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Patch 1(v1)

1. For FakeTracedTask, remove copy constructor and define assignment operator. When we create an AutoRunFakeTracedTask, task information are copied from a FakeTracedTask in the assignment operation (http://dxr.mozilla.org/mozilla-central/source/tools/profiler/TracedTaskCommon.cpp#136).

2. An instance of AutoRunFakeTracedTask contains a FakeTracedTask. So, the default ctor of FakeTracedTask is invoked when an AutoRunFakeTracedTask is created, and then a new taskId is generated for the FakeTracedTask. Then, we override the task information with |mTracedTask| in the ctor of AutoRunFakeTracedTask.

In this case, no new taskId should be generated for the FakeTracedTask.

3. Add comments for timers.

Comment 7

[Shelly Lin [:shelly]]

Comment on attachment 8514075 [details] [diff] [review]
Patch 1(v1)

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

::: xpcom/threads/TimerThread.cpp
@@ +459,5 @@
>    aTimer->mArmed = true;
>    NS_ADDREF(aTimer);
>  
>  #ifdef MOZ_TASK_TRACER
> +  // Task Tracer should log dispatch time when a timer is added successfully.

Thanks Gina! How about the following message? It provides more information about the idea behinds our change here.

// The latency of a timer should be from when it is created and added to the timer queue till when it is about to execute. So TaskTracer will create a FakeTracedTask, and log the dispatch time here.

::: xpcom/threads/nsTimerImpl.cpp
@@ +561,5 @@
>  
>  #ifdef MOZ_TASK_TRACER
> +  // The timer is going to be executed. Task Tracer should log begin time in the
> +  // ctor of AutoRunFakeTracedTask and log end time in the dtor of
> +  // AutoRunFakeTracedTask.

// The timer is going to be executed. mTracedTask should be created and a dispatch entry of this timer is logged by TaskTracer at when this timer is added into the timer queue. TaskTracer will log the begin/end time of this timer in the ctor/dtor of AutoRunFakeTracedTask.

Comment 8

[Gina Yeh [:gyeh] [:ginayeh]]

It's much clear now. Thanks for your feedback, Shelly.

Comment 9

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Patch1(v2)

Thinker, please take a look at the fix. Thanks.

Comment 10

[Thinker Li [:sinker]]

(In reply to Gina Yeh [:gyeh] [:ginayeh] from comment #9)
> Created attachment 8514103 [details] [diff] [review]
> Patch1(v2)

Why need we to copy FakeTracedTask at the constructor of AutoRunFakeTracedTask?  If we hold a reference by AutoRunFakeTracedTask instead of a new copy, the problem is not exist, right?!

Comment 11

[Shelly Lin [:shelly]]

The reason we make a copy of FakeTracedTask instead of holding its reference, is because a timer might add itself back into the timer queue during its execution, meaning mTracedTask will be recreated before the call of its dtor.

But we have came out a solution for the problem, Gina will provide a patch soon. :)

Comment 12

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Patch1(v3)

Comment 13

[Gina Yeh [:gyeh] [:ginayeh]]

(In reply to Thinker Li [:sinker] from comment #10)
> (In reply to Gina Yeh [:gyeh] [:ginayeh] from comment #9)
> > Created attachment 8514103 [details] [diff] [review]
> > Patch1(v2)
> 
> Why need we to copy FakeTracedTask at the constructor of
> AutoRunFakeTracedTask?  If we hold a reference by AutoRunFakeTracedTask
> instead of a new copy, the problem is not exist, right?!

I agree! A new patch is created based on your suggestion. Please take some time on the new one. Thanks.

Comment 14

[Thinker Li [:sinker]]

Comment on attachment 8514913 [details] [diff] [review]
Patch1(v3)

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

::: tools/profiler/TracedTaskCommon.cpp
@@ -106,5 @@
>  {
>    LogVirtualTablePtr(mTaskId, mSourceEventId, aVptr);
>  }
>  
> -FakeTracedTask::FakeTracedTask(const FakeTracedTask& aTask)

We should make this copy constructor as in private instead of removing it.  Then ensure no more copying.

Comment 15

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Patch 1(v4)

Hi Thinker,

I've move the copy constructor to private part. Please review again. Thanks.

Comment 16

[Thinker Li [:sinker]]

Comment on attachment 8515773 [details] [diff] [review]
Patch 1(v4)

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

r+ with suggestions of comments.

::: xpcom/threads/TimerThread.cpp
@@ +461,5 @@
>  
>  #ifdef MOZ_TASK_TRACER
> +  // The latency of a timer should be from when it is created and added to the
> +  // timer queue till when it is about to execute. So TaskTracer will create a
> +  // FakeTracedTask, and log the dispatch time here.

Create a FakeTracedTask, and dispatch it here.  This is the start point of the latency.

::: xpcom/threads/nsTimerImpl.cpp
@@ +562,5 @@
>  #ifdef MOZ_TASK_TRACER
> +  // The timer is going to be executed. mTracedTask should be created and a
> +  // dispatch entry of this timer is logged by TaskTracer at when this timer is
> +  // added into the timer queue. TaskTracer will log the begin/end time of this
> +  // timer in the ctor/dtor of AutoRunFakeTracedTask.

mTracedTask is an instance of FakeTracedTask created by DispatchTracedTask().  AutoRunFakeTracedTask logs the begin/end time of the timer/FakeTracedTask instance in ctor/dtor.

Comment 17

[Gina Yeh [:gyeh] [:ginayeh]]

Attachment: Patch 1, r=thinker.

Thanks for your suggestions, thinker. Comments are addressed, and I also add MOZ_DELETE to default ctor, copy ctor, and assigment operator.

Comment 18

[Gina Yeh [:gyeh] [:ginayeh]]

try:
https://tbpl.mozilla.org/?tree=Try&rev=c34a66dd9f83

Comment 19

[Gina Yeh [:gyeh] [:ginayeh]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3d49b8918170

Comment 20

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

https://hg.mozilla.org/mozilla-central/rev/3d49b8918170