We should not treat the delay time of a timer as the latency of its timer event.

(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(...)?

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.

Updated w/ a valid patch.

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".

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!

Try server result: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f11e00dd3e48