AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity
609f566b34
v8/test/unittests/logging/counters-unittest.cc
Clemens Backes 609f566b34 Revert "Unconditionally enable snapshot builds and remove 'v8_use_snapshot'" 
This reverts commit 1c56974f2a.

Reason for revert: Causes several bots to timeout, e.g. https://ci.chromium.org/p/v8/builders/ci/V8%20Linux%20-%20debug/27945

Original change's description:
> Unconditionally enable snapshot builds and remove 'v8_use_snapshot'
> 
> This CL removes 'v8_use_snapshot' and the usages of the implied
> V8_USE_SNAPSHOT define. One test runner unittest was updated to use the
> "asan" variant instead of the now obsolete "no_snap" variant.
> 
> Related chromium CL: https://crrev.com/c/1796325.
> 
> Bug: v8:8531
> Change-Id: I5da7c9f8e9110fe7bc0f4e4f821bcb7f7d98f927
> Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1784282
> Commit-Queue: Simon Zünd <szuend@chromium.org>
> Reviewed-by: Tamer Tas <tmrts@chromium.org>
> Reviewed-by: Michael Achenbach <machenbach@chromium.org>
> Reviewed-by: Nico Weber <thakis@chromium.org>
> Reviewed-by: Jakob Gruber <jgruber@chromium.org>
> Reviewed-by: Michael Starzinger <mstarzinger@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#64290}

TBR=thakis@chromium.org,machenbach@chromium.org,mstarzinger@chromium.org,jgruber@chromium.org,tmrts@chromium.org,szuend@chromium.org

Change-Id: I4024d818877e534b9f7908a2d14f33dca35b5924
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: v8:8531
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1862572
Reviewed-by: Clemens Backes <clemensb@chromium.org>
Commit-Queue: Clemens Backes <clemensb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#64293}
2019-10-15 14:20:52 +00:00

857 lines
26 KiB
C++
Raw Blame History

// Copyright 2014 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 <vector>
#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-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 {
class MockHistogram : public Histogram {
public:
void AddSample(int value) { samples_.push_back(value); }
std::vector<int>* samples() { return &samples_; }
private:
std::vector<int> samples_;
};
class AggregatedMemoryHistogramTest : public ::testing::Test {
public:
AggregatedMemoryHistogramTest() : aggregated_(&mock_) {}
~AggregatedMemoryHistogramTest() override = default;
void AddSample(double current_ms, double current_value) {
aggregated_.AddSample(current_ms, current_value);
}
std::vector<int>* samples() { return mock_.samples(); }
private:
AggregatedMemoryHistogram<MockHistogram> aggregated_;
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 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 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() {}
bool SupportsNativeCounters() const {
#ifdef V8_USE_SNAPSHOT
#ifdef V8_SNAPSHOT_NATIVE_CODE_COUNTERS
return true;
#else
return false;
#endif // V8_SNAPSHOT_NATIVE_CODE_COUNTERS
#else
// If we do not have a snapshot then we rely on the runtime option.
return internal::FLAG_native_code_counters;
#endif // V8_USE_SNAPSHOT
}
#define SC(name, caption) \
int name() { \
CHECK(isolate()->counters()->name()->Enabled()); \
return *isolate()->counters()->name()->GetInternalPointer(); \
}
STATS_COUNTER_NATIVE_CODE_LIST(SC)
#undef SC
void PrintAll() {
#define SC(name, caption) PrintF(#caption " = %d\n", name());
STATS_COUNTER_NATIVE_CODE_LIST(SC)
#undef SC
}
};
} // namespace
TEST_F(AggregatedMemoryHistogramTest, OneSample1) {
FLAG_histogram_interval = 10;
AddSample(10, 1000);
AddSample(20, 1000);
EXPECT_EQ(1U, samples()->size());
EXPECT_EQ(1000, (*samples())[0]);
}
TEST_F(AggregatedMemoryHistogramTest, OneSample2) {
FLAG_histogram_interval = 10;
AddSample(10, 500);
AddSample(20, 1000);
EXPECT_EQ(1U, samples()->size());
EXPECT_EQ(750, (*samples())[0]);
}
TEST_F(AggregatedMemoryHistogramTest, OneSample3) {
FLAG_histogram_interval = 10;
AddSample(10, 500);
AddSample(15, 500);
AddSample(15, 1000);
AddSample(20, 1000);
EXPECT_EQ(1U, samples()->size());
EXPECT_EQ(750, (*samples())[0]);
}
TEST_F(AggregatedMemoryHistogramTest, OneSample4) {
FLAG_histogram_interval = 10;
AddSample(10, 500);
AddSample(15, 750);
AddSample(20, 1000);
EXPECT_EQ(1U, samples()->size());
EXPECT_EQ(750, (*samples())[0]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples1) {
FLAG_histogram_interval = 10;
AddSample(10, 1000);
AddSample(30, 1000);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ(1000, (*samples())[0]);
EXPECT_EQ(1000, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples2) {
FLAG_histogram_interval = 10;
AddSample(10, 1000);
AddSample(20, 1000);
AddSample(30, 1000);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ(1000, (*samples())[0]);
EXPECT_EQ(1000, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples3) {
FLAG_histogram_interval = 10;
AddSample(10, 1000);
AddSample(20, 1000);
AddSample(20, 500);
AddSample(30, 500);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ(1000, (*samples())[0]);
EXPECT_EQ(500, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples4) {
FLAG_histogram_interval = 10;
AddSample(10, 1000);
AddSample(30, 0);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ(750, (*samples())[0]);
EXPECT_EQ(250, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples5) {
FLAG_histogram_interval = 10;
AddSample(10, 0);
AddSample(30, 1000);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ(250, (*samples())[0]);
EXPECT_EQ(750, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples6) {
FLAG_histogram_interval = 10;
AddSample(10, 0);
AddSample(15, 1000);
AddSample(30, 1000);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ((500 + 1000) / 2, (*samples())[0]);
EXPECT_EQ(1000, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples7) {
FLAG_histogram_interval = 10;
AddSample(10, 0);
AddSample(15, 1000);
AddSample(25, 0);
AddSample(30, 1000);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ((500 + 750) / 2, (*samples())[0]);
EXPECT_EQ((250 + 500) / 2, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, TwoSamples8) {
FLAG_histogram_interval = 10;
AddSample(10, 1000);
AddSample(15, 0);
AddSample(25, 1000);
AddSample(30, 0);
EXPECT_EQ(2U, samples()->size());
EXPECT_EQ((500 + 250) / 2, (*samples())[0]);
EXPECT_EQ((750 + 500) / 2, (*samples())[1]);
}
TEST_F(AggregatedMemoryHistogramTest, ManySamples1) {
FLAG_histogram_interval = 10;
const int kMaxSamples = 1000;
AddSample(0, 0);
AddSample(10 * kMaxSamples, 10 * kMaxSamples);
EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
for (int i = 0; i < kMaxSamples; i++) {
EXPECT_EQ(i * 10 + 5, (*samples())[i]);
}
}
TEST_F(AggregatedMemoryHistogramTest, ManySamples2) {
FLAG_histogram_interval = 10;
const int kMaxSamples = 1000;
AddSample(0, 0);
AddSample(10 * (2 * kMaxSamples), 10 * (2 * kMaxSamples));
EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
for (int i = 0; i < kMaxSamples; i++) {
EXPECT_EQ(i * 10 + 5, (*samples())[i]);
}
}
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;
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;
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(SnapshotNativeCounterTest, StringAddNative) {
RunJS("let s = 'hello, ' + 'world!'");
if (SupportsNativeCounters()) {
EXPECT_NE(0, string_add_native());
} else {
EXPECT_EQ(0, string_add_native());
}
PrintAll();
}
TEST_F(SnapshotNativeCounterTest, SubStringNative) {
RunJS("'hello, world!'.substring(6);");
if (SupportsNativeCounters()) {
EXPECT_NE(0, sub_string_native());
} else {
EXPECT_EQ(0, sub_string_native());
}
PrintAll();
}
TEST_F(SnapshotNativeCounterTest, WriteBarrier) {
RunJS("let o = {a: 42};");
if (SupportsNativeCounters()) {
EXPECT_NE(0, write_barriers());
} else {
EXPECT_EQ(0, write_barriers());
}
PrintAll();
}
} // namespace internal
} // namespace v8
Reference in New Issue View Git Blame Copy Permalink