Commit d2ca7833 authored by Johnny(Jianning) Ding's avatar Johnny(Jianning) Ding Committed by Commit Bot

Reland "Using non-override time in InspectorPerformanceAgent.cpp."

This is a reland of 79b28587

Original change's description:
> 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/988833
> Reviewed-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}

Change-Id: I6f04a582d63376b3d6eeb80e27615c455dba4a61
Reviewed-on: https://chromium-review.googlesource.com/1045566
Commit-Queue: Johnny Ding <jnd@chromium.org>
Reviewed-by: default avatarPavel Feldman <pfeldman@chromium.org>
Reviewed-by: default avatarKentaro Hara <haraken@chromium.org>
Cr-Commit-Position: refs/heads/master@{#557267}
parent 1cbdc222
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.
(async function(testRunner) {
let {page, session, dp} = await testRunner.startHTML(`
<script>
// Function returns true if the JavaScript time does advance during the
// computation.
function doesJavaScriptTimeAdvance() {
let event = new Event('test');
let start = Date.now();
addEventListener('test', () => {
let f = (x) => x > 1 ? f(x-1) + x : 1;
for (let x = 0; x < 100; x++) { f(1000); }
}, false);
dispatchEvent(event);
return Date.now() > start;
}
</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();
})
include_rules = [ include_rules = [
"+base/time/time_override.h",
"+base/sampling_heap_profiler/sampling_heap_profiler.h", "+base/sampling_heap_profiler/sampling_heap_profiler.h",
# for base::GetUniqueIdForProcess # for base::GetUniqueIdForProcess
"+base/process/process_handle.h", "+base/process/process_handle.h",
......
...@@ -4,6 +4,9 @@ ...@@ -4,6 +4,9 @@
#include "third_party/blink/renderer/core/inspector/inspector_performance_agent.h" #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/public/platform/platform.h"
#include "third_party/blink/renderer/core/frame/local_frame.h" #include "third_party/blink/renderer/core/frame/local_frame.h"
#include "third_party/blink/renderer/core/inspector/inspected_frames.h" #include "third_party/blink/renderer/core/inspector/inspected_frames.h"
...@@ -53,8 +56,10 @@ protocol::Response InspectorPerformanceAgent::enable() { ...@@ -53,8 +56,10 @@ protocol::Response InspectorPerformanceAgent::enable() {
state_->setBoolean(kPerformanceAgentEnabled, true); state_->setBoolean(kPerformanceAgentEnabled, true);
instrumenting_agents_->addInspectorPerformanceAgent(this); instrumenting_agents_->addInspectorPerformanceAgent(this);
Platform::Current()->CurrentThread()->AddTaskTimeObserver(this); Platform::Current()->CurrentThread()->AddTaskTimeObserver(this);
task_start_time_ = TimeTicks(); layout_start_ticks_ = TimeTicks();
script_start_time_ = TimeTicks(); recalc_style_start_ticks_ = TimeTicks();
task_start_ticks_ = TimeTicks();
script_start_ticks_ = TimeTicks();
return Response::OK(); return Response::OK();
} }
...@@ -90,8 +95,8 @@ Response InspectorPerformanceAgent::getMetrics( ...@@ -90,8 +95,8 @@ Response InspectorPerformanceAgent::getMetrics(
std::unique_ptr<protocol::Array<protocol::Performance::Metric>> result = std::unique_ptr<protocol::Array<protocol::Performance::Metric>> result =
protocol::Array<protocol::Performance::Metric>::create(); protocol::Array<protocol::Performance::Metric>::create();
TimeTicks now = CurrentTimeTicks(); AppendMetric(result.get(), "Timestamp",
AppendMetric(result.get(), "Timestamp", TimeTicksInSeconds(now)); TimeTicksInSeconds(CurrentTimeTicks()));
// Renderer instance counters. // Renderer instance counters.
for (size_t i = 0; i < ARRAY_SIZE(kInstanceCounterNames); ++i) { for (size_t i = 0; i < ARRAY_SIZE(kInstanceCounterNames); ++i) {
...@@ -101,6 +106,7 @@ Response InspectorPerformanceAgent::getMetrics( ...@@ -101,6 +106,7 @@ Response InspectorPerformanceAgent::getMetrics(
} }
// Page performance metrics. // Page performance metrics.
TimeTicks now = base::subtle::TimeTicksNowIgnoringOverride();
AppendMetric(result.get(), "LayoutCount", static_cast<double>(layout_count_)); AppendMetric(result.get(), "LayoutCount", static_cast<double>(layout_count_));
AppendMetric(result.get(), "RecalcStyleCount", AppendMetric(result.get(), "RecalcStyleCount",
static_cast<double>(recalc_style_count_)); static_cast<double>(recalc_style_count_));
...@@ -108,12 +114,12 @@ Response InspectorPerformanceAgent::getMetrics( ...@@ -108,12 +114,12 @@ Response InspectorPerformanceAgent::getMetrics(
AppendMetric(result.get(), "RecalcStyleDuration", AppendMetric(result.get(), "RecalcStyleDuration",
recalc_style_duration_.InSecondsF()); recalc_style_duration_.InSecondsF());
TimeDelta script_duration = script_duration_; TimeDelta script_duration = script_duration_;
if (!script_start_time_.is_null()) if (!script_start_ticks_.is_null())
script_duration += now - script_start_time_; script_duration += now - script_start_ticks_;
AppendMetric(result.get(), "ScriptDuration", script_duration.InSecondsF()); AppendMetric(result.get(), "ScriptDuration", script_duration.InSecondsF());
TimeDelta task_duration = task_duration_; TimeDelta task_duration = task_duration_;
if (!task_start_time_.is_null()) if (!task_start_ticks_.is_null())
task_duration += now - task_start_time_; task_duration += now - task_start_ticks_;
AppendMetric(result.get(), "TaskDuration", task_duration.InSecondsF()); AppendMetric(result.get(), "TaskDuration", task_duration.InSecondsF());
v8::HeapStatistics heap_statistics; v8::HeapStatistics heap_statistics;
...@@ -149,60 +155,67 @@ void InspectorPerformanceAgent::ConsoleTimeStamp(const String& title) { ...@@ -149,60 +155,67 @@ void InspectorPerformanceAgent::ConsoleTimeStamp(const String& title) {
GetFrontend()->metrics(std::move(metrics), title); GetFrontend()->metrics(std::move(metrics), title);
} }
void InspectorPerformanceAgent::Will(const probe::CallFunction& probe) { void InspectorPerformanceAgent::ScriptStarts() {
if (!script_call_depth_++) 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_) if (--script_call_depth_)
return; return;
script_duration_ += probe.Duration(); script_duration_ +=
script_start_time_ = TimeTicks(); 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) { void InspectorPerformanceAgent::Will(const probe::ExecuteScript& probe) {
if (!script_call_depth_++) ScriptStarts();
script_start_time_ = probe.CaptureStartTime();
} }
void InspectorPerformanceAgent::Did(const probe::ExecuteScript& probe) { void InspectorPerformanceAgent::Did(const probe::ExecuteScript& probe) {
if (--script_call_depth_) ScriptEnds();
return;
script_duration_ += probe.Duration();
script_start_time_ = TimeTicks();
} }
void InspectorPerformanceAgent::Will(const probe::RecalculateStyle& probe) { void InspectorPerformanceAgent::Will(const probe::RecalculateStyle& probe) {
probe.CaptureStartTime(); recalc_style_start_ticks_ = base::subtle::TimeTicksNowIgnoringOverride();
} }
void InspectorPerformanceAgent::Did(const probe::RecalculateStyle& probe) { 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_++; recalc_style_count_++;
} }
void InspectorPerformanceAgent::Will(const probe::UpdateLayout& probe) { void InspectorPerformanceAgent::Will(const probe::UpdateLayout& probe) {
if (!layout_depth_++) if (!layout_depth_++)
probe.CaptureStartTime(); layout_start_ticks_ = base::subtle::TimeTicksNowIgnoringOverride();
} }
void InspectorPerformanceAgent::Did(const probe::UpdateLayout& probe) { void InspectorPerformanceAgent::Did(const probe::UpdateLayout& probe) {
if (--layout_depth_) if (--layout_depth_)
return; return;
layout_duration_ += probe.Duration(); layout_duration_ +=
base::subtle::TimeTicksNowIgnoringOverride() - layout_start_ticks_;
layout_count_++; layout_count_++;
} }
void InspectorPerformanceAgent::WillProcessTask(double start_time) { void InspectorPerformanceAgent::WillProcessTask(double start_time) {
task_start_time_ = TimeTicksFromSeconds(start_time); task_start_ticks_ = TimeTicksFromSeconds(start_time);
} }
void InspectorPerformanceAgent::DidProcessTask(double start_time, void InspectorPerformanceAgent::DidProcessTask(double start_time,
double end_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_duration_ += TimeDelta::FromSeconds(end_time - start_time);
task_start_time_ = TimeTicks(); task_start_ticks_ = TimeTicks();
} }
void InspectorPerformanceAgent::Trace(blink::Visitor* visitor) { void InspectorPerformanceAgent::Trace(blink::Visitor* visitor) {
......
...@@ -5,6 +5,8 @@ ...@@ -5,6 +5,8 @@
#ifndef THIRD_PARTY_BLINK_RENDERER_CORE_INSPECTOR_INSPECTOR_PERFORMANCE_AGENT_H_ #ifndef THIRD_PARTY_BLINK_RENDERER_CORE_INSPECTOR_INSPECTOR_PERFORMANCE_AGENT_H_
#define 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 "base/macros.h"
#include "third_party/blink/renderer/core/core_export.h" #include "third_party/blink/renderer/core/core_export.h"
#include "third_party/blink/renderer/core/inspector/inspector_base_agent.h" #include "third_party/blink/renderer/core/inspector/inspector_base_agent.h"
...@@ -59,16 +61,20 @@ class CORE_EXPORT InspectorPerformanceAgent final ...@@ -59,16 +61,20 @@ class CORE_EXPORT InspectorPerformanceAgent final
void DidProcessTask(double start_time, double end_time) override; void DidProcessTask(double start_time, double end_time) override;
private: private:
InspectorPerformanceAgent(InspectedFrames*); explicit InspectorPerformanceAgent(InspectedFrames*);
void ScriptStarts();
void ScriptEnds();
Member<InspectedFrames> inspected_frames_; Member<InspectedFrames> inspected_frames_;
bool enabled_ = false; bool enabled_ = false;
TimeDelta layout_duration_; TimeDelta layout_duration_;
TimeTicks layout_start_ticks_;
TimeDelta recalc_style_duration_; TimeDelta recalc_style_duration_;
TimeTicks recalc_style_start_ticks_;
TimeDelta script_duration_; TimeDelta script_duration_;
TimeTicks script_start_time_; TimeTicks script_start_ticks_;
TimeDelta task_duration_; TimeDelta task_duration_;
TimeTicks task_start_time_; TimeTicks task_start_ticks_;
unsigned long long layout_count_ = 0; unsigned long long layout_count_ = 0;
unsigned long long recalc_style_count_ = 0; unsigned long long recalc_style_count_ = 0;
int script_call_depth_ = 0; int script_call_depth_ = 0;
......
...@@ -205,11 +205,17 @@ _CONFIG = [ ...@@ -205,11 +205,17 @@ _CONFIG = [
], ],
}, },
{ {
'paths': ['third_party/blink/renderer/core/inspector/InspectorMemoryAgent.cpp'], 'paths': ['third_party/blink/renderer/core/inspector/inspector_memory_agent.cc'],
'allowed': [ 'allowed': [
'base::SamplingHeapProfiler', 'base::SamplingHeapProfiler',
], ],
}, },
{
'paths': ['third_party/blink/renderer/core/inspector/inspector_performance_agent.cc'],
'allowed': [
'base::subtle::TimeTicksNowIgnoringOverride',
],
},
{ {
'paths': [ 'paths': [
'third_party/blink/renderer/modules/device_orientation/', 'third_party/blink/renderer/modules/device_orientation/',
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment