Fix WebCore.Scripts.ParserBlocking.TimeBetweenLoadedAndCompiled

1) The results were skewed by scripts from the same resource being ran several
times (so we saw times > 10 s).

2) Script run time was included in the measurement, and it shouldn't be.

WebCore.Scripts.Deferred.TimeBetweenLoadedAndCompiled is removed for now (to be
fixed later, when it's really needed). Tracking whether a deferred script was
already loaded when requested is more complicated.

BUG=

Review URL: https://codereview.chromium.org/551333002

git-svn-id: svn://svn.chromium.org/blink/trunk@181641 bbb929c8-8fbe-4397-9dbb-9b2b20218538

third_party/WebKit/Source/bindings/core/v8/ScriptController.cpp

@@ -166,7 +166,7 @@ v8::Local<v8::Value> ScriptController::callFunction(ExecutionContext* context, v
     return result;
 }
 
-v8::Local<v8::Value> ScriptController::executeScriptAndReturnValue(v8::Handle<v8::Context> context, const ScriptSourceCode& source, AccessControlStatus corsStatus)
+v8::Local<v8::Value> ScriptController::executeScriptAndReturnValue(v8::Handle<v8::Context> context, const ScriptSourceCode& source, AccessControlStatus corsStatus, double* compilationFinishTime)
 {
     TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("devtools.timeline"), "EvaluateScript", "data", InspectorEvaluateScriptEvent::data(m_frame, source.url().string(), source.startLine()));
     TRACE_EVENT_INSTANT1(TRACE_DISABLED_BY_DEFAULT("devtools.timeline.stack"), "CallStack", "stack", InspectorCallStackEvent::currentCallStack());
@@ -188,6 +188,9 @@ v8::Local<v8::Value> ScriptController::executeScriptAndReturnValue(v8::Handle<v8
 
         v8::Handle<v8::Script> script = V8ScriptRunner::compileScript(source, m_isolate, corsStatus, v8CacheOptions);
 
+        if (compilationFinishTime) {
+            *compilationFinishTime = WTF::monotonicallyIncreasingTime();
+        }
         // Keep LocalFrame (and therefore ScriptController) alive.
         RefPtr<LocalFrame> protect(m_frame);
         result = V8ScriptRunner::runCompiledScript(script, m_frame->document(), m_isolate);
@@ -568,10 +571,10 @@ void ScriptController::executeScriptInMainWorld(const String& script, ExecuteScr
     evaluateScriptInMainWorld(ScriptSourceCode(script), NotSharableCrossOrigin, policy);
 }
 
-void ScriptController::executeScriptInMainWorld(const ScriptSourceCode& sourceCode, AccessControlStatus corsStatus)
+void ScriptController::executeScriptInMainWorld(const ScriptSourceCode& sourceCode, AccessControlStatus corsStatus, double* compilationFinishTime)
 {
     v8::HandleScope handleScope(m_isolate);
-    evaluateScriptInMainWorld(sourceCode, corsStatus, DoNotExecuteScriptWhenScriptsDisabled);
+    evaluateScriptInMainWorld(sourceCode, corsStatus, DoNotExecuteScriptWhenScriptsDisabled, compilationFinishTime);
 }
 
 v8::Local<v8::Value> ScriptController::executeScriptInMainWorldAndReturnValue(const ScriptSourceCode& sourceCode)
@@ -579,7 +582,7 @@ v8::Local<v8::Value> ScriptController::executeScriptInMainWorldAndReturnValue(co
     return evaluateScriptInMainWorld(sourceCode, NotSharableCrossOrigin, DoNotExecuteScriptWhenScriptsDisabled);
 }
 
-v8::Local<v8::Value> ScriptController::evaluateScriptInMainWorld(const ScriptSourceCode& sourceCode, AccessControlStatus corsStatus, ExecuteScriptPolicy policy)
+v8::Local<v8::Value> ScriptController::evaluateScriptInMainWorld(const ScriptSourceCode& sourceCode, AccessControlStatus corsStatus, ExecuteScriptPolicy policy, double* compilationFinishTime)
 {
     if (policy == DoNotExecuteScriptWhenScriptsDisabled && !canExecuteScripts(AboutToExecuteScript))
         return v8::Local<v8::Value>();
@@ -603,7 +606,7 @@ v8::Local<v8::Value> ScriptController::evaluateScriptInMainWorld(const ScriptSou
     OwnPtr<ScriptSourceCode> maybeProcessedSourceCode =  InspectorInstrumentation::preprocess(m_frame, sourceCode);
     const ScriptSourceCode& sourceCodeToCompile = maybeProcessedSourceCode ? *maybeProcessedSourceCode : sourceCode;
 
-    v8::Local<v8::Value> object = executeScriptAndReturnValue(scriptState->context(), sourceCodeToCompile, corsStatus);
+    v8::Local<v8::Value> object = executeScriptAndReturnValue(scriptState->context(), sourceCodeToCompile, corsStatus, compilationFinishTime);
     m_sourceURL = savedSourceURL;
 
     if (object.IsEmpty())

third_party/WebKit/Source/bindings/core/v8/ScriptController.h

@@ -82,9 +82,9 @@ public:
 
     // Evaluate JavaScript in the main world.
     void executeScriptInMainWorld(const String&, ExecuteScriptPolicy = DoNotExecuteScriptWhenScriptsDisabled);
-    void executeScriptInMainWorld(const ScriptSourceCode&, AccessControlStatus = NotSharableCrossOrigin);
+    void executeScriptInMainWorld(const ScriptSourceCode&, AccessControlStatus = NotSharableCrossOrigin, double* compilationFinishTime = 0);
     v8::Local<v8::Value> executeScriptInMainWorldAndReturnValue(const ScriptSourceCode&);
-    v8::Local<v8::Value> executeScriptAndReturnValue(v8::Handle<v8::Context>, const ScriptSourceCode&, AccessControlStatus = NotSharableCrossOrigin);
+    v8::Local<v8::Value> executeScriptAndReturnValue(v8::Handle<v8::Context>, const ScriptSourceCode&, AccessControlStatus = NotSharableCrossOrigin, double* compilationFinishTime = 0);
 
     // Executes JavaScript in an isolated world. The script gets its own global scope,
     // its own prototypes for intrinsic JavaScript objects (String, Array, and so-on),
@@ -153,7 +153,7 @@ private:
     typedef HashMap<int, OwnPtr<WindowProxy> > IsolatedWorldMap;
     typedef HashMap<Widget*, NPObject*> PluginObjectMap;
 
-    v8::Local<v8::Value> evaluateScriptInMainWorld(const ScriptSourceCode&, AccessControlStatus, ExecuteScriptPolicy);
+    v8::Local<v8::Value> evaluateScriptInMainWorld(const ScriptSourceCode&, AccessControlStatus, ExecuteScriptPolicy, double* compilationFinishTime = 0);
 
     LocalFrame* m_frame;
     const String* m_sourceURL;

third_party/WebKit/Source/core/dom/ScriptLoader.cpp

@@ -290,7 +290,7 @@ bool isSVGScriptLoader(Element* element)
     return isSVGScriptElement(*element);
 }
 
-void ScriptLoader::executeScript(const ScriptSourceCode& sourceCode)
+void ScriptLoader::executeScript(const ScriptSourceCode& sourceCode, double* compilationFinishTime)
 {
     ASSERT(m_alreadyStarted);
 
@@ -340,7 +340,7 @@ void ScriptLoader::executeScript(const ScriptSourceCode& sourceCode)
     // Create a script from the script element node, using the script
     // block's source and the script block's type.
     // Note: This is where the script is compiled and actually executed.
-    frame->script().executeScriptInMainWorld(sourceCode, corsCheck);
+    frame->script().executeScriptInMainWorld(sourceCode, corsCheck, compilationFinishTime);
 
     if (isHTMLScriptLoader(m_element)) {
         ASSERT(contextDocument->currentScript() == m_element);

third_party/WebKit/Source/core/dom/ScriptLoader.h

@@ -46,7 +46,7 @@ public:
 
     String scriptCharset() const { return m_characterEncoding; }
     String scriptContent() const;
-    void executeScript(const ScriptSourceCode&);
+    void executeScript(const ScriptSourceCode&, double* compilationFinishTime = 0);
     void execute(ScriptResource*);
 
     // XML parser calls these

third_party/WebKit/Source/core/html/parser/HTMLScriptRunner.cpp

@@ -49,6 +49,7 @@ HTMLScriptRunner::HTMLScriptRunner(Document* document, HTMLScriptRunnerHost* hos
     , m_host(host)
     , m_scriptNestingLevel(0)
     , m_hasScriptsWaitingForResources(false)
+    , m_parserBlockingScriptAlreadyLoaded(false)
 {
     ASSERT(m_host);
 }
@@ -125,6 +126,7 @@ void HTMLScriptRunner::executeParsingBlockingScript()
 void HTMLScriptRunner::executePendingScriptAndDispatchEvent(PendingScript& pendingScript, PendingScriptType pendingScriptType)
 {
     bool errorOccurred = false;
+    double loadFinishTime = pendingScript.resource() ? pendingScript.resource()->loadFinishTime() : 0;
     ScriptSourceCode sourceCode = pendingScript.getSource(documentURLForScriptExecution(m_document), errorOccurred);
 
     // Stop watching loads before executeScript to prevent recursion if the script reloads itself.
@@ -142,6 +144,7 @@ void HTMLScriptRunner::executePendingScriptAndDispatchEvent(PendingScript& pendi
 
     // Clear the pending script before possible rentrancy from executeScript()
     RefPtrWillBeRawPtr<Element> element = pendingScript.releaseElementAndClear();
+    double compilationFinishTime = 0;
     if (ScriptLoader* scriptLoader = toScriptLoaderIfPossible(element.get())) {
         NestingLevelIncrementer nestingLevelIncrementer(m_scriptNestingLevel);
         IgnoreDestructiveWriteCountIncrementer ignoreDestructiveWriteCountIncrementer(m_document);
@@ -149,14 +152,14 @@ void HTMLScriptRunner::executePendingScriptAndDispatchEvent(PendingScript& pendi
             scriptLoader->dispatchErrorEvent();
         else {
             ASSERT(isExecutingScript());
-            scriptLoader->executeScript(sourceCode);
+            scriptLoader->executeScript(sourceCode, &compilationFinishTime);
             element->dispatchEvent(createScriptLoadEvent());
         }
     }
-    if (sourceCode.resource()) {
-        double timeBetweenLoadedAndCompiledMs = (WTF::monotonicallyIncreasingTime() - sourceCode.resource()->loadFinishTime()) * 1000;
-        const char* histogramName = pendingScriptType == PendingScriptBlockingParser ? "WebCore.Scripts.ParsingBlocking.TimeBetweenLoadedAndCompiled" : "WebCore.Scripts.Deferred.TimeBetweenLoadedAndCompiled";
-        blink::Platform::current()->histogramCustomCounts(histogramName, timeBetweenLoadedAndCompiledMs, 0, 10000, 50);
+    // The exact value doesn't matter; valid time stamps are much bigger than this value.
+    const double epsilon = 1;
+    if (pendingScriptType == PendingScriptBlockingParser && !m_parserBlockingScriptAlreadyLoaded && compilationFinishTime > epsilon && loadFinishTime > epsilon) {
+        blink::Platform::current()->histogramCustomCounts("WebCore.Scripts.ParsingBlocking.TimeBetweenLoadedAndCompiled", (compilationFinishTime - loadFinishTime) * 1000, 0, 10000, 50);
     }
 
     ASSERT(!isExecutingScript());
@@ -247,11 +250,12 @@ void HTMLScriptRunner::requestParsingBlockingScript(Element* element)
 
     ASSERT(m_parserBlockingScript.resource());
 
-    blink::Platform::current()->histogramEnumeration("WebCore.Scripts.ParsingBlocking.AlreadyLoaded", m_parserBlockingScript.resource()->isLoaded() ? 1 : 0, 2);
+    m_parserBlockingScriptAlreadyLoaded = m_parserBlockingScript.resource()->isLoaded();
+    blink::Platform::current()->histogramEnumeration("WebCore.Scripts.ParsingBlocking.AlreadyLoaded", m_parserBlockingScriptAlreadyLoaded ? 1 : 0, 2);
     // We only care about a load callback if resource is not already
     // in the cache. Callers will attempt to run the m_parserBlockingScript
     // if possible before returning control to the parser.
-    if (!m_parserBlockingScript.resource()->isLoaded())
+    if (!m_parserBlockingScriptAlreadyLoaded)
         m_parserBlockingScript.watchForLoad(this);
 }
 

third_party/WebKit/Source/core/html/parser/HTMLScriptRunner.h

@@ -101,6 +101,11 @@ private:
     // cause nested script execution when parsing <style> tags since </style>
     // tags can cause Document to call executeScriptsWaitingForResources.
     bool m_hasScriptsWaitingForResources;
+
+    // For tracking the times between script load and compilation, we need to
+    // know whether a parser blocking script was loaded previously, or whether
+    // it's really loaded when requested.
+    bool m_parserBlockingScriptAlreadyLoaded;
 };
 
 }