Closed Bug 1089514 Opened 5 years ago Closed 5 years ago

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

Categories

(Core :: Gecko Profiler, defect)

x86_64
Linux
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla36

People

(Reporter: shelly, Assigned: gyeh)

References

(Blocks 1 open bug)

Details

Attachments

(3 files, 7 obsolete files)

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.
Attached patch Fix in FakeTracedTask (obsolete) — Splinter Review
Blocks: tasktracer
Attachment #8511838 - Attachment is obsolete: true
Attached patch Patch 1(v1) (obsolete) — Splinter Review
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.
Assignee: nobody → gyeh
Attachment #8512517 - Attachment is obsolete: true
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.
It's much clear now. Thanks for your feedback, Shelly.
Attached patch Patch1(v2) (obsolete) — Splinter Review
Thinker, please take a look at the fix. Thanks.
Attachment #8514075 - Attachment is obsolete: true
Attachment #8514103 - Flags: review?(tlee)
Blocks: 1091479
(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?!
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. :)
Attached patch Patch1(v3) (obsolete) — Splinter Review
Attachment #8514103 - Attachment is obsolete: true
Attachment #8514103 - Flags: review?(tlee)
(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.
Attachment #8514913 - Flags: review?(tlee)
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.
Attachment #8514913 - Flags: review?(tlee)
Attached patch Patch 1(v4) (obsolete) — Splinter Review
Hi Thinker,

I've move the copy constructor to private part. Please review again. Thanks.
Attachment #8514913 - Attachment is obsolete: true
Attachment #8515773 - Flags: review?(tlee)
No longer blocks: 1091479
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.
Attachment #8515773 - Flags: review?(tlee) → review+
Thanks for your suggestions, thinker. Comments are addressed, and I also add MOZ_DELETE to default ctor, copy ctor, and assigment operator.
Attachment #8515773 - Attachment is obsolete: true
Attachment #8516453 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/3d49b8918170
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
You need to log in before you can comment on or make changes to this bug.