Bug 1664475: Add telemetry probes to collect data for script delazification, xdr encoding time, bytecode caching time, and baseline compilation time. r=nbp,Dexter,sefeng,smaug

Differential Revision: https://phabricator.services.mozilla.com/D90798

dom/base/Document.cpp

@@ -1873,6 +1873,83 @@ void Document::ConstructUbiNode(void* storage) {
   JS::ubi::Concrete<Document>::construct(storage, this);
 }
 
+void Document::LoadEventFired() {
+  // Accumulate timing data located in each document's realm and report to
+  // telemetry.
+  AccumulateJSTelemetry();
+
+  // Release the JS bytecode cache from its wait on the load event, and
+  // potentially dispatch the encoding of the bytecode.
+  if (ScriptLoader()) {
+    ScriptLoader()->LoadEventFired();
+  }
+}
+
+static uint32_t CalcPercentage(TimeDuration aSubTimer,
+                               TimeDuration aTotalTimer) {
+  return static_cast<uint32_t>(100.0 * aSubTimer.ToMilliseconds() /
+                               aTotalTimer.ToMilliseconds());
+}
+
+void Document::AccumulateJSTelemetry() {
+  if (!IsTopLevelContentDocument()) {
+    return;
+  }
+
+  // Try to only measure real websites
+  if (!(GetDocumentURI()->SchemeIs("http") ||
+        GetDocumentURI()->SchemeIs("https"))) {
+    return;
+  }
+
+  if (!GetScopeObject() || !GetScopeObject()->GetGlobalJSObject()) {
+    return;
+  }
+
+  AutoJSContext cx;
+  JSObject* globalObject = GetScopeObject()->GetGlobalJSObject();
+  JSAutoRealm ar(cx, globalObject);
+  JS::JSTimers timers = JS::GetJSTimers(cx);
+
+  TimeDuration totalExecutionTime = timers.executionTime;
+  TimeDuration totalDelazificationTime = timers.delazificationTime;
+  TimeDuration totalXDREncodingTime = timers.xdrEncodingTime;
+  TimeDuration totalBaselineCompileTime = timers.baselineCompileTime;
+
+  if (totalExecutionTime.IsZero()) {
+    return;
+  }
+
+  if (!totalDelazificationTime.IsZero()) {
+    Telemetry::Accumulate(
+        Telemetry::JS_DELAZIFICATION_PROPORTION,
+        CalcPercentage(totalDelazificationTime, totalExecutionTime));
+  }
+
+  if (!totalXDREncodingTime.IsZero()) {
+    Telemetry::Accumulate(
+        Telemetry::JS_XDR_ENCODING_PROPORTION,
+        CalcPercentage(totalXDREncodingTime, totalExecutionTime));
+  }
+
+  if (!totalBaselineCompileTime.IsZero()) {
+    Telemetry::Accumulate(
+        Telemetry::JS_BASELINE_COMPILE_PROPORTION,
+        CalcPercentage(totalBaselineCompileTime, totalExecutionTime));
+  }
+
+  TimeStamp loadEventStart =
+      GetNavigationTiming()->GetLoadEventStartTimeStamp();
+  TimeStamp navigationStart =
+      GetNavigationTiming()->GetNavigationStartTimeStamp();
+
+  if (loadEventStart && navigationStart) {
+    TimeDuration pageLoadTime = loadEventStart - navigationStart;
+    Telemetry::Accumulate(Telemetry::JS_EXECUTION_PROPORTION,
+                          CalcPercentage(totalExecutionTime, pageLoadTime));
+  }
+}
+
 Document::~Document() {
   MOZ_LOG(gDocumentLeakPRLog, LogLevel::Debug, ("DOCUMENT %p destroyed", this));
   MOZ_ASSERT(!IsTopLevelContentDocument() || !IsResourceDoc(),

dom/base/Document.h

@@ -5089,6 +5089,9 @@ class Document : public nsINode,
   // Scope preloads per document.  This is used by speculative loading as well.
   PreloadService mPreloadService;
 
+  // Accumulate JS telemetry collected
+  void AccumulateJSTelemetry();
+
  public:
   // Needs to be public because the bindings code pokes at it.
   JS::ExpandoAndGeneration mExpandoAndGeneration;
@@ -5104,6 +5107,8 @@ class Document : public nsINode,
   void SetSavedResolutionBeforeMVM(float aResolution) {
     mSavedResolutionBeforeMVM = aResolution;
   }
+
+  void LoadEventFired();
 };
 
 NS_DEFINE_STATIC_IID_ACCESSOR(Document, NS_IDOCUMENT_IID)

dom/base/nsDOMNavigationTiming.h

@@ -59,6 +59,10 @@ class nsDOMNavigationTiming final : public mozilla::RelativeTimeline {
     return mNavigationStart;
   }
 
+  mozilla::TimeStamp GetLoadEventStartTimeStamp() const {
+    return mLoadEventStart;
+  }
+
   DOMTimeMilliSec GetUnloadEventStart() {
     return TimeStampToDOM(GetUnloadEventStartTimeStamp());
   }

dom/script/ScriptLoader.cpp

@@ -3140,6 +3140,8 @@ void ScriptLoader::EncodeBytecode() {
     return;
   }
 
+  TimeStamp startTime = TimeStamp::Now();
+
   AutoEntryScript aes(globalObject, "encode bytecode", true);
   RefPtr<ScriptLoadRequest> request;
   while (!mBytecodeEncodingQueue.isEmpty()) {
@@ -3148,6 +3150,10 @@ void ScriptLoader::EncodeBytecode() {
     request->mScriptBytecode.clearAndFree();
     request->DropBytecodeCacheReferences();
   }
+
+  TimeDuration delta = TimeStamp::Now() - startTime;
+  Telemetry::Accumulate(Telemetry::JS_BYTECODE_CACHING_TIME,
+                        static_cast<uint32_t>(delta.ToMilliseconds()));
 }
 
 void ScriptLoader::EncodeRequestBytecode(JSContext* aCx,

js/src/jit/BaselineCodeGen.cpp

@@ -198,6 +198,7 @@ MethodStatus BaselineCompiler::compile() {
   JitSpew(JitSpew_Codegen, "# Emitting baseline code for script %s:%u:%u",
           script->filename(), script->lineno(), script->column());
 
+  AutoIncrementalTimer timer(cx->realm()->timers.baselineCompileTime);
   TraceLoggerThread* logger = TraceLoggerForCurrentThread(cx);
   TraceLoggerEvent scriptEvent(TraceLogger_AnnotateScripts, script);
   AutoTraceLog logScript(logger, scriptEvent);

js/src/jsapi.cpp

@@ -5951,6 +5951,10 @@ JS_PUBLIC_API js::StackFormat js::GetStackFormat(JSContext* cx) {
   return cx->runtime()->stackFormat();
 }
 
+JS_PUBLIC_API JS::JSTimers JS::GetJSTimers(JSContext* cx) {
+  return cx->realm()->timers;
+}
+
 namespace js {
 
 JS_PUBLIC_API void NoteIntentionalCrash() {

js/src/jsapi.h

@@ -16,6 +16,7 @@
 #include "mozilla/Range.h"
 #include "mozilla/RangedPtr.h"
 #include "mozilla/RefPtr.h"
+#include "mozilla/TimeStamp.h"
 #include "mozilla/Utf8.h"
 #include "mozilla/Variant.h"
 
@@ -190,6 +191,17 @@ namespace JS {
 
 extern JS_PUBLIC_API const char* InformalValueTypeName(const JS::Value& v);
 
+/** Timing information for telemetry purposes **/
+struct JSTimers {
+  mozilla::TimeDuration executionTime;       // Total time spent executing
+  mozilla::TimeDuration delazificationTime;  // Total time spent delazifying
+  mozilla::TimeDuration xdrEncodingTime;     // Total time spent XDR encoding
+  mozilla::TimeDuration
+      baselineCompileTime;  // Total time spent in baseline compiler
+};
+
+extern JS_PUBLIC_API JSTimers GetJSTimers(JSContext* cx);
+
 } /* namespace JS */
 
 /** True iff fun is the global eval function. */

js/src/vm/Interpreter.cpp

@@ -443,15 +443,26 @@ bool js::RunScript(JSContext* cx, RunState& state) {
 
   GeckoProfilerEntryMarker marker(cx, state.script());
 
-#ifdef ENABLE_SPIDERMONKEY_TELEMETRY
   bool measuringTime = !cx->isMeasuringExecutionTime();
-  int64_t startTime = 0;
+  mozilla::TimeStamp startTime;
   if (measuringTime) {
     cx->setIsMeasuringExecutionTime(true);
-    startTime = PRMJ_Now();
+    startTime = ReallyNow();
   }
+  auto timerEnd = mozilla::MakeScopeExit([&]() {
+    if (measuringTime) {
+      mozilla::TimeDuration delta = ReallyNow() - startTime;
+      cx->realm()->timers.executionTime += delta;
+
+#ifdef ENABLE_SPIDERMONKEY_TELEMETRY
+      int64_t runtimeMicros = delta.ToMicroseconds();
+      cx->runtime()->addTelemetry(JS_TELEMETRY_RUN_TIME_US, runtimeMicros);
 #endif
 
+      cx->setIsMeasuringExecutionTime(false);
+    }
+  });
+
   jit::EnterJitStatus status = jit::MaybeEnterJit(cx, state);
   switch (status) {
     case jit::EnterJitStatus::Error:
@@ -469,15 +480,6 @@ bool js::RunScript(JSContext* cx, RunState& state) {
 
   bool ok = Interpret(cx, state);
 
-#ifdef ENABLE_SPIDERMONKEY_TELEMETRY
-  if (measuringTime) {
-    int64_t endTime = PRMJ_Now();
-    int64_t runtimeMicros = endTime - startTime;
-    cx->runtime()->addTelemetry(JS_TELEMETRY_RUN_TIME_US, runtimeMicros);
-    cx->setIsMeasuringExecutionTime(false);
-  }
-#endif
-
   return ok;
 }
 #ifdef _MSC_VER

js/src/vm/JSFunction.cpp

@@ -1564,6 +1564,8 @@ bool DelazifyCanonicalScriptedFunctionImpl(JSContext* cx, HandleFunction fun,
   MOZ_ASSERT(!lazy->hasBytecode(), "Script is already compiled!");
   MOZ_ASSERT(lazy->function() == fun);
 
+  AutoIncrementalTimer timer(cx->realm()->timers.delazificationTime);
+
   size_t sourceStart = lazy->sourceStart();
   size_t sourceLength = lazy->sourceEnd() - lazy->sourceStart();
 

js/src/vm/JSScript.cpp

@@ -2676,6 +2676,8 @@ bool ScriptSource::xdrEncodeTopLevel(JSContext* cx, HandleScript script) {
   }
 
   MOZ_ASSERT(hasEncoder());
+  AutoIncrementalTimer timer(cx->realm()->timers.xdrEncodingTime);
+
   auto failureCase =
       mozilla::MakeScopeExit([&] { xdrEncoder_.reset(nullptr); });
 
@@ -2709,6 +2711,7 @@ bool ScriptSource::xdrEncodeInitialStencil(
     return false;
   }
 
+  AutoIncrementalTimer timer(cx->realm()->timers.xdrEncodingTime);
   auto failureCase = mozilla::MakeScopeExit([&] { xdrEncoder.reset(nullptr); });
 
   XDRResult res = xdrEncoder->codeStencil(compilationInfo);
@@ -2751,6 +2754,8 @@ bool ScriptSource::xdrEncodeFunction(JSContext* cx, HandleFunction fun,
                                      HandleScriptSourceObject sourceObject) {
   MOZ_ASSERT(sourceObject->source() == this);
   MOZ_ASSERT(hasEncoder());
+  AutoIncrementalTimer timer(cx->realm()->timers.xdrEncodingTime);
+
   auto failureCase =
       mozilla::MakeScopeExit([&] { xdrEncoder_.reset(nullptr); });
 
@@ -2772,6 +2777,7 @@ bool ScriptSource::xdrEncodeFunction(JSContext* cx, HandleFunction fun,
 bool ScriptSource::xdrEncodeFunctionStencil(
     JSContext* cx, frontend::CompilationStencil& stencil) {
   MOZ_ASSERT(hasEncoder());
+  AutoIncrementalTimer timer(cx->realm()->timers.xdrEncodingTime);
   return xdrEncodeFunctionStencilWith(cx, stencil, xdrEncoder_);
 }
 

js/src/vm/Realm.h

@@ -385,6 +385,10 @@ class JS::Realm : public JS::shadow::Realm {
   unsigned enterRealmDepthIgnoringJit_ = 0;
 
  public:
+  // Various timers for collecting time spent delazifying, jit compiling,
+  // executing, etc
+  JS::JSTimers timers;
+
   struct DebuggerVectorEntry {
     // The debugger relies on iterating through the DebuggerVector to know what
     // debuggers to notify about certain actions, which it does using this

js/src/vm/Time.h

@@ -159,6 +159,22 @@ static inline mozilla::TimeStamp ReallyNow() {
   return mozilla::TimeStamp::NowUnfuzzed();
 }
 
+class MOZ_RAII AutoIncrementalTimer {
+  mozilla::TimeStamp startTime;
+  mozilla::TimeDuration& output;
+
+ public:
+  AutoIncrementalTimer(const AutoIncrementalTimer&) = delete;
+  AutoIncrementalTimer& operator=(const AutoIncrementalTimer&) = delete;
+
+  explicit AutoIncrementalTimer(mozilla::TimeDuration& output_)
+      : output(output_) {
+    startTime = ReallyNow();
+  }
+
+  ~AutoIncrementalTimer() { output += ReallyNow() - startTime; }
+};
+
 }  // namespace js
 
 #endif /* vm_Time_h */

layout/base/nsDocumentViewer.cpp

@@ -1160,10 +1160,9 @@ nsDocumentViewer::LoadComplete(nsresult aStatus) {
       }
     }
   }
-  // Release the JS bytecode cache from its wait on the load event, and
-  // potentially dispatch the encoding of the bytecode.
-  if (mDocument && mDocument->ScriptLoader()) {
-    mDocument->ScriptLoader()->LoadEventFired();
+
+  if (mDocument && !restoring) {
+    mDocument->LoadEventFired();
   }
 
   // It's probably a good idea to GC soon since we have finished loading.

toolkit/components/telemetry/Histograms.json

@@ -13276,6 +13276,66 @@
     "releaseChannelCollection": "opt-out",
     "description": "Plugin drawing model. 0 when windowed, otherwise NPDrawingModel + 1."
   },
+  "JS_EXECUTION_PROPORTION" : {
+    "record_in_processes": ["content"],
+    "products": ["firefox", "geckoview_streaming"],
+    "alert_emails": ["dpalmeiro@mozilla.com","perfteam@mozilla.com"],
+    "expires_in_version": "89",
+    "releaseChannelCollection": "opt-out",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 20,
+    "bug_numbers": [1664475],
+    "description": "Percentage of page load time spent executing Javascript."
+  },
+  "JS_DELAZIFICATION_PROPORTION" : {
+    "record_in_processes": ["content"],
+    "products": ["firefox", "geckoview_streaming"],
+    "alert_emails": ["dpalmeiro@mozilla.com","perfteam@mozilla.com"],
+    "expires_in_version": "89",
+    "releaseChannelCollection": "opt-out",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 20,
+    "bug_numbers": [1664475],
+    "description": "Percentage of execution time spent during delazification for JS scripts up until the page load event fires."
+  },
+  "JS_XDR_ENCODING_PROPORTION" : {
+    "record_in_processes": ["content"],
+    "products": ["firefox", "geckoview_streaming"],
+    "alert_emails": ["dpalmeiro@mozilla.com","perfteam@mozilla.com"],
+    "expires_in_version": "89",
+    "releaseChannelCollection": "opt-out",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 20,
+    "bug_numbers": [1664475],
+    "description": "Percentage of execution time spent during XDR encoding for JS scripts up until the page load event fires."
+  },
+  "JS_BASELINE_COMPILE_PROPORTION" : {
+    "record_in_processes": ["content"],
+    "products": ["firefox", "geckoview_streaming"],
+    "alert_emails": ["dpalmeiro@mozilla.com","perfteam@mozilla.com"],
+    "expires_in_version": "89",
+    "releaseChannelCollection": "opt-out",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 20,
+    "bug_numbers": [1664475],
+    "description": "Percentage of execution time spent during Baseline compilation for JS scripts up until the page load event fires."
+  },
+  "JS_BYTECODE_CACHING_TIME" : {
+    "record_in_processes": ["content"],
+    "products": ["firefox", "geckoview_streaming"],
+    "alert_emails": ["dpalmeiro@mozilla.com","perfteam@mozilla.com"],
+    "expires_in_version": "89",
+    "releaseChannelCollection": "opt-out",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 100,
+    "bug_numbers": [1664475],
+    "description": "Time in milliseconds spent caching JS bytecode for scripts executed during a page load."
+  },
   "DOM_SCRIPT_KIND": {
     "record_in_processes": ["main", "content"],
     "products": ["firefox", "fennec"],

toolkit/components/telemetry/geckoview/streaming/metrics.yaml

@@ -1187,6 +1187,97 @@ performance.interaction:
       - dolske@mozilla.com
     expires: never
 
+js:
+  execution_percentage:
+    type: custom_distribution
+    description: >
+      Percentage of page load time spent executing Javascript.
+    range_min: 0
+    range_max: 100
+    bucket_count: 20
+    histogram_type: linear
+    unit: percentage of execution time
+    gecko_datapoint: JS_EXECUTION_PROPORTION
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475#c6
+    notification_emails:
+      - dpalmeiro@mozilla.com
+      - perfteam@mozilla.com
+    expires: 2021-03-18
+  delazification_percentage:
+    type: custom_distribution
+    description: >
+      Percentage of execution time spent during delazification for
+      JS scripts up until the page load event fires.
+    range_min: 0
+    range_max: 100
+    bucket_count: 20
+    histogram_type: linear
+    unit: percentage of execution time
+    gecko_datapoint: JS_DELAZIFICATION_PROPORTION
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475#c6
+    notification_emails:
+      - dpalmeiro@mozilla.com
+      - perfteam@mozilla.com
+    expires: 2021-03-18
+  xdr_encode_percentage:
+    type: custom_distribution
+    description: >
+      Percentage of execution time spent during XDR encoding for
+      JS scripts up until the page load event fires.
+    range_min: 0
+    range_max: 100
+    bucket_count: 20
+    histogram_type: linear
+    unit: percentage of execution time
+    gecko_datapoint: JS_XDR_ENCODING_PROPORTION
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475#c6
+    notification_emails:
+      - dpalmeiro@mozilla.com
+      - perfteam@mozilla.com
+    expires: 2021-03-18
+  baseline_compile_percentage:
+    type: custom_distribution
+    description: >
+      Percentage of execution time spent during Baseline compilation for
+      JS scripts up until the page load event fires.
+    range_min: 0
+    range_max: 100
+    bucket_count: 20
+    histogram_type: linear
+    unit: percentage of execution time
+    gecko_datapoint: JS_BASELINE_COMPILE_PROPORTION
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475#c6
+    notification_emails:
+      - dpalmeiro@mozilla.com
+      - perfteam@mozilla.com
+    expires: 2021-03-18
+  bytecode_caching_time:
+    type: timing_distribution
+    unit: milliseconds
+    description: >
+      Time spent caching JS bytecode for scripts executed during a page load.
+    gecko_datapoint: JS_BYTECODE_CACHING_TIME
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1664475#c6
+    notification_emails:
+      - dpalmeiro@mozilla.com
+      - perfteam@mozilla.com
+    expires: 2021-03-18
+
 javascript.gc:
   total_time:
     type: timing_distribution