DevTools: add the logging aspect into the PerformanceMonitor

third_party/WebKit/Source/core/frame/PerformanceMonitor.cpp

Index: third_party/WebKit/Source/core/frame/PerformanceMonitor.cpp
diff --git a/third_party/WebKit/Source/core/frame/PerformanceMonitor.cpp b/third_party/WebKit/Source/core/frame/PerformanceMonitor.cpp
index 9258d86ae622bf30f9648d6dc66e2de8909da747..fe1a3d2698864ae611cae75a3c64938407866072 100644
--- a/third_party/WebKit/Source/core/frame/PerformanceMonitor.cpp
+++ b/third_party/WebKit/Source/core/frame/PerformanceMonitor.cpp
@@ -4,21 +4,27 @@
 
 #include "core/frame/PerformanceMonitor.h"
 
+#include "bindings/core/v8/SourceLocation.h"
 #include "core/InstrumentingAgents.h"
 #include "core/dom/Document.h"
 #include "core/dom/ExecutionContext.h"
 #include "core/frame/DOMWindow.h"
 #include "core/frame/Frame.h"
+#include "core/frame/FrameConsole.h"
 #include "core/frame/LocalFrame.h"
 #include "core/frame/UseCounter.h"
+#include "core/inspector/ConsoleMessage.h"
 #include "core/timing/DOMWindowPerformance.h"
 #include "core/timing/Performance.h"
 #include "public/platform/Platform.h"
+#include "wtf/CurrentTime.h"
 
 namespace blink {
 
 namespace {
 static const double kLongTaskThresholdMillis = 50.0;
+static const double kMaxSyncLayoutMillis = 15.0;

[panicker, 2016/11/04 20:59:28]

kSyncLayoutThresholdMillis for consistency?

[pfeldman, 2016/11/04 21:26:39]

Done.

+
 static const char kUnknownAttribution[] = "unknown";
 static const char kAmbugiousAttribution[] = "multiple-contexts";
 static const char kSameOriginAttribution[] = "same-origin";
@@ -41,7 +47,7 @@ void PerformanceMonitor::performanceObserverAdded(Performance* performance) {
   LocalFrame* frame = performance->frame();
   PerformanceMonitor* monitor = frame->performanceMonitor();
   monitor->m_webPerformanceObservers.add(performance);
-  monitor->enable();
+  monitor->updateInstrumentation();
 }
 
 // static
@@ -53,8 +59,75 @@ void PerformanceMonitor::performanceObserverRemoved(Performance* performance) {
   }
   PerformanceMonitor* monitor = frame->performanceMonitor();
   monitor->m_webPerformanceObservers.remove(performance);
-  if (!monitor->m_webPerformanceObservers.size())
-    monitor->disable();
+  monitor->updateInstrumentation();
+}
+
+// static
+void PerformanceMonitor::willExecuteScript(ExecutionContext* context) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(context);
+  if (performanceMonitor)
+    performanceMonitor->innerWillExecuteScript(context);
+}
+
+// static
+void PerformanceMonitor::didExecuteScript(ExecutionContext* context) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(context);
+  if (performanceMonitor)
+    performanceMonitor->didExecuteScript();
+}
+
+// static
+void PerformanceMonitor::willUpdateLayout(Document* document) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(document);
+  if (performanceMonitor)
+    performanceMonitor->willUpdateLayout();
+}
+
+// static
+void PerformanceMonitor::didUpdateLayout(Document* document) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(document);
+  if (performanceMonitor)
+    performanceMonitor->didUpdateLayout();
+}
+
+// static
+void PerformanceMonitor::willRecalculateStyle(Document* document) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(document);
+  if (performanceMonitor)
+    performanceMonitor->willRecalculateStyle();
+}
+
+// static
+void PerformanceMonitor::didRecalculateStyle(Document* document) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(document);
+  if (performanceMonitor)
+    performanceMonitor->didRecalculateStyle();
+}
+
+// static
+void PerformanceMonitor::logViolation(ExecutionContext* context,
+                                      const String& messageText) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(context);
+  if (performanceMonitor)
+    performanceMonitor->logViolation(messageText);
+}
+
+// static
+void PerformanceMonitor::logViolation(
+    ExecutionContext* context,
+    const String& messageText,
+    std::unique_ptr<SourceLocation> location) {
+  PerformanceMonitor* performanceMonitor =
+      PerformanceMonitor::instrumentingMonitor(context);
+  if (performanceMonitor)
+    performanceMonitor->logViolation(messageText, std::move(location));
 }
 
 // static
@@ -69,38 +142,37 @@ PerformanceMonitor* PerformanceMonitor::instrumentingMonitor(
   return monitor->m_enabled ? monitor : nullptr;
 }
 
-// static
-void PerformanceMonitor::willExecuteScript(ExecutionContext* context) {
-  PerformanceMonitor* performanceMonitor =
-      PerformanceMonitor::instrumentingMonitor(context);
-  if (performanceMonitor)
-    performanceMonitor->innerWillExecuteScript(context);
-}
-
 PerformanceMonitor::PerformanceMonitor(LocalFrame* localRoot)
     : m_localRoot(localRoot) {}
 
 PerformanceMonitor::~PerformanceMonitor() {}
 
-void PerformanceMonitor::enable() {
-  if (m_enabled)
-    return;
-  m_enabled = true;
-  UseCounter::count(m_localRoot, UseCounter::LongTaskObserver);
-  Platform::current()->currentThread()->addTaskTimeObserver(this);
-  Platform::current()->currentThread()->addTaskObserver(this);
+void PerformanceMonitor::setLoggingEnabled(bool enabled) {
+  m_loggingEnabled = enabled;
+  updateInstrumentation();
 }
 
-void PerformanceMonitor::disable() {
-  if (!m_enabled)
-    return;
-  m_enabled = false;
-  DCHECK(!m_webPerformanceObservers.size());
-  Platform::current()->currentThread()->removeTaskTimeObserver(this);
-  Platform::current()->currentThread()->removeTaskObserver(this);
+void PerformanceMonitor::updateInstrumentation() {
+  if (m_loggingEnabled || m_webPerformanceObservers.size()) {
+    if (!m_enabled) {
+      m_enabled = true;
+      UseCounter::count(m_localRoot, UseCounter::LongTaskObserver);
+      Platform::current()->currentThread()->addTaskTimeObserver(this);
+      Platform::current()->currentThread()->addTaskObserver(this);
+    }
+  }
+
+  if (!m_loggingEnabled && !m_webPerformanceObservers.size()) {

[caseq, 2016/11/04 20:58:59]

This really could be an else. 
bool should_enable = m_loggingEnabled || m_webPerformanceObservers.size()
if (should_enable == m_enabled)
  return;
if (should_enable) {
   ...
} else {
   ...
}

[pfeldman, 2016/11/04 21:26:39]

Omg, so much better! (I had more branches there)

+    if (m_enabled) {
+      m_enabled = false;
+      Platform::current()->currentThread()->removeTaskTimeObserver(this);
+      Platform::current()->currentThread()->removeTaskObserver(this);
+    }
+  }
 }
 
 void PerformanceMonitor::innerWillExecuteScript(ExecutionContext* context) {
+  m_isExecutingScript = true;
   // Heuristic for minimal frame context attribution: note the frame context
   // for each script execution. When a long task is encountered,
   // if there is only one frame context involved, then report it.
@@ -108,23 +180,63 @@ void PerformanceMonitor::innerWillExecuteScript(ExecutionContext* context) {
   // NOTE: This heuristic is imperfect and will be improved in V2 API.
   // In V2, timing of script execution along with style & layout updates will be
   // accounted for detailed and more accurate attribution.
-  if (context->isDocument() && toDocument(context)->frame()) {
+  if (context->isDocument() && toDocument(context)->frame())
     m_frameContexts.add(toDocument(context)->frame());
+}
+
+void PerformanceMonitor::didExecuteScript() {
+  m_isExecutingScript = false;
+}
+
+void PerformanceMonitor::willUpdateLayout() {
+  if (m_isExecutingScript)
+    m_layoutStartTime = WTF::monotonicallyIncreasingTime();
+}
+
+void PerformanceMonitor::didUpdateLayout() {
+  if (m_isExecutingScript) {
+    m_perTaskStyleAndLayoutTime +=
+        WTF::monotonicallyIncreasingTime() - m_layoutStartTime;
+  }
+}
+
+void PerformanceMonitor::willRecalculateStyle() {
+  if (m_isExecutingScript)
+    m_styleStartTime = WTF::monotonicallyIncreasingTime();
+}
+
+void PerformanceMonitor::didRecalculateStyle() {
+  if (m_isExecutingScript) {
+    m_perTaskStyleAndLayoutTime +=
+        WTF::monotonicallyIncreasingTime() - m_styleStartTime;
   }
 }
 
 void PerformanceMonitor::willProcessTask() {
+  m_perTaskStyleAndLayoutTime = 0;
+  m_isExecutingTask = true;

[panicker, 2016/11/04 20:59:28]

this is not used yet?

[pfeldman, 2016/11/04 21:26:39]

Done.

   // Reset m_frameContexts. We don't clear this in didProcessTask
   // as it is needed in ReportTaskTime which occurs after didProcessTask.
   m_frameContexts.clear();
 }
 
-void PerformanceMonitor::didProcessTask() {}
+void PerformanceMonitor::didProcessTask() {
+  m_isExecutingTask = false;
+  if (m_perTaskStyleAndLayoutTime * 1000 < kMaxSyncLayoutMillis)
+    return;
+
+  if (m_loggingEnabled) {
+    logViolation(
+        String::format("Forced reflow while executing JavaScript took %ldms.",
+                       lround(m_perTaskStyleAndLayoutTime * 1000)));
+  }
+}
 
 void PerformanceMonitor::ReportTaskTime(scheduler::TaskQueue*,
                                         double startTime,
                                         double endTime) {
-  if (((endTime - startTime) * 1000) <= kLongTaskThresholdMillis)
+  double taskTimeMs = (endTime - startTime) * 1000;
+  if (taskTimeMs <= kLongTaskThresholdMillis)
     return;
 
   for (Performance* performance : m_webPerformanceObservers) {
@@ -135,6 +247,25 @@ void PerformanceMonitor::ReportTaskTime(scheduler::TaskQueue*,
     performance->addLongTaskTiming(startTime, endTime, attribution.first,
                                    attribution.second);
   }
+  if (m_loggingEnabled) {
+    logViolation(String::format("Long running JavaScript task took %ldms.",
+                                lround(taskTimeMs)));
+  }
+}
+
+void PerformanceMonitor::logViolation(const String& messageText) {
+  ConsoleMessage* message = ConsoleMessage::create(
+      PerfMessageSource, ViolationMessageLevel, messageText);
+  m_localRoot->console().addMessage(message);
+}
+
+void PerformanceMonitor::logViolation(
+    const String& messageText,
+    std::unique_ptr<SourceLocation> location) {
+  ConsoleMessage* message =
+      ConsoleMessage::create(PerfMessageSource, ViolationMessageLevel,
+                             messageText, std::move(location));
+  m_localRoot->console().addMessage(message);
 }
 
 /**