Bug 1515214 - Add markers with cause stacks and the name of the called function for setTimeout callback execution. r=jesup
☠☠ backed out by 2d48960b2816 ☠ ☠
authorMarkus Stange <mstange@themasta.com>
Thu, 07 Mar 2019 18:04:58 +0000
changeset 523894 7c4973b0d0e80a4f6b9172454c8f709b60f9e431
parent 523893 9aabc3ad2470032f34bf20cafcb5c0bc2c61d64e
child 523895 7d12f69394014cce9ffb2326e46170958867cb12
push id2032
push userffxbld-merge
push dateMon, 13 May 2019 09:36:57 +0000
treeherdermozilla-release@455c1065dcbe [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjesup
bugs1515214
milestone67.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 1515214 - Add markers with cause stacks and the name of the called function for setTimeout callback execution. r=jesup These duplicate the existing setTimeout markers a bit. Differential Revision: https://phabricator.services.mozilla.com/D19194
dom/base/Timeout.cpp
dom/base/Timeout.h
dom/base/nsGlobalWindowInner.cpp
--- a/dom/base/Timeout.cpp
+++ b/dom/base/Timeout.cpp
@@ -44,16 +44,23 @@ NS_IMPL_CYCLE_COLLECTION_TRAVERSE_END
 NS_IMPL_CYCLE_COLLECTION_ROOT_NATIVE(Timeout, AddRef)
 NS_IMPL_CYCLE_COLLECTION_UNROOT_NATIVE(Timeout, Release)
 
 void Timeout::SetWhenOrTimeRemaining(const TimeStamp& aBaseTime,
                                      const TimeDuration& aDelay) {
   MOZ_DIAGNOSTIC_ASSERT(mWindow);
   mSubmitTime = aBaseTime;
 
+  mSubmitTime = aBaseTime;
+#ifdef MOZ_GECKO_PROFILER
+  if (profiler_is_active()) {
+    mCause = profiler_get_backtrace();
+  }
+#endif
+
   // If we are frozen simply set mTimeRemaining to be the "time remaining" in
   // the timeout (i.e., the interval itself).  This will be used to create a
   // new mWhen time when the window is thawed.  The end effect is that time does
   // not appear to pass for frozen windows.
   if (mWindow->IsFrozen()) {
     mWhen = TimeStamp();
     mTimeRemaining = aDelay;
     return;
--- a/dom/base/Timeout.h
+++ b/dom/base/Timeout.h
@@ -8,16 +8,17 @@
 #define mozilla_dom_timeout_h
 
 #include "mozilla/dom/PopupBlocker.h"
 #include "mozilla/LinkedList.h"
 #include "mozilla/TimeStamp.h"
 #include "nsCOMPtr.h"
 #include "nsCycleCollectionParticipant.h"
 #include "nsITimeoutHandler.h"
+#include "GeckoProfiler.h"
 
 class nsIEventTarget;
 class nsIPrincipal;
 class nsIEventTarget;
 class nsGlobalWindowInner;
 
 namespace mozilla {
 namespace dom {
@@ -45,16 +46,20 @@ class Timeout final : public LinkedListE
   // Can only be called when not frozen.
   const TimeStamp& When() const;
 
   const TimeStamp& SubmitTime() const;
 
   // Can only be called when frozen.
   const TimeDuration& TimeRemaining() const;
 
+#ifdef MOZ_GECKO_PROFILER
+  UniqueProfilerBacktrace TakeProfilerBacktrace() { return std::move(mCause); }
+#endif
+
  private:
   // mWhen and mTimeRemaining can't be in a union, sadly, because they
   // have constructors.
   // Nominal time to run this timeout.  Use only when timeouts are not
   // frozen.
   TimeStamp mWhen;
 
   // Remaining time to wait.  Used only when timeouts are frozen.
@@ -77,16 +82,20 @@ class Timeout final : public LinkedListE
   RefPtr<nsGlobalWindowInner> mWindow;
 
   // The language-specific information about the callback.
   nsCOMPtr<nsITimeoutHandler> mScriptHandler;
 
   // Interval
   TimeDuration mInterval;
 
+#ifdef MOZ_GECKO_PROFILER
+  UniqueProfilerBacktrace mCause;
+#endif
+
   // Returned as value of setTimeout()
   uint32_t mTimeoutId;
 
   // Identifies which firing level this Timeout is being processed in
   // when sync loops trigger nested firing.
   uint32_t mFiringId;
 
 #ifdef DEBUG
--- a/dom/base/nsGlobalWindowInner.cpp
+++ b/dom/base/nsGlobalWindowInner.cpp
@@ -5508,16 +5508,52 @@ int32_t nsGlobalWindowInner::SetTimeoutO
 
   int32_t result;
   aError =
       mTimeoutManager->SetTimeout(handler, aTimeout, aIsInterval,
                                   Timeout::Reason::eTimeoutOrInterval, &result);
   return result;
 }
 
+static const char* GetTimeoutReasonString(Timeout* aTimeout) {
+  switch (aTimeout->mReason) {
+    case Timeout::Reason::eTimeoutOrInterval:
+      if (aTimeout->mIsInterval) {
+        return "setInterval handler";
+      }
+      return "setTimeout handler";
+    case Timeout::Reason::eIdleCallbackTimeout:
+      return "setIdleCallback handler (timed out)";
+    default:
+      MOZ_CRASH("Unexpected enum value");
+      return "";
+  }
+}
+
+static void GetHandlerDescription(Timeout* aTimeout, nsACString& aOutString) {
+  nsCOMPtr<nsIScriptTimeoutHandler> handler(
+      do_QueryInterface(aTimeout->mScriptHandler));
+
+  if (!handler) {
+    aOutString.Append("<non-script timeout handler>");
+    return;
+  }
+
+  if (RefPtr<Function> callback = handler->GetCallback()) {
+    callback->GetDescription(aOutString);
+    return;
+  }
+
+  const char* filename = nullptr;
+  uint32_t lineNo = 0, columnNo = 0;
+  handler->GetLocation(&filename, &lineNo, &columnNo);
+  aOutString.AppendPrintf("<string handler> (%s:%d:%d)", filename, lineNo,
+                          columnNo);
+}
+
 bool nsGlobalWindowInner::RunTimeoutHandler(Timeout* aTimeout,
                                             nsIScriptContext* aScx) {
   // Hold on to the timeout in case mExpr or mFunObj releases its
   // doc.
   RefPtr<Timeout> timeout = aTimeout;
   Timeout* last_running_timeout = mTimeoutManager->BeginRunningTimeout(timeout);
   timeout->mRunning = true;
 
@@ -5533,22 +5569,35 @@ bool nsGlobalWindowInner::RunTimeoutHand
 
   bool trackNestingLevel = !timeout->mIsInterval;
   uint32_t nestingLevel;
   if (trackNestingLevel) {
     nestingLevel = TimeoutManager::GetNestingLevel();
     TimeoutManager::SetNestingLevel(timeout->mNestingLevel);
   }
 
-  const char* reason;
-  if (timeout->mIsInterval) {
-    reason = "setInterval handler";
-  } else {
-    reason = "setTimeout handler";
-  }
+  const char* reason = GetTimeoutReasonString(timeout);
+
+#ifdef MOZ_GECKO_PROFILER
+  nsCOMPtr<nsIDocShell> docShell = GetDocShell();
+  nsCString str;
+  if (profiler_is_active()) {
+    TimeDuration originalInterval = timeout->When() - timeout->SubmitTime();
+    str.Append(reason);
+    str.Append(" with interval ");
+    str.AppendInt(int(originalInterval.ToMilliseconds()));
+    str.Append("ms: ");
+    nsCString handlerDescription;
+    GetHandlerDescription(timeout, handlerDescription);
+    str.Append(handlerDescription);
+  }
+  AUTO_PROFILER_TEXT_MARKER_DOCSHELL_CAUSE("setTimeout callback", str, JS,
+                                           docShell,
+                                           timeout->TakeProfilerBacktrace());
+#endif
 
   bool abortIntervalHandler = false;
   nsCOMPtr<nsIScriptTimeoutHandler> handler(
       do_QueryInterface(timeout->mScriptHandler));
   if (handler) {
     RefPtr<Function> callback = handler->GetCallback();
 
     if (!callback) {