Replaced CaptureSnapshotDuration metric with DevToolsCommandDuration.

DevToolsCommandDuration is more generic and also captures protocol
overhead.

Change-Id: I9dc9815de22fd4ada9ace738fa7e3d551ea5ec2d
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2068823Reviewed-by: Dmitry Gozman <dgozman@chromium.org>
Reviewed-by: Andrey Kosyakov <caseq@chromium.org>
Reviewed-by: Johannes Henkel <johannes@chromium.org>
Commit-Queue: Peter Kvitek <kvitekp@chromium.org>
Cr-Commit-Position: refs/heads/master@{#744668}

third_party/blink/renderer/core/exported/web_dev_tools_agent_impl.cc

@@ -249,7 +249,7 @@ void WebDevToolsAgentImpl::AttachSession(DevToolsSession* session,
   session->Append(performance_agent);
 
   session->Append(MakeGarbageCollected<InspectorDOMSnapshotAgent>(
-      inspected_frames, dom_debugger_agent, performance_agent));
+      inspected_frames, dom_debugger_agent));
 
   session->Append(MakeGarbageCollected<InspectorAnimationAgent>(
       inspected_frames, css_agent, session->V8Session()));
@@ -410,9 +410,13 @@ void WebDevToolsAgentImpl::InspectElement(
   }
 }
 
-void WebDevToolsAgentImpl::DebuggerTaskStarted() {}
+void WebDevToolsAgentImpl::DebuggerTaskStarted() {
+  probe::WillStartDebuggerTask(probe_sink_);
+}
 
-void WebDevToolsAgentImpl::DebuggerTaskFinished() {}
+void WebDevToolsAgentImpl::DebuggerTaskFinished() {
+  probe::DidFinishDebuggerTask(probe_sink_);
+}
 
 void WebDevToolsAgentImpl::DidCommitLoadForLocalFrame(LocalFrame* frame) {
   resource_container_->DidCommitLoadForLocalFrame(frame);

third_party/blink/renderer/core/inspector/inspector_dom_snapshot_agent.cc

@@ -125,11 +125,9 @@ PhysicalRect InspectorDOMSnapshotAgent::TextFragmentRectInDocument(
 
 InspectorDOMSnapshotAgent::InspectorDOMSnapshotAgent(
     InspectedFrames* inspected_frames,
-    InspectorDOMDebuggerAgent* dom_debugger_agent,
-    InspectorPerformanceAgent* performance_agent)
+    InspectorDOMDebuggerAgent* dom_debugger_agent)
     : inspected_frames_(inspected_frames),
       dom_debugger_agent_(dom_debugger_agent),
-      performance_agent_(performance_agent),
       enabled_(&agent_state_, /*default_value=*/false) {}
 
 InspectorDOMSnapshotAgent::~InspectorDOMSnapshotAgent() = default;
@@ -228,17 +226,6 @@ protocol::Response InspectorDOMSnapshotAgent::captureSnapshot(
     std::unique_ptr<protocol::Array<protocol::DOMSnapshot::DocumentSnapshot>>*
         documents,
     std::unique_ptr<protocol::Array<String>>* strings) {
-  struct ScopedPerformanceReporter {
-    explicit ScopedPerformanceReporter(
-        InspectorPerformanceAgent* performance_agent)
-        : performance_agent(performance_agent) {
-      performance_agent->WillCaptureSnapshot();
-    }
-    ~ScopedPerformanceReporter() { performance_agent->DidCaptureSnapshot(); }
-    InspectorPerformanceAgent* performance_agent;
-    STACK_ALLOCATED();
-  } scoped_performance_reporter(performance_agent_);
-
   // This function may kick the layout, but external clients may call this
   // function outside of the layout phase.
   FontCachePurgePreventer fontCachePurgePreventer;
@@ -734,7 +721,6 @@ void InspectorDOMSnapshotAgent::VisitPaintLayer(
 void InspectorDOMSnapshotAgent::Trace(Visitor* visitor) {
   visitor->Trace(inspected_frames_);
   visitor->Trace(dom_debugger_agent_);
-  visitor->Trace(performance_agent_);
   visitor->Trace(document_order_map_);
   InspectorBaseAgent::Trace(visitor);
 }

third_party/blink/renderer/core/inspector/inspector_dom_snapshot_agent.h

@@ -9,7 +9,6 @@
 #include "third_party/blink/renderer/core/css/css_property_names.h"
 #include "third_party/blink/renderer/core/dom/dom_node_ids.h"
 #include "third_party/blink/renderer/core/inspector/inspector_base_agent.h"
-#include "third_party/blink/renderer/core/inspector/inspector_performance_agent.h"
 #include "third_party/blink/renderer/core/inspector/protocol/DOMSnapshot.h"
 #include "third_party/blink/renderer/core/layout/layout_text.h"
 #include "third_party/blink/renderer/platform/wtf/hash_map.h"
@@ -27,9 +26,7 @@ class PaintLayer;
 class CORE_EXPORT InspectorDOMSnapshotAgent final
     : public InspectorBaseAgent<protocol::DOMSnapshot::Metainfo> {
  public:
-  InspectorDOMSnapshotAgent(InspectedFrames*,
-                            InspectorDOMDebuggerAgent*,
-                            InspectorPerformanceAgent*);
+  InspectorDOMSnapshotAgent(InspectedFrames*, InspectorDOMDebuggerAgent*);
   ~InspectorDOMSnapshotAgent() override;
   void Trace(Visitor*) override;
 
@@ -131,7 +128,6 @@ class CORE_EXPORT InspectorDOMSnapshotAgent final
   DocumentOrderMap document_order_map_;
   Member<InspectedFrames> inspected_frames_;
   Member<InspectorDOMDebuggerAgent> dom_debugger_agent_;
-  Member<InspectorPerformanceAgent> performance_agent_;
   InspectorAgentState::Boolean enabled_;
   DISALLOW_COPY_AND_ASSIGN(InspectorDOMSnapshotAgent);
 };

third_party/blink/renderer/core/inspector/inspector_performance_agent.cc

@@ -57,7 +57,7 @@ void InspectorPerformanceAgent::InnerEnable() {
   task_start_ticks_ = base::TimeTicks();
   script_start_ticks_ = base::TimeTicks();
   v8compile_start_ticks_ = base::TimeTicks();
-  capture_snapshot_start_ticks_ = base::TimeTicks();
+  devtools_command_start_ticks_ = base::TimeTicks();
   thread_time_origin_ = GetThreadTimeNow();
 }
 
@@ -110,6 +110,10 @@ Response InspectorPerformanceAgent::setTimeDomain(const String& time_domain) {
     return Response::Error("Invalid time domain specification.");
   }
 
+  // Prevent this devtools command duration from being collected to avoid
+  // using start and end time from different time domains.
+  devtools_command_start_ticks_ = base::TimeTicks();
+
   return Response::OK();
 }
 
@@ -154,8 +158,12 @@ Response InspectorPerformanceAgent::getMetrics(
   AppendMetric(result.get(), "LayoutDuration", layout_duration_.InSecondsF());
   AppendMetric(result.get(), "RecalcStyleDuration",
                recalc_style_duration_.InSecondsF());
-  AppendMetric(result.get(), "CaptureSnapshotDuration",
-               capture_snapshot_duration_.InSecondsF());
+
+  base::TimeDelta devtools_command_duration = devtools_command_duration_;
+  if (!devtools_command_start_ticks_.is_null())
+    devtools_command_duration += now - devtools_command_start_ticks_;
+  AppendMetric(result.get(), "DevToolsCommandDuration",
+               devtools_command_duration.InSecondsF());
 
   base::TimeDelta script_duration = script_duration_;
   if (!script_start_ticks_.is_null())
@@ -174,10 +182,10 @@ Response InspectorPerformanceAgent::getMetrics(
   AppendMetric(result.get(), "TaskDuration", task_duration.InSecondsF());
 
   // Compute task time not accounted for by other metrics.
-  base::TimeDelta other_tasks_duration =
-      task_duration -
-      (script_duration + v8compile_duration + recalc_style_duration_ +
-       layout_duration_ + capture_snapshot_duration_);
+  base::TimeDelta known_tasks_duration =
+      script_duration + v8compile_duration + recalc_style_duration_ +
+      layout_duration_ + devtools_command_duration;
+  base::TimeDelta other_tasks_duration = task_duration - known_tasks_duration;
   AppendMetric(result.get(), "TaskOtherDuration",
                other_tasks_duration.InSecondsF());
 
@@ -232,8 +240,13 @@ void InspectorPerformanceAgent::ScriptStarts() {
 void InspectorPerformanceAgent::ScriptEnds() {
   if (--script_call_depth_)
     return;
-  script_duration_ += GetTimeTicksNow() - script_start_ticks_;
+  base::TimeDelta delta = GetTimeTicksNow() - script_start_ticks_;
+  script_duration_ += delta;
   script_start_ticks_ = base::TimeTicks();
+
+  // Exclude nested script execution from devtools command duration.
+  if (!devtools_command_start_ticks_.is_null())
+    devtools_command_start_ticks_ += delta;
 }
 
 void InspectorPerformanceAgent::Will(const probe::CallFunction& probe) {
@@ -262,11 +275,14 @@ void InspectorPerformanceAgent::Did(const probe::RecalculateStyle& probe) {
   recalc_style_count_++;
   recalc_style_start_ticks_ = base::TimeTicks();
 
-  // Exclude nested style re-calculations from script and layout duration.
+  // Exclude nested style re-calculations from script, layout and devtools
+  // command durations.
   if (!script_start_ticks_.is_null())
     script_start_ticks_ += delta;
   if (!layout_start_ticks_.is_null())
     layout_start_ticks_ += delta;
+  if (!devtools_command_start_ticks_.is_null())
+    devtools_command_start_ticks_ += delta;
 }
 
 void InspectorPerformanceAgent::Will(const probe::UpdateLayout& probe) {
@@ -282,12 +298,14 @@ void InspectorPerformanceAgent::Did(const probe::UpdateLayout& probe) {
   layout_count_++;
   layout_start_ticks_ = base::TimeTicks();
 
-  // Exclude nested layout update from script and style re-calculations
-  // duration.
+  // Exclude nested layout update from script, style re-calculations and
+  // devtools command durations.
   if (!script_start_ticks_.is_null())
     script_start_ticks_ += delta;
   if (!recalc_style_start_ticks_.is_null())
     recalc_style_start_ticks_ += delta;
+  if (!devtools_command_start_ticks_.is_null())
+    devtools_command_start_ticks_ += delta;
 }
 
 void InspectorPerformanceAgent::Will(const probe::V8Compile& probe) {
@@ -296,8 +314,25 @@ void InspectorPerformanceAgent::Will(const probe::V8Compile& probe) {
 }
 
 void InspectorPerformanceAgent::Did(const probe::V8Compile& probe) {
-  v8compile_duration_ += GetTimeTicksNow() - v8compile_start_ticks_;
+  base::TimeDelta delta = GetTimeTicksNow() - v8compile_start_ticks_;
+  v8compile_duration_ += delta;
   v8compile_start_ticks_ = base::TimeTicks();
+
+  // Exclude nested script compilation from devtools command duration.
+  if (!devtools_command_start_ticks_.is_null())
+    devtools_command_start_ticks_ += delta;
+}
+
+void InspectorPerformanceAgent::WillStartDebuggerTask() {
+  devtools_command_start_ticks_ = GetTimeTicksNow();
+}
+
+void InspectorPerformanceAgent::DidFinishDebuggerTask() {
+  if (!devtools_command_start_ticks_.is_null()) {
+    devtools_command_duration_ +=
+        GetTimeTicksNow() - devtools_command_start_ticks_;
+    devtools_command_start_ticks_ = base::TimeTicks();
+  }
 }
 
 // Will/DidProcessTask() ignore caller provided times to ensure time domain
@@ -308,21 +343,10 @@ void InspectorPerformanceAgent::WillProcessTask(base::TimeTicks start_time) {
 
 void InspectorPerformanceAgent::DidProcessTask(base::TimeTicks start_time,
                                                base::TimeTicks end_time) {
-  if (!task_start_ticks_.is_null())
+  if (!task_start_ticks_.is_null()) {
     task_duration_ += GetTimeTicksNow() - task_start_ticks_;
-  task_start_ticks_ = base::TimeTicks();
-}
-
-void InspectorPerformanceAgent::WillCaptureSnapshot() {
-  capture_snapshot_start_ticks_ = GetTimeTicksNow();
-}
-
-void InspectorPerformanceAgent::DidCaptureSnapshot() {
-  if (!capture_snapshot_start_ticks_.is_null()) {
-    capture_snapshot_duration_ +=
-        GetTimeTicksNow() - capture_snapshot_start_ticks_;
+    task_start_ticks_ = base::TimeTicks();
   }
-  capture_snapshot_start_ticks_ = base::TimeTicks();
 }
 
 void InspectorPerformanceAgent::Trace(Visitor* visitor) {

third_party/blink/renderer/core/inspector/inspector_performance_agent.h

@@ -56,16 +56,14 @@ class CORE_EXPORT InspectorPerformanceAgent final
   void Did(const probe::UpdateLayout&);
   void Will(const probe::V8Compile&);
   void Did(const probe::V8Compile&);
+  void WillStartDebuggerTask();
+  void DidFinishDebuggerTask();
 
   // TaskTimeObserver implementation.
   void WillProcessTask(base::TimeTicks start_time) override;
   void DidProcessTask(base::TimeTicks start_time,
                       base::TimeTicks end_time) override;
 
-  // Called from DOMSnapshotAgent
-  void WillCaptureSnapshot();
-  void DidCaptureSnapshot();
-
  private:
   void ScriptStarts();
   void ScriptEnds();
@@ -84,8 +82,8 @@ class CORE_EXPORT InspectorPerformanceAgent final
   base::TimeTicks task_start_ticks_;
   base::TimeDelta v8compile_duration_;
   base::TimeTicks v8compile_start_ticks_;
-  base::TimeDelta capture_snapshot_duration_;
-  base::TimeTicks capture_snapshot_start_ticks_;
+  base::TimeDelta devtools_command_duration_;
+  base::TimeTicks devtools_command_start_ticks_;
   base::TimeTicks thread_time_origin_;
   uint64_t layout_count_ = 0;
   uint64_t recalc_style_count_ = 0;

third_party/blink/renderer/core/probe/core_probes.json5

@@ -213,6 +213,8 @@
         "RecalculateStyle",
         "UpdateLayout",
         "V8Compile",
+        "WillStartDebuggerTask",
+        "DidFinishDebuggerTask",
       ]
     },
     InspectorTraceEvents: {

third_party/blink/renderer/core/probe/core_probes.pidl

@@ -161,6 +161,8 @@ interface CoreProbes {
   void ShouldBlockRequest(CoreProbeSink*, const KURL&, bool* result);
   void ShouldBypassServiceWorker(ExecutionContext* context, bool* result);
   void ConsoleTimeStamp(ExecutionContext*, const String& title);
+  void WillStartDebuggerTask(CoreProbeSink*);
+  void DidFinishDebuggerTask(CoreProbeSink*);
   void LifecycleEvent([Keep] LocalFrame*, DocumentLoader*, const char* name, double timestamp);
   void PaintTiming([Keep] Document*, const char* name, double timestamp);
   void DidCreateAudioContext(Document*);

third_party/blink/web_tests/http/tests/devtools/oopif/oopif-performance-monitor-expected.txt

@@ -4,9 +4,9 @@ Tests stability of performance metrics list.
 Metrics reported:
 AdSubframes
 AudioHandlers
-CaptureSnapshotDuration
 ContextLifecycleStateObservers
 DetachedScriptStates
+DevToolsCommandDuration
 Documents
 DomContentLoaded
 FirstMeaningfulPaint

third_party/blink/web_tests/inspector-protocol/performance/perf-push-metrics-expected.txt

@@ -22,7 +22,7 @@ title: test1
 	RecalcStyleCount
 	LayoutDuration
 	RecalcStyleDuration
-	CaptureSnapshotDuration
+	DevToolsCommandDuration
 	ScriptDuration
 	V8CompileDuration
 	TaskDuration
@@ -56,7 +56,7 @@ title: test1
 	RecalcStyleCount
 	LayoutDuration
 	RecalcStyleDuration
-	CaptureSnapshotDuration
+	DevToolsCommandDuration
 	ScriptDuration
 	V8CompileDuration
 	TaskDuration
@@ -90,7 +90,7 @@ title:
 	RecalcStyleCount
 	LayoutDuration
 	RecalcStyleDuration
-	CaptureSnapshotDuration
+	DevToolsCommandDuration
 	ScriptDuration
 	V8CompileDuration
 	TaskDuration