0ff8205261
Change the unittest runner to no longer uncondtionally set up a default platform in the "environment", but to instead make platform set-up part of the "mixin" framework for test fixtures. Requires modifying some tests that expect the platform to be available, and all flag implications resolved, before the mixin constructors run. We still keep the environment for setting up the process for cppgc. This process setup can only be done once per process, so it can no longer use the platform -- that's ok though, the page allocator used by cppgc's process initialisation doesn't have to be the same as the platform's so we can just pass in a separate new one. Change-Id: Ic8ccf39722e8212962c5bba87350c4b304388a7c Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3571886 Reviewed-by: Michael Lippautz <mlippautz@chromium.org> Auto-Submit: Leszek Swirski <leszeks@chromium.org> Commit-Queue: Leszek Swirski <leszeks@chromium.org> Cr-Commit-Position: refs/heads/main@{#79820}
652 lines
21 KiB
C++
652 lines
21 KiB
C++
// Copyright 2021 the V8 project authors. All rights reserved.
|
|
// Use of this source code is governed by a BSD-style license that can be
|
|
// found in the LICENSE file.
|
|
|
|
#include "src/logging/runtime-call-stats.h"
|
|
|
|
#include <atomic>
|
|
|
|
#include "include/v8-template.h"
|
|
#include "src/api/api-inl.h"
|
|
#include "src/base/atomic-utils.h"
|
|
#include "src/base/platform/time.h"
|
|
#include "src/flags/flags.h"
|
|
#include "src/handles/handles-inl.h"
|
|
#include "src/logging/counters.h"
|
|
#include "src/objects/objects-inl.h"
|
|
#include "src/tracing/tracing-category-observer.h"
|
|
#include "test/unittests/test-utils.h"
|
|
#include "testing/gtest/include/gtest/gtest.h"
|
|
|
|
namespace v8 {
|
|
namespace internal {
|
|
|
|
namespace {
|
|
|
|
static std::atomic<base::TimeTicks> runtime_call_stats_test_time_ =
|
|
base::TimeTicks();
|
|
// Time source used for the RuntimeCallTimer during tests. We cannot rely on
|
|
// the native timer since it's too unpredictable on the build bots.
|
|
static base::TimeTicks RuntimeCallStatsTestNow() {
|
|
return runtime_call_stats_test_time_;
|
|
}
|
|
|
|
class RuntimeCallStatsTest : public TestWithNativeContext {
|
|
public:
|
|
RuntimeCallStatsTest() {
|
|
TracingFlags::runtime_stats.store(
|
|
v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE,
|
|
std::memory_order_relaxed);
|
|
// We need to set {time_} to a non-zero value since it would otherwise
|
|
// cause runtime call timers to think they are uninitialized.
|
|
Sleep(1);
|
|
stats()->Reset();
|
|
}
|
|
|
|
~RuntimeCallStatsTest() override {
|
|
// Disable RuntimeCallStats before tearing down the isolate to prevent
|
|
// printing the tests table. Comment the following line for debugging
|
|
// purposes.
|
|
TracingFlags::runtime_stats.store(0, std::memory_order_relaxed);
|
|
}
|
|
|
|
static void SetUpTestSuite() {
|
|
TestWithIsolate::SetUpTestSuite();
|
|
// Use a custom time source to precisly emulate system time.
|
|
RuntimeCallTimer::Now = &RuntimeCallStatsTestNow;
|
|
}
|
|
|
|
static void TearDownTestSuite() {
|
|
TestWithIsolate::TearDownTestSuite();
|
|
// Restore the original time source.
|
|
RuntimeCallTimer::Now = &base::TimeTicks::Now;
|
|
}
|
|
|
|
RuntimeCallStats* stats() {
|
|
return isolate()->counters()->runtime_call_stats();
|
|
}
|
|
|
|
RuntimeCallCounterId counter_id() {
|
|
return RuntimeCallCounterId::kTestCounter1;
|
|
}
|
|
|
|
RuntimeCallCounterId counter_id2() {
|
|
return RuntimeCallCounterId::kTestCounter2;
|
|
}
|
|
|
|
RuntimeCallCounterId counter_id3() {
|
|
return RuntimeCallCounterId::kTestCounter3;
|
|
}
|
|
|
|
RuntimeCallCounter* js_counter() {
|
|
return stats()->GetCounter(RuntimeCallCounterId::kJS_Execution);
|
|
}
|
|
RuntimeCallCounter* counter() { return stats()->GetCounter(counter_id()); }
|
|
RuntimeCallCounter* counter2() { return stats()->GetCounter(counter_id2()); }
|
|
RuntimeCallCounter* counter3() { return stats()->GetCounter(counter_id3()); }
|
|
|
|
void Sleep(int64_t microseconds) {
|
|
base::TimeDelta delta = base::TimeDelta::FromMicroseconds(microseconds);
|
|
time_ += delta;
|
|
runtime_call_stats_test_time_ =
|
|
base::TimeTicks::FromInternalValue(time_.InMicroseconds());
|
|
}
|
|
|
|
private:
|
|
base::TimeDelta time_;
|
|
};
|
|
|
|
// Temporarily use the native time to modify the test time.
|
|
class V8_NODISCARD ElapsedTimeScope {
|
|
public:
|
|
explicit ElapsedTimeScope(RuntimeCallStatsTest* test) : test_(test) {
|
|
timer_.Start();
|
|
}
|
|
~ElapsedTimeScope() { test_->Sleep(timer_.Elapsed().InMicroseconds()); }
|
|
|
|
private:
|
|
base::ElapsedTimer timer_;
|
|
RuntimeCallStatsTest* test_;
|
|
};
|
|
|
|
// Temporarily use the default time source.
|
|
class V8_NODISCARD NativeTimeScope {
|
|
public:
|
|
NativeTimeScope() {
|
|
CHECK_EQ(RuntimeCallTimer::Now, &RuntimeCallStatsTestNow);
|
|
RuntimeCallTimer::Now = &base::TimeTicks::Now;
|
|
}
|
|
~NativeTimeScope() {
|
|
CHECK_EQ(RuntimeCallTimer::Now, &base::TimeTicks::Now);
|
|
RuntimeCallTimer::Now = &RuntimeCallStatsTestNow;
|
|
}
|
|
};
|
|
|
|
} // namespace
|
|
|
|
TEST_F(RuntimeCallStatsTest, RuntimeCallTimer) {
|
|
RuntimeCallTimer timer;
|
|
|
|
Sleep(50);
|
|
stats()->Enter(&timer, counter_id());
|
|
EXPECT_EQ(counter(), timer.counter());
|
|
EXPECT_EQ(nullptr, timer.parent());
|
|
EXPECT_TRUE(timer.IsStarted());
|
|
EXPECT_EQ(&timer, stats()->current_timer());
|
|
|
|
Sleep(100);
|
|
|
|
stats()->Leave(&timer);
|
|
Sleep(50);
|
|
EXPECT_FALSE(timer.IsStarted());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, RuntimeCallTimerSubTimer) {
|
|
RuntimeCallTimer timer;
|
|
RuntimeCallTimer timer2;
|
|
|
|
stats()->Enter(&timer, counter_id());
|
|
EXPECT_TRUE(timer.IsStarted());
|
|
EXPECT_FALSE(timer2.IsStarted());
|
|
EXPECT_EQ(counter(), timer.counter());
|
|
EXPECT_EQ(nullptr, timer.parent());
|
|
EXPECT_EQ(&timer, stats()->current_timer());
|
|
|
|
Sleep(50);
|
|
|
|
stats()->Enter(&timer2, counter_id2());
|
|
// timer 1 is paused, while timer 2 is active.
|
|
EXPECT_TRUE(timer2.IsStarted());
|
|
EXPECT_EQ(counter(), timer.counter());
|
|
EXPECT_EQ(counter2(), timer2.counter());
|
|
EXPECT_EQ(nullptr, timer.parent());
|
|
EXPECT_EQ(&timer, timer2.parent());
|
|
EXPECT_EQ(&timer2, stats()->current_timer());
|
|
|
|
Sleep(100);
|
|
stats()->Leave(&timer2);
|
|
|
|
// The subtimer subtracts its time from the parent timer.
|
|
EXPECT_TRUE(timer.IsStarted());
|
|
EXPECT_FALSE(timer2.IsStarted());
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
EXPECT_EQ(0, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter2()->time().InMicroseconds());
|
|
EXPECT_EQ(&timer, stats()->current_timer());
|
|
|
|
Sleep(100);
|
|
|
|
stats()->Leave(&timer);
|
|
EXPECT_FALSE(timer.IsStarted());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
EXPECT_EQ(150, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter2()->time().InMicroseconds());
|
|
EXPECT_EQ(nullptr, stats()->current_timer());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, RuntimeCallTimerRecursive) {
|
|
RuntimeCallTimer timer;
|
|
RuntimeCallTimer timer2;
|
|
|
|
stats()->Enter(&timer, counter_id());
|
|
EXPECT_EQ(counter(), timer.counter());
|
|
EXPECT_EQ(nullptr, timer.parent());
|
|
EXPECT_TRUE(timer.IsStarted());
|
|
EXPECT_EQ(&timer, stats()->current_timer());
|
|
|
|
stats()->Enter(&timer2, counter_id());
|
|
EXPECT_EQ(counter(), timer2.counter());
|
|
EXPECT_EQ(nullptr, timer.parent());
|
|
EXPECT_EQ(&timer, timer2.parent());
|
|
EXPECT_TRUE(timer2.IsStarted());
|
|
EXPECT_EQ(&timer2, stats()->current_timer());
|
|
|
|
Sleep(50);
|
|
|
|
stats()->Leave(&timer2);
|
|
EXPECT_EQ(nullptr, timer.parent());
|
|
EXPECT_FALSE(timer2.IsStarted());
|
|
EXPECT_TRUE(timer.IsStarted());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(50, counter()->time().InMicroseconds());
|
|
|
|
Sleep(100);
|
|
|
|
stats()->Leave(&timer);
|
|
EXPECT_FALSE(timer.IsStarted());
|
|
EXPECT_EQ(2, counter()->count());
|
|
EXPECT_EQ(150, counter()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScope) {
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(50);
|
|
}
|
|
Sleep(100);
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(50, counter()->time().InMicroseconds());
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(50);
|
|
}
|
|
EXPECT_EQ(2, counter()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) {
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(50);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter()->time().InMicroseconds());
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(50);
|
|
}
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(50, counter()->time().InMicroseconds());
|
|
}
|
|
EXPECT_EQ(2, counter()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, RenameTimer) {
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(50);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(0, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, counter2()->time().InMicroseconds());
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(100);
|
|
}
|
|
CHANGE_CURRENT_RUNTIME_COUNTER(stats(),
|
|
RuntimeCallCounterId::kTestCounter2);
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, counter2()->time().InMicroseconds());
|
|
}
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(50, counter2()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, BasicPrintAndSnapshot) {
|
|
std::ostringstream out;
|
|
stats()->Print(out);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(0, counter3()->count());
|
|
EXPECT_EQ(0, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, counter2()->time().InMicroseconds());
|
|
EXPECT_EQ(0, counter3()->time().InMicroseconds());
|
|
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(50);
|
|
stats()->Print(out);
|
|
}
|
|
stats()->Print(out);
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(0, counter3()->count());
|
|
EXPECT_EQ(50, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, counter2()->time().InMicroseconds());
|
|
EXPECT_EQ(0, counter3()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, PrintAndSnapshot) {
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(100);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter()->time().InMicroseconds());
|
|
{
|
|
RCS_SCOPE(stats(), counter_id2());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(0, counter2()->time().InMicroseconds());
|
|
Sleep(50);
|
|
|
|
// This calls Snapshot on the current active timer and sychronizes and
|
|
// commits the whole timer stack.
|
|
std::ostringstream out;
|
|
stats()->Print(out);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(50, counter2()->time().InMicroseconds());
|
|
// Calling Print several times shouldn't have a (big) impact on the
|
|
// measured times.
|
|
stats()->Print(out);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(50, counter2()->time().InMicroseconds());
|
|
|
|
Sleep(50);
|
|
stats()->Print(out);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter2()->time().InMicroseconds());
|
|
Sleep(50);
|
|
}
|
|
Sleep(50);
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(150, counter2()->time().InMicroseconds());
|
|
Sleep(50);
|
|
}
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
EXPECT_EQ(200, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(150, counter2()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, NestedScopes) {
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(100);
|
|
{
|
|
RCS_SCOPE(stats(), counter_id2());
|
|
Sleep(100);
|
|
{
|
|
RCS_SCOPE(stats(), counter_id3());
|
|
Sleep(50);
|
|
}
|
|
Sleep(50);
|
|
{
|
|
RCS_SCOPE(stats(), counter_id3());
|
|
Sleep(50);
|
|
}
|
|
Sleep(50);
|
|
}
|
|
Sleep(100);
|
|
{
|
|
RCS_SCOPE(stats(), counter_id2());
|
|
Sleep(100);
|
|
}
|
|
Sleep(50);
|
|
}
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(2, counter2()->count());
|
|
EXPECT_EQ(2, counter3()->count());
|
|
EXPECT_EQ(250, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(300, counter2()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter3()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, BasicJavaScript) {
|
|
RuntimeCallCounter* counter =
|
|
stats()->GetCounter(RuntimeCallCounterId::kJS_Execution);
|
|
EXPECT_EQ(0, counter->count());
|
|
EXPECT_EQ(0, counter->time().InMicroseconds());
|
|
|
|
{
|
|
NativeTimeScope native_timer_scope;
|
|
RunJS("function f() { return 1; };");
|
|
}
|
|
EXPECT_EQ(1, counter->count());
|
|
int64_t time = counter->time().InMicroseconds();
|
|
EXPECT_LT(0, time);
|
|
|
|
{
|
|
NativeTimeScope native_timer_scope;
|
|
RunJS("f();");
|
|
}
|
|
EXPECT_EQ(2, counter->count());
|
|
EXPECT_LE(time, counter->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, FunctionLengthGetter) {
|
|
RuntimeCallCounter* getter_counter =
|
|
stats()->GetCounter(RuntimeCallCounterId::kFunctionLengthGetter);
|
|
EXPECT_EQ(0, getter_counter->count());
|
|
EXPECT_EQ(0, js_counter()->count());
|
|
EXPECT_EQ(0, getter_counter->time().InMicroseconds());
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
|
|
{
|
|
NativeTimeScope native_timer_scope;
|
|
RunJS("function f(array) { return array.length; };");
|
|
}
|
|
EXPECT_EQ(0, getter_counter->count());
|
|
EXPECT_EQ(1, js_counter()->count());
|
|
EXPECT_EQ(0, getter_counter->time().InMicroseconds());
|
|
int64_t js_time = js_counter()->time().InMicroseconds();
|
|
EXPECT_LT(0, js_time);
|
|
|
|
{
|
|
NativeTimeScope native_timer_scope;
|
|
RunJS("f.length;");
|
|
}
|
|
EXPECT_EQ(1, getter_counter->count());
|
|
EXPECT_EQ(2, js_counter()->count());
|
|
EXPECT_LE(0, getter_counter->time().InMicroseconds());
|
|
EXPECT_LE(js_time, js_counter()->time().InMicroseconds());
|
|
|
|
{
|
|
NativeTimeScope native_timer_scope;
|
|
RunJS("for (let i = 0; i < 50; i++) { f.length };");
|
|
}
|
|
EXPECT_EQ(51, getter_counter->count());
|
|
EXPECT_EQ(3, js_counter()->count());
|
|
|
|
{
|
|
NativeTimeScope native_timer_scope;
|
|
RunJS("for (let i = 0; i < 1000; i++) { f.length; };");
|
|
}
|
|
EXPECT_EQ(1051, getter_counter->count());
|
|
EXPECT_EQ(4, js_counter()->count());
|
|
}
|
|
|
|
namespace {
|
|
static RuntimeCallStatsTest* current_test;
|
|
static const int kCustomCallbackTime = 1234;
|
|
static void CustomCallback(const v8::FunctionCallbackInfo<v8::Value>& info) {
|
|
RCS_SCOPE(current_test->stats(), current_test->counter_id2());
|
|
current_test->Sleep(kCustomCallbackTime);
|
|
}
|
|
} // namespace
|
|
|
|
TEST_F(RuntimeCallStatsTest, CallbackFunction) {
|
|
FLAG_allow_natives_syntax = true;
|
|
FLAG_incremental_marking = false;
|
|
|
|
RuntimeCallCounter* callback_counter =
|
|
stats()->GetCounter(RuntimeCallCounterId::kFunctionCallback);
|
|
|
|
current_test = this;
|
|
// Set up a function template with a custom callback.
|
|
v8::Isolate* isolate = v8_isolate();
|
|
v8::HandleScope scope(isolate);
|
|
|
|
v8::Local<v8::ObjectTemplate> object_template =
|
|
v8::ObjectTemplate::New(isolate);
|
|
object_template->Set(isolate, "callback",
|
|
v8::FunctionTemplate::New(isolate, CustomCallback));
|
|
v8::Local<v8::Object> object =
|
|
object_template->NewInstance(v8_context()).ToLocalChecked();
|
|
SetGlobalProperty("custom_object", object);
|
|
|
|
EXPECT_EQ(0, js_counter()->count());
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, callback_counter->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(100);
|
|
RunJS("custom_object.callback();");
|
|
}
|
|
EXPECT_EQ(1, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(1, callback_counter->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
// Given that no native timers are used, only the two scopes explitly
|
|
// mentioned above will track the time.
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime, counter2()->time().InMicroseconds());
|
|
|
|
RunJS("for (let i = 0; i < 9; i++) { custom_object.callback(); };");
|
|
EXPECT_EQ(2, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(10, callback_counter->count());
|
|
EXPECT_EQ(10, counter2()->count());
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime * 10, counter2()->time().InMicroseconds());
|
|
|
|
RunJS("for (let i = 0; i < 4000; i++) { custom_object.callback(); };");
|
|
EXPECT_EQ(3, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(4010, callback_counter->count());
|
|
EXPECT_EQ(4010, counter2()->count());
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime * 4010, counter2()->time().InMicroseconds());
|
|
|
|
// Check that the FunctionCallback tracing also works properly
|
|
// when the `callback` is called from optimized code.
|
|
RunJS(
|
|
"function wrap(o) { return o.callback(); };\n"
|
|
"%PrepareFunctionForOptimization(wrap);\n"
|
|
"wrap(custom_object);\n"
|
|
"wrap(custom_object);\n"
|
|
"%OptimizeFunctionOnNextCall(wrap);\n"
|
|
"wrap(custom_object);\n");
|
|
EXPECT_EQ(4, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(4013, callback_counter->count());
|
|
EXPECT_EQ(4013, counter2()->count());
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime * 4013, counter2()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, ApiGetter) {
|
|
FLAG_allow_natives_syntax = true;
|
|
FLAG_incremental_marking = false;
|
|
|
|
RuntimeCallCounter* callback_counter =
|
|
stats()->GetCounter(RuntimeCallCounterId::kFunctionCallback);
|
|
current_test = this;
|
|
// Set up a function template with an api accessor.
|
|
v8::Isolate* isolate = v8_isolate();
|
|
v8::HandleScope scope(isolate);
|
|
|
|
v8::Local<v8::ObjectTemplate> object_template =
|
|
v8::ObjectTemplate::New(isolate);
|
|
object_template->SetAccessorProperty(
|
|
NewString("apiGetter"),
|
|
v8::FunctionTemplate::New(isolate, CustomCallback));
|
|
v8::Local<v8::Object> object =
|
|
object_template->NewInstance(v8_context()).ToLocalChecked();
|
|
SetGlobalProperty("custom_object", object);
|
|
|
|
// TODO(cbruni): Check api accessor timer (one above the custom callback).
|
|
EXPECT_EQ(0, js_counter()->count());
|
|
EXPECT_EQ(0, counter()->count());
|
|
EXPECT_EQ(0, callback_counter->count());
|
|
EXPECT_EQ(0, counter2()->count());
|
|
|
|
{
|
|
RCS_SCOPE(stats(), counter_id());
|
|
Sleep(100);
|
|
RunJS("custom_object.apiGetter;");
|
|
}
|
|
|
|
EXPECT_EQ(1, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(1, callback_counter->count());
|
|
EXPECT_EQ(1, counter2()->count());
|
|
// Given that no native timers are used, only the two scopes explitly
|
|
// mentioned above will track the time.
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime, counter2()->time().InMicroseconds());
|
|
|
|
RunJS("for (let i = 0; i < 9; i++) { custom_object.apiGetter };");
|
|
|
|
EXPECT_EQ(2, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(10, callback_counter->count());
|
|
EXPECT_EQ(10, counter2()->count());
|
|
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime * 10, counter2()->time().InMicroseconds());
|
|
|
|
RunJS("for (let i = 0; i < 4000; i++) { custom_object.apiGetter };");
|
|
|
|
EXPECT_EQ(3, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(4010, callback_counter->count());
|
|
EXPECT_EQ(4010, counter2()->count());
|
|
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime * 4010, counter2()->time().InMicroseconds());
|
|
|
|
// Check that the FunctionCallback tracing also works properly
|
|
// when the `apiGetter` is called from optimized code.
|
|
RunJS(
|
|
"function wrap(o) { return o.apiGetter; };\n"
|
|
"%PrepareFunctionForOptimization(wrap);\n"
|
|
"wrap(custom_object);\n"
|
|
"wrap(custom_object);\n"
|
|
"%OptimizeFunctionOnNextCall(wrap);\n"
|
|
"wrap(custom_object);\n");
|
|
|
|
EXPECT_EQ(4, js_counter()->count());
|
|
EXPECT_EQ(1, counter()->count());
|
|
EXPECT_EQ(4013, callback_counter->count());
|
|
EXPECT_EQ(4013, counter2()->count());
|
|
|
|
EXPECT_EQ(0, js_counter()->time().InMicroseconds());
|
|
EXPECT_EQ(100, counter()->time().InMicroseconds());
|
|
EXPECT_EQ(0, callback_counter->time().InMicroseconds());
|
|
EXPECT_EQ(kCustomCallbackTime * 4013, counter2()->time().InMicroseconds());
|
|
}
|
|
|
|
TEST_F(RuntimeCallStatsTest, GarbageCollection) {
|
|
if (FLAG_stress_incremental_marking) return;
|
|
FLAG_expose_gc = true;
|
|
// Disable concurrent GC threads because otherwise they may continue
|
|
// running after this test completes and race with is_runtime_stats_enabled()
|
|
// updates.
|
|
FLAG_single_threaded_gc = true;
|
|
|
|
FlagList::EnforceFlagImplications();
|
|
v8::Isolate* isolate = v8_isolate();
|
|
RunJS(
|
|
"let root = [];"
|
|
"for (let i = 0; i < 10; i++) root.push((new Array(1000)).fill(0));"
|
|
"root.push((new Array(1000000)).fill(0));"
|
|
"((new Array(1000000)).fill(0));");
|
|
isolate->RequestGarbageCollectionForTesting(
|
|
v8::Isolate::kFullGarbageCollection);
|
|
isolate->RequestGarbageCollectionForTesting(
|
|
v8::Isolate::kFullGarbageCollection);
|
|
}
|
|
|
|
} // namespace internal
|
|
} // namespace v8
|