// 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 #include "src/base/platform/time.h" #include "src/counters-inl.h" #include "src/counters.h" #include "src/handles-inl.h" #include "src/objects-inl.h" #include "src/tracing/tracing-category-observer.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* samples() { return &samples_; } private: std::vector samples_; }; class AggregatedMemoryHistogramTest : public ::testing::Test { public: AggregatedMemoryHistogramTest() : aggregated_(&mock_) {} virtual ~AggregatedMemoryHistogramTest() {} void AddSample(double current_ms, double current_value) { aggregated_.AddSample(current_ms, current_value); } std::vector* samples() { return mock_.samples(); } private: AggregatedMemoryHistogram aggregated_; MockHistogram mock_; }; static base::TimeTicks runtime_call_stats_test_time_ = base::TimeTicks(); static base::TimeTicks RuntimeCallStatsTestNow() { return runtime_call_stats_test_time_; } class RuntimeCallStatsTest : public ::testing::Test { public: RuntimeCallStatsTest() { FLAG_runtime_stats = v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE; RuntimeCallTimer::Now = &RuntimeCallStatsTestNow; // 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); } virtual ~RuntimeCallStatsTest() { RuntimeCallTimer::Now = &base::TimeTicks::HighResolutionNow; } RuntimeCallStats* stats() { return &stats_; } RuntimeCallStats::CounterId counter_id() { return &RuntimeCallStats::TestCounter1; } RuntimeCallStats::CounterId counter_id2() { return &RuntimeCallStats::TestCounter2; } RuntimeCallStats::CounterId counter_id3() { return &RuntimeCallStats::TestCounter3; } RuntimeCallCounter* counter() { return &(stats()->*counter_id()); } RuntimeCallCounter* counter2() { return &(stats()->*counter_id2()); } RuntimeCallCounter* counter3() { return &(stats()->*counter_id3()); } void Sleep(int32_t milliseconds) { base::TimeDelta delta = base::TimeDelta::FromMilliseconds(milliseconds); time_ += delta; runtime_call_stats_test_time_ = base::TimeTicks::FromInternalValue(time_.InMicroseconds()); } private: RuntimeCallStats stats_; base::TimeDelta time_; }; } // 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(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(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); RuntimeCallStats::Enter(stats(), &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); RuntimeCallStats::Leave(stats(), &timer); Sleep(50); EXPECT_FALSE(timer.IsStarted()); EXPECT_EQ(1, counter()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); } TEST_F(RuntimeCallStatsTest, RuntimeCallTimerSubTimer) { RuntimeCallTimer timer; RuntimeCallTimer timer2; RuntimeCallStats::Enter(stats(), &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); RuntimeCallStats::Enter(stats(), &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); RuntimeCallStats::Leave(stats(), &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().InMilliseconds()); EXPECT_EQ(100, counter2()->time().InMilliseconds()); EXPECT_EQ(&timer, stats()->current_timer()); Sleep(100); RuntimeCallStats::Leave(stats(), &timer); EXPECT_FALSE(timer.IsStarted()); EXPECT_EQ(1, counter()->count()); EXPECT_EQ(1, counter2()->count()); EXPECT_EQ(150, counter()->time().InMilliseconds()); EXPECT_EQ(100, counter2()->time().InMilliseconds()); EXPECT_EQ(nullptr, stats()->current_timer()); } TEST_F(RuntimeCallStatsTest, RuntimeCallTimerRecursive) { RuntimeCallTimer timer; RuntimeCallTimer timer2; RuntimeCallStats::Enter(stats(), &timer, counter_id()); EXPECT_EQ(counter(), timer.counter()); EXPECT_EQ(nullptr, timer.parent()); EXPECT_TRUE(timer.IsStarted()); EXPECT_EQ(&timer, stats()->current_timer()); RuntimeCallStats::Enter(stats(), &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); RuntimeCallStats::Leave(stats(), &timer2); EXPECT_EQ(nullptr, timer.parent()); EXPECT_FALSE(timer2.IsStarted()); EXPECT_TRUE(timer.IsStarted()); EXPECT_EQ(1, counter()->count()); EXPECT_EQ(50, counter()->time().InMilliseconds()); Sleep(100); RuntimeCallStats::Leave(stats(), &timer); EXPECT_FALSE(timer.IsStarted()); EXPECT_EQ(2, counter()->count()); EXPECT_EQ(150, counter()->time().InMilliseconds()); } TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScope) { { RuntimeCallTimerScope scope(stats(), counter_id()); Sleep(50); } Sleep(100); EXPECT_EQ(1, counter()->count()); EXPECT_EQ(50, counter()->time().InMilliseconds()); { RuntimeCallTimerScope scope(stats(), counter_id()); Sleep(50); } EXPECT_EQ(2, counter()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); } TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) { { RuntimeCallTimerScope scope(stats(), counter_id()); Sleep(50); EXPECT_EQ(0, counter()->count()); EXPECT_EQ(0, counter()->time().InMilliseconds()); { RuntimeCallTimerScope scope(stats(), counter_id()); Sleep(50); } EXPECT_EQ(1, counter()->count()); EXPECT_EQ(50, counter()->time().InMilliseconds()); } EXPECT_EQ(2, counter()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); } 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().InMilliseconds()); EXPECT_EQ(0, counter2()->time().InMilliseconds()); { RuntimeCallTimerScope scope(stats(), counter_id()); Sleep(100); } CHANGE_CURRENT_RUNTIME_COUNTER(stats(), TestCounter2); EXPECT_EQ(1, counter()->count()); EXPECT_EQ(0, counter2()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); EXPECT_EQ(0, counter2()->time().InMilliseconds()); } EXPECT_EQ(1, counter()->count()); EXPECT_EQ(1, counter2()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); EXPECT_EQ(50, counter2()->time().InMilliseconds()); } 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().InMilliseconds()); EXPECT_EQ(0, counter2()->time().InMilliseconds()); EXPECT_EQ(0, counter3()->time().InMilliseconds()); { 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().InMilliseconds()); EXPECT_EQ(0, counter2()->time().InMilliseconds()); EXPECT_EQ(0, counter3()->time().InMilliseconds()); } TEST_F(RuntimeCallStatsTest, PrintAndSnapshot) { { RuntimeCallTimerScope scope(stats(), counter_id()); Sleep(100); EXPECT_EQ(0, counter()->count()); EXPECT_EQ(0, counter()->time().InMilliseconds()); { RuntimeCallTimerScope scope(stats(), counter_id2()); EXPECT_EQ(0, counter2()->count()); EXPECT_EQ(0, counter2()->time().InMilliseconds()); 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().InMilliseconds()); EXPECT_EQ(50, counter2()->time().InMilliseconds()); // 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().InMilliseconds()); EXPECT_EQ(50, counter2()->time().InMilliseconds()); Sleep(50); stats()->Print(out); EXPECT_EQ(0, counter()->count()); EXPECT_EQ(0, counter2()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); EXPECT_EQ(100, counter2()->time().InMilliseconds()); Sleep(50); } Sleep(50); EXPECT_EQ(0, counter()->count()); EXPECT_EQ(1, counter2()->count()); EXPECT_EQ(100, counter()->time().InMilliseconds()); EXPECT_EQ(150, counter2()->time().InMilliseconds()); Sleep(50); } EXPECT_EQ(1, counter()->count()); EXPECT_EQ(1, counter2()->count()); EXPECT_EQ(200, counter()->time().InMilliseconds()); EXPECT_EQ(150, counter2()->time().InMilliseconds()); } 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().InMilliseconds()); EXPECT_EQ(300, counter2()->time().InMilliseconds()); EXPECT_EQ(100, counter3()->time().InMilliseconds()); } } // namespace internal } // namespace v8