Bug 1579876 - Add telemetry to estimate the benefit of a streaming parser for JS. data-review=mlopatka r=jorendorff

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

--HG--
extra : moz-landing-system : lando

dom/script/ScriptLoadHandler.cpp

@@ -80,8 +80,10 @@ nsresult ScriptLoadHandler::DecodeRawDataHelper(const uint8_t* aData,
     Accumulate(DOM_SCRIPT_LOAD_INCREMENTAL_RATIO, 100 * haveRead / (haveRead + written));
     // Compute the rate of transfer of the incremental data calls averaged
     // across the time needed to complete the request.
-    double ms = (TimeStamp::Now() - mFirstOnIncrementalData).ToMilliseconds();
+    auto streamingTime = TimeStamp::Now() - mFirstOnIncrementalData;
+    double ms = streamingTime.ToMilliseconds();
     Accumulate(DOM_SCRIPT_LOAD_INCREMENTAL_AVG_TRANSFER_RATE, haveRead / ms);
+    mRequest->mStreamingTime = streamingTime;
   }
   if (!aEndOfStream && !haveRead) {
     mFirstOnIncrementalData = TimeStamp::Now();

dom/script/ScriptLoadRequest.cpp

@@ -95,7 +95,8 @@ ScriptLoadRequest::ScriptLoadRequest(ScriptKind aKind, nsIURI* aURI,
       mLineNo(1),
       mIntegrity(aIntegrity),
       mReferrer(aReferrer),
-      mUnreportedPreloadError(NS_OK) {
+      mUnreportedPreloadError(NS_OK),
+      mStreamingTime() {
   MOZ_ASSERT(mFetchOptions);
 }
 

dom/script/ScriptLoadRequest.h

@@ -12,6 +12,7 @@
 #include "mozilla/dom/SRIMetadata.h"
 #include "mozilla/LinkedList.h"
 #include "mozilla/Maybe.h"
+#include "mozilla/TimeStamp.h"
 #include "mozilla/Utf8.h"  // mozilla::Utf8Unit
 #include "mozilla/Variant.h"
 #include "mozilla/Vector.h"
@@ -331,6 +332,11 @@ class ScriptLoadRequest
   // For preload requests, we defer reporting errors to the console until the
   // request is used.
   nsresult mUnreportedPreloadError;
+
+  // Measure the duration of streamed bytes and the duration of parsing, to
+  // determine the maximal gain of streaming parsing using the same parsing
+  // speed.
+  TimeDuration mStreamingTime;
 };
 
 class ScriptLoadRequestList : private mozilla::LinkedList<ScriptLoadRequest> {

dom/script/ScriptLoader.cpp

@@ -2572,6 +2572,29 @@ class MOZ_RAII AutoSetProcessingScriptTag {
   ~AutoSetProcessingScriptTag() { mContext->SetProcessingScriptTag(mOldTag); }
 };
 
+static void ReportStreamAndParseTelemetry(JS::Handle<JSScript*> aScript,
+                                          TimeDuration aStreamingTime) {
+  using namespace mozilla::Telemetry;
+  if (!aStreamingTime) {
+    Accumulate(DOM_SCRIPT_IS_STREAMED, false);
+    return;
+  }
+  Accumulate(DOM_SCRIPT_IS_STREAMED, true);
+  TimeDuration parseTime;
+  TimeDuration emitTime;
+  JS_ReportFirstCompileTime(aScript, parseTime, emitTime);
+
+  double st = aStreamingTime.ToMilliseconds();
+  double pt = parseTime.ToMilliseconds();
+  double et = emitTime.ToMilliseconds();
+  double total = st + pt + et;
+  double spt = st + std::max(pt - st, double(0)) + et;
+  Accumulate(DOM_SCRIPT_LOAD_STREAM_TIME_PERCENT, 100 * st / total);
+  Accumulate(DOM_SCRIPT_LOAD_PARSE_TIME_PERCENT, 100 * pt / total);
+  Accumulate(DOM_SCRIPT_LOAD_EMIT_TIME_PERCENT, 100 * et / total);
+  Accumulate(DOM_SCRIPT_LOAD_STREAMPARSE_ESTIMATE_PERCENT, 100 * spt / total);
+}
+
 static nsresult ExecuteCompiledScript(JSContext* aCx,
                                       ScriptLoadRequest* aRequest,
                                       nsJSUtils::ExecutionContext& aExec) {
@@ -2582,6 +2605,11 @@ static nsresult ExecuteCompiledScript(JSContext* aCx,
     return NS_OK;
   }
 
+  // Report telemetry about streaming, parsing and emitting code for the given
+  // script. These telemetry are used to analyze whether it would be beneficial
+  // to use a streaming parser.
+  ReportStreamAndParseTelemetry(script, aRequest->mStreamingTime);
+
   // Create a ClassicScript object and associate it with the JSScript.
   RefPtr<ClassicScript> classicScript =
       new ClassicScript(aRequest->mFetchOptions, aRequest->mBaseURL);

js/src/frontend/BytecodeCompiler.cpp

@@ -498,6 +498,10 @@ JSScript* frontend::ScriptCompiler<Unit>::compileScript(
     BytecodeCompiler& info, HandleObject environment, SharedContext* sc) {
   assertSourceParserAndScriptCreated(info);
 
+  // We are about to start parsing the source. Record this information for
+  // telemetry purposes.
+  info.script->scriptSource()->recordParseStarted();
+
   TokenStreamPosition startPosition(info.keepAtoms, parser->tokenStream);
 
   JSContext* cx = info.cx;
@@ -518,6 +522,10 @@ JSScript* frontend::ScriptCompiler<Unit>::compileScript(
     AutoGeckoProfilerEntry pseudoFrame(cx, "script emit",
                                        JS::ProfilingCategoryPair::JS_Parsing);
     if (pn) {
+      // We are about to start emitting bytecode. Record this information for
+      // telemetry purposes.
+      info.script->scriptSource()->recordEmitStarted();
+
       // Publish deferred items
       if (!parser->publishDeferredItems()) {
         return nullptr;

js/src/jsfriendapi.cpp

@@ -561,6 +561,17 @@ JS_FRIEND_API void JS_SetSetUseCounterCallback(
   cx->runtime()->setUseCounterCallback(cx->runtime(), callback);
 }
 
+JS_FRIEND_API void JS_ReportFirstCompileTime(JS::HandleScript script,
+                                             mozilla::TimeDuration& parse,
+                                             mozilla::TimeDuration& emit) {
+  auto ss = script->scriptSource();
+  if (!ss) {
+    return;
+  }
+  parse = ss->parseTime();
+  emit = ss->emitTime();
+}
+
 JS_FRIEND_API JSObject* JS_CloneObject(JSContext* cx, HandleObject obj,
                                        HandleObject protoArg) {
   // |obj| might be in a different compartment.

js/src/jsfriendapi.h

@@ -11,6 +11,7 @@
 #include "mozilla/Casting.h"
 #include "mozilla/Maybe.h"
 #include "mozilla/MemoryReporting.h"
+#include "mozilla/TimeStamp.h"
 #include "mozilla/UniquePtr.h"
 
 #include "jspubtd.h"
@@ -198,6 +199,10 @@ typedef void (*JSSetUseCounterCallback)(JSObject* obj, JSUseCounter counter);
 extern JS_FRIEND_API void JS_SetSetUseCounterCallback(
     JSContext* cx, JSSetUseCounterCallback callback);
 
+extern JS_FRIEND_API void JS_ReportFirstCompileTime(JS::HandleScript script,
+                                                    mozilla::TimeDuration& parse,
+                                                    mozilla::TimeDuration& emit);
+
 extern JS_FRIEND_API JSPrincipals* JS_GetScriptPrincipals(JSScript* script);
 
 namespace js {

js/src/vm/JSScript.h

@@ -649,12 +649,25 @@ class ScriptSource {
   // function should be recorded before their first execution.
   UniquePtr<XDRIncrementalEncoder> xdrEncoder_ = nullptr;
 
-  // Instant at which the first parse of this source ended, or null
+  // Instant at which the first parse of this source started, or null
   // if the source hasn't been parsed yet.
   //
-  // Used for statistics purposes, to determine how much time code spends
-  // syntax parsed before being full parsed, to help determine whether
-  // our syntax parse vs. full parse heuristics are correct.
+  // Used for telemetry purposes, to evaluate the benefit of using a streaming
+  // parser.
+  mozilla::TimeStamp parseStarted_;
+
+  // Instant at which the top-level compilation starts emitting bytes, or null
+  // if the source hasn't been compiled yet.
+  //
+  // Used for telemetry purposes, to evaluate the cost of the front-end.
+  mozilla::TimeStamp emitStarted_;
+
+  // Instant at which the first compilation of this source ended, or null if the
+  // source hasn't been parsed yet.
+  //
+  // Used for statistics purposes, to determine how much time code spends syntax
+  // parsed before being full parsed, to help determine whether our syntax parse
+  // vs. full parse heuristics are correct.
   mozilla::TimeStamp parseEnded_;
 
   // A string indicating how this source code was introduced into the system.
@@ -1194,6 +1207,22 @@ class ScriptSource {
   bool xdrFinalizeEncoder(JS::TranscodeBuffer& buffer);
 
   const mozilla::TimeStamp parseEnded() const { return parseEnded_; }
+  const mozilla::TimeDuration parseTime() const {
+    return emitStarted_ - parseStarted_;
+  }
+  const mozilla::TimeDuration emitTime() const {
+    return parseEnded_ - emitStarted_;
+  }
+  // Record the timestamp at which this source is starting to be parsed.
+  void recordParseStarted() {
+    MOZ_ASSERT(parseStarted_.IsNull());
+    parseStarted_ = ReallyNow();
+  }
+  // Record the timestamp at which this source is starting to be parsed.
+  void recordEmitStarted() {
+    MOZ_ASSERT(emitStarted_.IsNull());
+    emitStarted_ = ReallyNow();
+  }
   // Inform `this` source that it has been fully parsed.
   void recordParseEnded() {
     MOZ_ASSERT(parseEnded_.IsNull());

toolkit/components/telemetry/Histograms.json

@@ -13687,6 +13687,63 @@
     "bug_numbers": [1573904],
     "description": "Speed at which JavaScript-text bytes are transferred incrementally, measured between the first onIncremantalData call and the onStreamComplete call (in character/ms)."
   },
+  "DOM_SCRIPT_IS_STREAMED": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "alert_emails": ["nicolas.b.pierron@mozilla.com"],
+    "expires_in_version": "75",
+    "kind": "boolean",
+    "bug_numbers": [1579876],
+    "description": "Count whether JS scripts are streamed or not. Useful for interpreting DOM_SCRIPT_LOAD_* telemetry."
+  },
+  "DOM_SCRIPT_LOAD_STREAM_TIME_PERCENT": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "alert_emails": ["nicolas.b.pierron@mozilla.com"],
+    "expires_in_version": "75",
+    "kind": "linear",
+    "low": 2,
+    "high": 100,
+    "n_buckets": 99,
+    "bug_numbers": [1579876],
+    "description": "Percent of time spent streaming bytes while loading a JS Script."
+  },
+  "DOM_SCRIPT_LOAD_PARSE_TIME_PERCENT": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "alert_emails": ["nicolas.b.pierron@mozilla.com"],
+    "expires_in_version": "75",
+    "kind": "linear",
+    "low": 2,
+    "high": 100,
+    "n_buckets": 99,
+    "bug_numbers": [1579876],
+    "description": "Percent of time spent syntax-parsing and full-parsing the top-level script, while loading a JS script."
+  },
+  "DOM_SCRIPT_LOAD_EMIT_TIME_PERCENT": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "alert_emails": ["nicolas.b.pierron@mozilla.com"],
+    "expires_in_version": "75",
+    "kind": "linear",
+    "low": 2,
+    "high": 100,
+    "n_buckets": 99,
+    "bug_numbers": [1579876],
+    "description": "Percent of time spent emitting bytecode for the top-level script, while loading a JS script."
+  },
+  "DOM_SCRIPT_LOAD_STREAMPARSE_ESTIMATE_PERCENT": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "alert_emails": ["nicolas.b.pierron@mozilla.com"],
+    "expires_in_version": "75",
+    "kind": "linear",
+    "low": 2,
+    "high": 100,
+    "n_buckets": 99,
+    "bug_numbers": [1579876],
+    "description": "Estimated percent of time taken use a streaming parser compared to not using a streaming parser."
+  },
   "VIDEO_DROPPED_FRAMES_PROPORTION" : {
     "record_in_processes": ["content"],
     "products": ["firefox", "geckoview"],