diff options
Diffstat (limited to 'deps/v8/test/unittests/logging')
-rw-r--r-- | deps/v8/test/unittests/logging/counters-unittest.cc | 616 | ||||
-rw-r--r-- | deps/v8/test/unittests/logging/runtime-call-stats-unittest.cc | 643 |
2 files changed, 643 insertions, 616 deletions
diff --git a/deps/v8/test/unittests/logging/counters-unittest.cc b/deps/v8/test/unittests/logging/counters-unittest.cc index 468ca4fc4e..3558f745f8 100644 --- a/deps/v8/test/unittests/logging/counters-unittest.cc +++ b/deps/v8/test/unittests/logging/counters-unittest.cc @@ -8,7 +8,6 @@ #include "src/base/atomic-utils.h" #include "src/base/platform/time.h" #include "src/handles/handles-inl.h" -#include "src/logging/counters-inl.h" #include "src/logging/counters.h" #include "src/objects/objects-inl.h" #include "src/tracing/tracing-category-observer.h" @@ -46,104 +45,6 @@ class AggregatedMemoryHistogramTest : public ::testing::Test { MockHistogram mock_; }; -static 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 SetUpTestCase() { - TestWithIsolate::SetUpTestCase(); - // Use a custom time source to precisly emulate system time. - RuntimeCallTimer::Now = &RuntimeCallStatsTestNow; - } - - static void TearDownTestCase() { - TestWithIsolate::TearDownTestCase(); - // Restore the original time source. - RuntimeCallTimer::Now = &base::TimeTicks::HighResolutionNow; - } - - 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::HighResolutionNow; - } - ~NativeTimeScope() { - CHECK_EQ(RuntimeCallTimer::Now, &base::TimeTicks::HighResolutionNow); - RuntimeCallTimer::Now = &RuntimeCallStatsTestNow; - } -}; - class SnapshotNativeCounterTest : public TestWithNativeContextAndCounters { public: SnapshotNativeCounterTest() {} @@ -310,523 +211,6 @@ TEST_F(AggregatedMemoryHistogramTest, ManySamples2) { } } -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) { - { - RuntimeCallTimerScope scope(stats(), counter_id()); - Sleep(50); - } - Sleep(100); - EXPECT_EQ(1, counter()->count()); - EXPECT_EQ(50, counter()->time().InMicroseconds()); - { - RuntimeCallTimerScope scope(stats(), counter_id()); - Sleep(50); - } - EXPECT_EQ(2, counter()->count()); - EXPECT_EQ(100, counter()->time().InMicroseconds()); -} - -TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) { - { - RuntimeCallTimerScope scope(stats(), counter_id()); - Sleep(50); - EXPECT_EQ(0, counter()->count()); - EXPECT_EQ(0, counter()->time().InMicroseconds()); - { - RuntimeCallTimerScope 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) { - { - RuntimeCallTimerScope 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()); - { - RuntimeCallTimerScope 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()); - - { - RuntimeCallTimerScope 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) { - { - RuntimeCallTimerScope scope(stats(), counter_id()); - Sleep(100); - EXPECT_EQ(0, counter()->count()); - EXPECT_EQ(0, counter()->time().InMicroseconds()); - { - RuntimeCallTimerScope 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) { - { - RuntimeCallTimerScope scope(stats(), counter_id()); - Sleep(100); - { - RuntimeCallTimerScope scope(stats(), counter_id2()); - Sleep(100); - { - RuntimeCallTimerScope scope(stats(), counter_id3()); - Sleep(50); - } - Sleep(50); - { - RuntimeCallTimerScope scope(stats(), counter_id3()); - Sleep(50); - } - Sleep(50); - } - Sleep(100); - { - RuntimeCallTimerScope 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) { - RuntimeCallTimerScope 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()); - { - RuntimeCallTimerScope 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()); - - { - RuntimeCallTimerScope 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) { - FLAG_expose_gc = true; - 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); -} - TEST_F(SnapshotNativeCounterTest, StringAddNative) { RunJS("let s = 'hello, ' + 'world!'"); diff --git a/deps/v8/test/unittests/logging/runtime-call-stats-unittest.cc b/deps/v8/test/unittests/logging/runtime-call-stats-unittest.cc new file mode 100644 index 0000000000..8d0ea594c3 --- /dev/null +++ b/deps/v8/test/unittests/logging/runtime-call-stats-unittest.cc @@ -0,0 +1,643 @@ +// 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 "src/api/api-inl.h" +#include "src/base/atomic-utils.h" +#include "src/base/platform/time.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 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 SetUpTestCase() { + TestWithIsolate::SetUpTestCase(); + // Use a custom time source to precisly emulate system time. + RuntimeCallTimer::Now = &RuntimeCallStatsTestNow; + } + + static void TearDownTestCase() { + TestWithIsolate::TearDownTestCase(); + // Restore the original time source. + RuntimeCallTimer::Now = &base::TimeTicks::HighResolutionNow; + } + + 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::HighResolutionNow; + } + ~NativeTimeScope() { + CHECK_EQ(RuntimeCallTimer::Now, &base::TimeTicks::HighResolutionNow); + 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) { + 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; + 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 |