Using non-override time in InspectorPerformanceAgent.cpp.

Right now the InspectorPerformanceAgent returns incorrect performance metrics
(such as LayoutDuration, ScriptDuration, etc.) if there is an time override in
place. The InspectorPerformanceAgent needs to return real time elapsed.

Per offline discussion with Pavel(pfeldman@), the reason we don't expose the
non-override time API in the web platform (<blink>/platform/time.h) is that time
override is to abstract the web platform from the time. The web platform should
just deal with time and not know about whether the time is overridden. Exposing
the non-override time API in the very core part of blink will leak the override
aspect and hence compromising the whole design

BUG: 830033
Change-Id: If3140892ac60bc853ef5f98f7b478a98ae332806
Reviewed-on: https://chromium-review.googlesource.com/988833Reviewed-by: Kentaro Hara <haraken@chromium.org>
Reviewed-by: Pavel Feldman <pfeldman@chromium.org>
Commit-Queue: Johnny Ding <jnd@chromium.org>
Cr-Commit-Position: refs/heads/master@{#556012}

third_party/WebKit/LayoutTests/inspector-protocol/emulation/performance-return-real-time-expected.txt

+Tests that perf metrics return real time even if there is a virtual time override in place.
+Does real time advance? true.
+Does virtual time advance? false.
+Is script duration increased? true.
+

third_party/WebKit/LayoutTests/inspector-protocol/emulation/performance-return-real-time.js

+(async function(testRunner) {
+  let {page, session, dp} = await testRunner.startHTML(`
+    <script>
+      function f(x) { return x > 1 ? f(x-1) + x : 1; }
+      // Function returns true if the JavaScript time does advance during the
+      // computation.
+      function doesJavaScriptTimeAdvance() {
+        let event = new Event('test');
+        let rv = false;
+        addEventListener('test', () => {
+          start = Date.now();
+          for (let x = 0; x < 10000; x++) { f(1000); }
+          rv = Date.now() > start;
+        }, false);
+        dispatchEvent(event);
+        return rv;
+      }
+    </script>
+  `, 'Tests that perf metrics return real time even if there is a virtual time override in place.');
+
+  let v = await session.evaluate("doesJavaScriptTimeAdvance()");
+  testRunner.log(`Does real time advance? ${v}.`);
+
+  await dp.Performance.enable();
+  await dp.Emulation.setVirtualTimePolicy(
+      {policy: 'advance', initialVirtualTime: 1234567890});
+  let before = await getScriptDuration();
+  v = await session.evaluate("doesJavaScriptTimeAdvance()");
+  testRunner.log(`Does virtual time advance? ${v}.`);
+  let after = await getScriptDuration();
+  testRunner.log(`Is script duration increased? ${after > before}.`);
+
+  async function getScriptDuration() {
+    const {result:{metrics}} = await dp.Performance.getMetrics();
+    //testRunner.log(metrics);
+    const metric = metrics.find(metric => metric.name === "ScriptDuration");
+    return metric.value;
+  }
+
+  testRunner.completeTest();
+})

third_party/blink/renderer/core/inspector/DEPS

 include_rules = [
+    "+base/time/time_override.h",
     "+base/sampling_heap_profiler/sampling_heap_profiler.h",
     # for base::GetUniqueIdForProcess
     "+base/process/process_handle.h",

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

@@ -4,6 +4,9 @@
 
 #include "third_party/blink/renderer/core/inspector/inspector_performance_agent.h"
 
+#include <utility>
+
+#include "base/time/time_override.h"
 #include "third_party/blink/public/platform/platform.h"
 #include "third_party/blink/renderer/core/frame/local_frame.h"
 #include "third_party/blink/renderer/core/inspector/inspected_frames.h"
@@ -53,8 +56,10 @@ protocol::Response InspectorPerformanceAgent::enable() {
   state_->setBoolean(kPerformanceAgentEnabled, true);
   instrumenting_agents_->addInspectorPerformanceAgent(this);
   Platform::Current()->CurrentThread()->AddTaskTimeObserver(this);
-  task_start_time_ = TimeTicks();
-  script_start_time_ = TimeTicks();
+  layout_start_ticks_ = TimeTicks();
+  recalc_style_start_ticks_ = TimeTicks();
+  task_start_ticks_ = TimeTicks();
+  script_start_ticks_ = TimeTicks();
   return Response::OK();
 }
 
@@ -90,8 +95,8 @@ Response InspectorPerformanceAgent::getMetrics(
   std::unique_ptr<protocol::Array<protocol::Performance::Metric>> result =
       protocol::Array<protocol::Performance::Metric>::create();
 
-  TimeTicks now = CurrentTimeTicks();
-  AppendMetric(result.get(), "Timestamp", TimeTicksInSeconds(now));
+  AppendMetric(result.get(), "Timestamp",
+               TimeTicksInSeconds(CurrentTimeTicks()));
 
   // Renderer instance counters.
   for (size_t i = 0; i < ARRAY_SIZE(kInstanceCounterNames); ++i) {
@@ -101,6 +106,7 @@ Response InspectorPerformanceAgent::getMetrics(
   }
 
   // Page performance metrics.
+  TimeTicks now = base::subtle::TimeTicksNowIgnoringOverride();
   AppendMetric(result.get(), "LayoutCount", static_cast<double>(layout_count_));
   AppendMetric(result.get(), "RecalcStyleCount",
                static_cast<double>(recalc_style_count_));
@@ -108,12 +114,12 @@ Response InspectorPerformanceAgent::getMetrics(
   AppendMetric(result.get(), "RecalcStyleDuration",
                recalc_style_duration_.InSecondsF());
   TimeDelta script_duration = script_duration_;
-  if (!script_start_time_.is_null())
-    script_duration += now - script_start_time_;
+  if (!script_start_ticks_.is_null())
+    script_duration += now - script_start_ticks_;
   AppendMetric(result.get(), "ScriptDuration", script_duration.InSecondsF());
   TimeDelta task_duration = task_duration_;
-  if (!task_start_time_.is_null())
-    task_duration += now - task_start_time_;
+  if (!task_start_ticks_.is_null())
+    task_duration += now - task_start_ticks_;
   AppendMetric(result.get(), "TaskDuration", task_duration.InSecondsF());
 
   v8::HeapStatistics heap_statistics;
@@ -149,60 +155,67 @@ void InspectorPerformanceAgent::ConsoleTimeStamp(const String& title) {
   GetFrontend()->metrics(std::move(metrics), title);
 }
 
-void InspectorPerformanceAgent::Will(const probe::CallFunction& probe) {
+void InspectorPerformanceAgent::ScriptStarts() {
   if (!script_call_depth_++)
-    script_start_time_ = probe.CaptureStartTime();
+    script_start_ticks_ = base::subtle::TimeTicksNowIgnoringOverride();
 }
 
-void InspectorPerformanceAgent::Did(const probe::CallFunction& probe) {
+void InspectorPerformanceAgent::ScriptEnds() {
   if (--script_call_depth_)
     return;
-  script_duration_ += probe.Duration();
-  script_start_time_ = TimeTicks();
+  script_duration_ +=
+      base::subtle::TimeTicksNowIgnoringOverride() - script_start_ticks_;
+  script_start_ticks_ = TimeTicks();
+}
+
+void InspectorPerformanceAgent::Will(const probe::CallFunction& probe) {
+  ScriptStarts();
+}
+
+void InspectorPerformanceAgent::Did(const probe::CallFunction& probe) {
+  ScriptEnds();
 }
 
 void InspectorPerformanceAgent::Will(const probe::ExecuteScript& probe) {
-  if (!script_call_depth_++)
-    script_start_time_ = probe.CaptureStartTime();
+  ScriptStarts();
 }
 
 void InspectorPerformanceAgent::Did(const probe::ExecuteScript& probe) {
-  if (--script_call_depth_)
-    return;
-  script_duration_ += probe.Duration();
-  script_start_time_ = TimeTicks();
+  ScriptEnds();
 }
 
 void InspectorPerformanceAgent::Will(const probe::RecalculateStyle& probe) {
-  probe.CaptureStartTime();
+  recalc_style_start_ticks_ = base::subtle::TimeTicksNowIgnoringOverride();
 }
 
 void InspectorPerformanceAgent::Did(const probe::RecalculateStyle& probe) {
-  recalc_style_duration_ += probe.Duration();
+  recalc_style_duration_ +=
+      base::subtle::TimeTicksNowIgnoringOverride() - recalc_style_start_ticks_;
   recalc_style_count_++;
 }
 
 void InspectorPerformanceAgent::Will(const probe::UpdateLayout& probe) {
   if (!layout_depth_++)
-    probe.CaptureStartTime();
+    layout_start_ticks_ = base::subtle::TimeTicksNowIgnoringOverride();
 }
 
 void InspectorPerformanceAgent::Did(const probe::UpdateLayout& probe) {
   if (--layout_depth_)
     return;
-  layout_duration_ += probe.Duration();
+  layout_duration_ +=
+      base::subtle::TimeTicksNowIgnoringOverride() - layout_start_ticks_;
   layout_count_++;
 }
 
 void InspectorPerformanceAgent::WillProcessTask(double start_time) {
-  task_start_time_ = TimeTicksFromSeconds(start_time);
+  task_start_ticks_ = TimeTicksFromSeconds(start_time);
 }
 
 void InspectorPerformanceAgent::DidProcessTask(double start_time,
                                                double end_time) {
-  if (task_start_time_ == TimeTicksFromSeconds(start_time))
+  if (task_start_ticks_ == TimeTicksFromSeconds(start_time))
     task_duration_ += TimeDelta::FromSeconds(end_time - start_time);
-  task_start_time_ = TimeTicks();
+  task_start_ticks_ = TimeTicks();
 }
 
 void InspectorPerformanceAgent::Trace(blink::Visitor* visitor) {

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

@@ -5,6 +5,8 @@
 #ifndef THIRD_PARTY_BLINK_RENDERER_CORE_INSPECTOR_INSPECTOR_PERFORMANCE_AGENT_H_
 #define THIRD_PARTY_BLINK_RENDERER_CORE_INSPECTOR_INSPECTOR_PERFORMANCE_AGENT_H_
 
+#include <memory>
+
 #include "base/macros.h"
 #include "third_party/blink/renderer/core/core_export.h"
 #include "third_party/blink/renderer/core/inspector/inspector_base_agent.h"
@@ -59,16 +61,20 @@ class CORE_EXPORT InspectorPerformanceAgent final
   void DidProcessTask(double start_time, double end_time) override;
 
  private:
-  InspectorPerformanceAgent(InspectedFrames*);
+  explicit InspectorPerformanceAgent(InspectedFrames*);
+  void ScriptStarts();
+  void ScriptEnds();
 
   Member<InspectedFrames> inspected_frames_;
   bool enabled_ = false;
   TimeDelta layout_duration_;
+  TimeTicks layout_start_ticks_;
   TimeDelta recalc_style_duration_;
+  TimeTicks recalc_style_start_ticks_;
   TimeDelta script_duration_;
-  TimeTicks script_start_time_;
+  TimeTicks script_start_ticks_;
   TimeDelta task_duration_;
-  TimeTicks task_start_time_;
+  TimeTicks task_start_ticks_;
   unsigned long long layout_count_ = 0;
   unsigned long long recalc_style_count_ = 0;
   int script_call_depth_ = 0;

third_party/blink/tools/audit_non_blink_usage.py

@@ -167,11 +167,17 @@ _CONFIG = [
         ],
     },
     {
-        'paths': ['third_party/blink/renderer/core/inspector/InspectorMemoryAgent.cpp'],
+        'paths': ['third_party/blink/renderer/core/inspector/inspector_memory_agent.cc'],
         'allowed': [
             'base::SamplingHeapProfiler',
         ],
     },
+    {
+        'paths': ['third_party/blink/renderer/core/inspector/inspector_performance_agent.cc'],
+        'allowed': [
+            'base::subtle::TimeTicksNowIgnoringOverride',
+        ],
+    },
     {
         'paths': [
             'third_party/blink/renderer/modules/device_orientation/',