Task Tracer: Timer delay should not be the latency of a timer event

RESOLVED FIXED in Firefox 41

Status

()

defect
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: shelly, Assigned: shelly)

Tracking

(Blocks 2 bugs)

unspecified
mozilla41
x86_64
Linux
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox41 fixed)

Details

Attachments

(1 attachment, 4 obsolete attachments)

We should not treat the delay time of a timer as the latency of its timer event.
No longer depends on: 1103915, 1064673
Assignee: nobody → slin
(This patch needs to rebase to the fix of bug 1095433)

Fixes in this patch:
1. The creation of wrapper task (TracedRunnable/TracedTask) no longer equals to the dispatching of this task, an explicit call |task->DispatchTask()| is needed to log the dispatch entry.

2. FakeTracedTask is no longer used in TimerImpl, instead, use a TraceInfoBasic to store the TimerEvent's correct parent task id, source event id/type.

Follow up questions:
1. I'm not sure about the right place to "dispatch" a delayed task in message_loop.
2. How should we keep track of the "delay" of a timer? Use mozilla::tasktracer::AddLabel(...)?
Attachment #8543813 - Flags: feedback?(cyu)
Comment on attachment 8543813 [details] [diff] [review]
[WIP] Fixes for timer event and the timing of task dispatch

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

Per our offline discussion, the definition of the 'delay' of a timed task (nsITimer or MessageLoop::PostDelayedTask) should be the delta of the expected and actual execution time. I think we can record the expected dispatch time right away when the timed task is dispatched (i.e. nsITimer->InitWithCallback() or MessageLoop::PostDelayedTask()). It's a little awkward that we output something in the future in the log, but I don't think it breaks anything.

::: tools/profiler/GeckoTaskTracer.h
@@ +57,5 @@
> +  ~TraceInfoBasic();
> +
> +  void StoreCurTraceInfo();
> +  void SetCurTraceInfo();
> +

Set/Store performs opposite operations, but they sounds like doing the same thing. They should have better naming like Save/Restore, Set/Restore, Set/Unset and the like.
Attachment #8543813 - Flags: feedback?(cyu) → feedback+
Depends on: 1095433
Attachment #8543813 - Attachment is obsolete: true
Attachment #8601281 - Flags: review?(tlee)
Updated w/ a valid patch.
Attachment #8601281 - Attachment is obsolete: true
Attachment #8601281 - Flags: review?(tlee)
Attachment #8601296 - Flags: review?(tlee)
Comment on attachment 8601296 [details] [diff] [review]
bug-1113562-fix-timer-event-and-task-with-delay.patch

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

Major fix in this patch:
- Remove "FakeTracedTask", we should not wrap TimerImpl as a traced task, instead, we save out the current TraceInfo of TLS at its birth place(AddTimerInternal), and set them back to TLS when the timer event is really dispatched.
- For tasks of message loop, we handle the situation where a task is post with delay, the actual dispatch time of this kind of tasks is "birth time + expected delay time".
Blocks: 1167634
Comment on attachment 8601296 [details] [diff] [review]
bug-1113562-fix-timer-event-and-task-with-delay.patch

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

::: tools/profiler/GeckoTaskTracer.cpp
@@ +322,5 @@
>    TraceInfo* info = GetOrCreateTraceInfo();
>    ENSURE_TRUE_VOID(info);
>  
> +  uint64_t time = (aDelayTimeMs <= 0) ? GetTimestamp() :
> +                  GetTimestamp() + aDelayTimeMs;

There may be minor difference from real dispatch time.  I think we could ignore it now.  But, please leave a comment here as an awareness.

::: tools/profiler/TracedTaskCommon.cpp
@@ -26,5 @@
>    mTaskId = GenNewUniqueTaskId();
>    mSourceEventId = info->mCurTraceSourceId;
>    mSourceEventType = info->mCurTraceSourceType;
> -
> -  LogDispatch(mTaskId, info->mCurTaskId, mSourceEventId, mSourceEventType);

Maybe we should keep this line, and define it as a virtual function with empty body for the delay case.  So, there is an LogDispatchInternal() called with a delay parameter.  For TraceTaskCommon::LogDispatch() call *Internal() one, and TraceTaskDelay inherit *Common and redefine LogDispatch() with an empty body.
Comment on attachment 8601296 [details] [diff] [review]
bug-1113562-fix-timer-event-and-task-with-delay.patch

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

::: tools/profiler/TracedTaskCommon.cpp
@@ -26,5 @@
>    mTaskId = GenNewUniqueTaskId();
>    mSourceEventId = info->mCurTraceSourceId;
>    mSourceEventType = info->mCurTraceSourceType;
> -
> -  LogDispatch(mTaskId, info->mCurTaskId, mSourceEventId, mSourceEventType);

I think I understand your feeback here, but let me double check with u.

(LogDispatch() is called directly from GeckoTaskTracerImpl.h)
1. The reason I remove LogDispatch() from TraceTaskCommon::Init is it was not only confusing (a init of task shouldn't equal to dispatching that task), and nsTimerImpl is using it as a record of keeping task info.

2. How about instead of having TracedTaskCommon::DispatchTask() and TracedTask::DispatchWithDelay(int aDelayTimeMS), we declare DispatchTask with a default delay time, such as TracedTaskCommon::DispatchTask(int aDelayTimeMS = 0), and let it call the overloaded function of LogDispatch() from GeckoTaskTracerImpl?
Agree!
Attachment #8601296 - Attachment is obsolete: true
Attachment #8601296 - Flags: review?(tlee)
Attachment #8620789 - Flags: review?(tlee)
Attachment #8620789 - Flags: review?(tlee) → review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/ce36885ea160
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
You need to log in before you can comment on or make changes to this bug.