Bug 1059469: Part 2 - When rescheduling the interval timer, cancel it first, and refactor things so that actually does something. r=bent
authorKyle Huey <khuey@kylehuey.com>
Wed, 06 Jan 2016 13:18:29 -0800
changeset 278871 4a5dfc998bf4a41e539988b8165d2efc0411f07c
parent 278870 aadea6a5781c963f782fa3bd4c7c046c8ff658e8
child 278872 fd83b35491fc940055a4daad8511fe1e08432c6f
push id29860
push usercbook@mozilla.com
push dateThu, 07 Jan 2016 10:51:20 +0000
treeherdermozilla-central@e0bcd16e1d4b [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbent
bugs1059469
milestone46.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1059469: Part 2 - When rescheduling the interval timer, cancel it first, and refactor things so that actually does something. r=bent RunExpiredTimeouts has "fudging" code to always ensure that we execute at least one timeout. This is intended to cover cases where an nsITimer fires slightly early, but it means we must be careful not to fire a timer more times than we intend to or we'll execute a timeout prematurely. Consider a sequences of setTimeout calls alternating in delay between 0ms and 1000ms. When the 1000ms timeout fires, it schedules a 0ms timeout. The setTimeout call itself calls RescheduleTimeoutTimer, which schedules the timer for a 0 ms delay. And once we unwind the 1000ms timeout RunExpiredTimeouts will also schedule the timer for a 0 ms delay. If the timer has fired (remember, it's processed on a completely different thread) in the meantime, we ultimately will get two callbacks from nsITimer for our 0 ms timeout. The first will run the 0 ms timeout and schedule a 1000 ms timeout, and the second will run the 1000 ms timeout (remember, RunExpiredTimeouts always runs at least one timeout!) ~999 ms ahead of schedule. The solution is to cancel the timer in RescheduleTimeoutTimer, so that when we call it the second time it will cause any pending events from the first scheduling to be canceled. But this actually doesn't work at all, because of how we use nsITimer. Before worker threads were capable of accepting arbitrary runnables we created TimerThreadEventTarget, which translates the timer firing to the special worker event queue when the timer thread attempts to *dispatch* a runnable to the worker. We still need this for some of the other types of timers (which use control runnables that interrupt JS, and not the regular event queue). But setTimeout can simply run like a normal nsITimer callback now. We need that here, or calling nsITimer::Cancel won't actually do anything, because the timer's event was ignored and TimerThreadEventTarget created its own event.
dom/workers/WorkerPrivate.cpp
dom/workers/WorkerPrivate.h
--- a/dom/workers/WorkerPrivate.cpp
+++ b/dom/workers/WorkerPrivate.cpp
@@ -111,21 +111,32 @@
 // JS_MaybeGC will run once every second during normal execution.
 #define PERIODIC_GC_TIMER_DELAY_SEC 1
 
 // A shrinking GC will run five seconds after the last event is processed.
 #define IDLE_GC_TIMER_DELAY_SEC 5
 
 #define PREF_WORKERS_ENABLED "dom.workers.enabled"
 
-#ifdef WORKER_LOGGING
-#define LOG(_args) do { printf _args ; fflush(stdout); } while (0)
-#else
-#define LOG(_args) do { } while (0)
-#endif
+static mozilla::LazyLogModule sWorkerPrivateLog("WorkerPrivate");
+static mozilla::LazyLogModule sWorkerTimeoutsLog("WorkerTimeouts");
+
+mozilla::LogModule*
+WorkerLog()
+{
+  return sWorkerPrivateLog;
+}
+
+mozilla::LogModule*
+TimeoutsLog()
+{
+  return sWorkerTimeoutsLog;
+}
+
+#define LOG(log, _args) MOZ_LOG(log, LogLevel::Debug, _args);
 
 using namespace mozilla;
 using namespace mozilla::dom;
 using namespace mozilla::ipc;
 
 USING_WORKERS_NAMESPACE
 
 MOZ_DEFINE_MALLOC_SIZE_OF(JsWorkerMallocSizeOf)
@@ -1114,24 +1125,29 @@ private:
     }
 
     return ReportError(aCx, parent, fireAtScope, aWorkerPrivate, mMessage,
                        mFilename, mLine, mLineNumber, mColumnNumber, mFlags,
                        mErrorNumber, mExnType, mMutedError, innerWindowId);
   }
 };
 
-class TimerRunnable final : public WorkerRunnable
+class TimerRunnable final : public WorkerRunnable,
+                            public nsITimerCallback
 {
 public:
+  NS_DECL_ISUPPORTS_INHERITED
+
   explicit TimerRunnable(WorkerPrivate* aWorkerPrivate)
   : WorkerRunnable(aWorkerPrivate, WorkerThreadUnchangedBusyCount)
   { }
 
 private:
+  ~TimerRunnable() {}
+
   virtual bool
   PreDispatch(JSContext* aCx, WorkerPrivate* aWorkerPrivate) override
   {
     // Silence bad assertions.
     return true;
   }
 
   virtual void
@@ -1141,18 +1157,26 @@ private:
     // Silence bad assertions.
   }
 
   virtual bool
   WorkerRun(JSContext* aCx, WorkerPrivate* aWorkerPrivate) override
   {
     return aWorkerPrivate->RunExpiredTimeouts(aCx);
   }
+
+  NS_IMETHOD
+  Notify(nsITimer* aTimer) override
+  {
+    return Run();
+  }
 };
 
+NS_IMPL_ISUPPORTS_INHERITED(TimerRunnable, WorkerRunnable, nsITimerCallback)
+
 class DebuggerImmediateRunnable : public WorkerRunnable
 {
   RefPtr<dom::Function> mHandler;
 
 public:
   explicit DebuggerImmediateRunnable(WorkerPrivate* aWorkerPrivate,
                                      dom::Function& aHandler)
   : WorkerRunnable(aWorkerPrivate, WorkerThreadUnchangedBusyCount),
@@ -4632,18 +4656,18 @@ WorkerPrivate::SetGCTimerMode(GCTimerMod
       (aMode == IdleTimer && mIdleGCTimerRunning)) {
     return;
   }
 
   MOZ_ALWAYS_TRUE(NS_SUCCEEDED(mGCTimer->Cancel()));
 
   mPeriodicGCTimerRunning = false;
   mIdleGCTimerRunning = false;
-
-  LOG(("Worker %p canceled GC timer because %s\n", this,
+  LOG(WorkerLog(),
+      ("Worker %p canceled GC timer because %s\n", this,
        aMode == PeriodicTimer ?
        "periodic" :
        aMode == IdleTimer ? "idle" : "none"));
 
   if (aMode == NoTimer) {
     return;
   }
 
@@ -4665,36 +4689,36 @@ WorkerPrivate::SetGCTimerMode(GCTimerMod
   }
 
   MOZ_ALWAYS_TRUE(NS_SUCCEEDED(mGCTimer->SetTarget(target)));
   MOZ_ALWAYS_TRUE(NS_SUCCEEDED(
     mGCTimer->InitWithNamedFuncCallback(DummyCallback, nullptr, delay, type,
                                         "dom::workers::DummyCallback(2)")));
 
   if (aMode == PeriodicTimer) {
-    LOG(("Worker %p scheduled periodic GC timer\n", this));
+    LOG(WorkerLog(), ("Worker %p scheduled periodic GC timer\n", this));
     mPeriodicGCTimerRunning = true;
   }
   else {
-    LOG(("Worker %p scheduled idle GC timer\n", this));
+    LOG(WorkerLog(), ("Worker %p scheduled idle GC timer\n", this));
     mIdleGCTimerRunning = true;
   }
 }
 
 void
 WorkerPrivate::ShutdownGCTimers()
 {
   AssertIsOnWorkerThread();
 
   MOZ_ASSERT(mGCTimer);
 
   // Always make sure the timer is canceled.
   MOZ_ALWAYS_TRUE(NS_SUCCEEDED(mGCTimer->Cancel()));
 
-  LOG(("Worker %p killed the GC timer\n", this));
+  LOG(WorkerLog(), ("Worker %p killed the GC timer\n", this));
 
   mGCTimer = nullptr;
   mPeriodicGCTimerTarget = nullptr;
   mIdleGCTimerTarget = nullptr;
   mPeriodicGCTimerRunning = false;
   mIdleGCTimerRunning = false;
 }
 
@@ -5199,18 +5223,20 @@ WorkerPrivate::NotifyFeatures(JSContext*
   }
 }
 
 void
 WorkerPrivate::CancelAllTimeouts(JSContext* aCx)
 {
   AssertIsOnWorkerThread();
 
+  LOG(TimeoutsLog(), ("Worker %p CancelAllTimeouts.\n", this));
+
   if (mTimerRunning) {
-    NS_ASSERTION(mTimer, "Huh?!");
+    NS_ASSERTION(mTimer && mTimerRunnable, "Huh?!");
     NS_ASSERTION(!mTimeouts.IsEmpty(), "Huh?!");
 
     if (NS_FAILED(mTimer->Cancel())) {
       NS_WARNING("Failed to cancel timer!");
     }
 
     for (uint32_t index = 0; index < mTimeouts.Length(); index++) {
       mTimeouts[index]->mCanceled = true;
@@ -5224,16 +5250,17 @@ WorkerPrivate::CancelAllTimeouts(JSConte
   }
 #ifdef DEBUG
   else if (!mRunningExpiredTimeouts) {
     NS_ASSERTION(mTimeouts.IsEmpty(), "Huh?!");
   }
 #endif
 
   mTimer = nullptr;
+  mTimerRunnable = nullptr;
 }
 
 already_AddRefed<nsIEventTarget>
 WorkerPrivate::CreateNewSyncLoop()
 {
   AssertIsOnWorkerThread();
 
   nsCOMPtr<nsIThreadInternal> thread = do_QueryInterface(NS_GetCurrentThread());
@@ -5895,40 +5922,32 @@ WorkerPrivate::SetTimeout(JSContext* aCx
     if (!nsJSUtils::GetCallingLocation(aCx, newInfo->mFilename, &newInfo->mLineNumber)) {
       NS_WARNING("Failed to get calling location!");
     }
   }
 
   nsAutoPtr<TimeoutInfo>* insertedInfo =
     mTimeouts.InsertElementSorted(newInfo.forget(), GetAutoPtrComparator(mTimeouts));
 
+  LOG(TimeoutsLog(), ("Worker %p has new timeout: delay=%d interval=%s\n",
+                      this, aTimeout, aIsInterval ? "yes" : "no"));
+
   // If the timeout we just made is set to fire next then we need to update the
-  // timer.
-  if (insertedInfo == mTimeouts.Elements()) {
+  // timer, unless we're currently running timeouts.
+  if (insertedInfo == mTimeouts.Elements() && !mRunningExpiredTimeouts) {
     nsresult rv;
 
     if (!mTimer) {
-      nsCOMPtr<nsITimer> timer = do_CreateInstance(NS_TIMER_CONTRACTID, &rv);
+      mTimer = do_CreateInstance(NS_TIMER_CONTRACTID, &rv);
       if (NS_FAILED(rv)) {
         aRv.Throw(rv);
         return 0;
       }
 
-      RefPtr<TimerRunnable> runnable = new TimerRunnable(this);
-
-      RefPtr<TimerThreadEventTarget> target =
-        new TimerThreadEventTarget(this, runnable);
-
-      rv = timer->SetTarget(target);
-      if (NS_FAILED(rv)) {
-        aRv.Throw(rv);
-        return 0;
-      }
-
-      timer.swap(mTimer);
+      mTimerRunnable = new TimerRunnable(this);
     }
 
     if (!mTimerRunning) {
       if (!ModifyBusyCountFromWorker(aCx, true)) {
         aRv.Throw(NS_ERROR_FAILURE);
         return 0;
       }
       mTimerRunning = true;
@@ -5968,27 +5987,33 @@ WorkerPrivate::RunExpiredTimeouts(JSCont
 
   // We may be called recursively (e.g. close() inside a timeout) or we could
   // have been canceled while this event was pending, bail out if there is
   // nothing to do.
   if (mRunningExpiredTimeouts || !mTimerRunning) {
     return true;
   }
 
-  NS_ASSERTION(mTimer, "Must have a timer!");
+  NS_ASSERTION(mTimer && mTimerRunnable, "Must have a timer!");
   NS_ASSERTION(!mTimeouts.IsEmpty(), "Should have some work to do!");
 
   bool retval = true;
 
   AutoPtrComparator<TimeoutInfo> comparator = GetAutoPtrComparator(mTimeouts);
   JS::Rooted<JSObject*> global(aCx, JS::CurrentGlobalOrNull(aCx));
 
   // We want to make sure to run *something*, even if the timer fired a little
   // early. Fudge the value of now to at least include the first timeout.
-  const TimeStamp now = std::max(TimeStamp::Now(), mTimeouts[0]->mTargetTime);
+  const TimeStamp actual_now = TimeStamp::Now();
+  const TimeStamp now = std::max(actual_now, mTimeouts[0]->mTargetTime);
+
+  if (now != actual_now) {
+    LOG(TimeoutsLog(), ("Worker %p fudged timeout by %f ms.\n", this,
+                        (now - actual_now).ToMilliseconds()));
+  }
 
   nsAutoTArray<TimeoutInfo*, 10> expiredTimeouts;
   for (uint32_t index = 0; index < mTimeouts.Length(); index++) {
     nsAutoPtr<TimeoutInfo>& info = mTimeouts[index];
     if (info->mTargetTime > now) {
       break;
     }
     expiredTimeouts.AppendElement(info);
@@ -6000,16 +6025,19 @@ WorkerPrivate::RunExpiredTimeouts(JSCont
   // Run expired timeouts.
   for (uint32_t index = 0; index < expiredTimeouts.Length(); index++) {
     TimeoutInfo*& info = expiredTimeouts[index];
 
     if (info->mCanceled) {
       continue;
     }
 
+    LOG(TimeoutsLog(), ("Worker %p executing timeout with original delay %f ms.\n",
+                        this, info->mInterval.ToMilliseconds()));
+
     // Always call JS_ReportPendingException if something fails, and if
     // JS_ReportPendingException returns false (i.e. uncatchable exception) then
     // break out of the loop.
 
     if (!info->mTimeoutCallable.isUndefined()) {
       JS::Rooted<JS::Value> rval(aCx);
       JS::HandleValueArray args =
         JS::HandleValueArray::fromMarkedLocation(info->mExtraArgVals.Length(),
@@ -6097,26 +6125,36 @@ WorkerPrivate::RunExpiredTimeouts(JSCont
 
   return retval;
 }
 
 bool
 WorkerPrivate::RescheduleTimeoutTimer(JSContext* aCx)
 {
   AssertIsOnWorkerThread();
+  MOZ_ASSERT(!mRunningExpiredTimeouts);
   NS_ASSERTION(!mTimeouts.IsEmpty(), "Should have some timeouts!");
-  NS_ASSERTION(mTimer, "Should have a timer!");
+  NS_ASSERTION(mTimer && mTimerRunnable, "Should have a timer!");
+
+  // NB: This is important! The timer may have already fired, e.g. if a timeout
+  // callback itself calls setTimeout for a short duration and then takes longer
+  // than that to finish executing. If that has happened, it's very important
+  // that we don't execute the event that is now pending in our event queue, or
+  // our code in RunExpiredTimeouts to "fudge" the timeout value will unleash an
+  // early timeout when we execute the event we're about to queue.
+  mTimer->Cancel();
 
   double delta =
     (mTimeouts[0]->mTargetTime - TimeStamp::Now()).ToMilliseconds();
   uint32_t delay = delta > 0 ? std::min(delta, double(UINT32_MAX)) : 0;
 
-  nsresult rv = mTimer->InitWithNamedFuncCallback(
-    DummyCallback, nullptr, delay, nsITimer::TYPE_ONE_SHOT,
-    "dom::workers::DummyCallback(3)");
+  LOG(TimeoutsLog(), ("Worker %p scheduled timer for %d ms, %d pending timeouts\n",
+                      this, delay, mTimeouts.Length()));
+
+  nsresult rv = mTimer->InitWithCallback(mTimerRunnable, delay, nsITimer::TYPE_ONE_SHOT);
   if (NS_FAILED(rv)) {
     JS_ReportError(aCx, "Failed to start timer!");
     return false;
   }
 
   return true;
 }
 
@@ -6213,27 +6251,27 @@ WorkerPrivate::GarbageCollectInternal(JS
   if (aShrinking || aCollectChildren) {
     JSRuntime* rt = JS_GetRuntime(aCx);
     JS::PrepareForFullGC(rt);
 
     if (aShrinking) {
       JS::GCForReason(rt, GC_SHRINK, JS::gcreason::DOM_WORKER);
 
       if (!aCollectChildren) {
-        LOG(("Worker %p collected idle garbage\n", this));
+        LOG(WorkerLog(), ("Worker %p collected idle garbage\n", this));
       }
     }
     else {
       JS::GCForReason(rt, GC_NORMAL, JS::gcreason::DOM_WORKER);
-      LOG(("Worker %p collected garbage\n", this));
+      LOG(WorkerLog(), ("Worker %p collected garbage\n", this));
     }
   }
   else {
     JS_MaybeGC(aCx);
-    LOG(("Worker %p collected periodic garbage\n", this));
+    LOG(WorkerLog(), ("Worker %p collected periodic garbage\n", this));
   }
 
   if (aCollectChildren) {
     for (uint32_t index = 0; index < mChildWorkers.Length(); index++) {
       mChildWorkers[index]->GarbageCollect(aCx, aShrinking);
     }
   }
 }
--- a/dom/workers/WorkerPrivate.h
+++ b/dom/workers/WorkerPrivate.h
@@ -909,16 +909,17 @@ class WorkerPrivate : public WorkerPriva
   };
 
   // This is only modified on the worker thread, but in DEBUG builds
   // AssertValidSyncLoop function iterates it on other threads. Therefore
   // modifications are done with mMutex held *only* in DEBUG builds.
   nsTArray<nsAutoPtr<SyncLoopInfo>> mSyncLoopStack;
 
   nsCOMPtr<nsITimer> mTimer;
+  nsCOMPtr<nsITimerCallback> mTimerRunnable;
 
   nsCOMPtr<nsITimer> mGCTimer;
   nsCOMPtr<nsIEventTarget> mPeriodicGCTimerTarget;
   nsCOMPtr<nsIEventTarget> mIdleGCTimerTarget;
 
   RefPtr<MemoryReporter> mMemoryReporter;
 
   // fired on the main thread if the worker script fails to load