Line data Source code
1 : // Copyright 2014 the V8 project authors. All rights reserved.
2 : // Use of this source code is governed by a BSD-style license that can be
3 : // found in the LICENSE file.
4 :
5 : #include <vector>
6 :
7 : #include "src/api-inl.h"
8 : #include "src/base/atomic-utils.h"
9 : #include "src/base/platform/time.h"
10 : #include "src/counters-inl.h"
11 : #include "src/counters.h"
12 : #include "src/handles-inl.h"
13 : #include "src/objects-inl.h"
14 : #include "src/tracing/tracing-category-observer.h"
15 :
16 : #include "test/unittests/test-utils.h"
17 : #include "testing/gtest/include/gtest/gtest.h"
18 :
19 : namespace v8 {
20 : namespace internal {
21 :
22 : namespace {
23 :
24 14 : class MockHistogram : public Histogram {
25 : public:
26 2020 : void AddSample(int value) { samples_.push_back(value); }
27 : std::vector<int>* samples() { return &samples_; }
28 :
29 : private:
30 : std::vector<int> samples_;
31 : };
32 :
33 :
34 : class AggregatedMemoryHistogramTest : public ::testing::Test {
35 : public:
36 14 : AggregatedMemoryHistogramTest() : aggregated_(&mock_) {}
37 28 : ~AggregatedMemoryHistogramTest() override = default;
38 :
39 : void AddSample(double current_ms, double current_value) {
40 14 : aggregated_.AddSample(current_ms, current_value);
41 : }
42 :
43 : std::vector<int>* samples() { return mock_.samples(); }
44 :
45 : private:
46 : AggregatedMemoryHistogram<MockHistogram> aggregated_;
47 : MockHistogram mock_;
48 : };
49 :
50 : static base::TimeTicks runtime_call_stats_test_time_ = base::TimeTicks();
51 : // Time source used for the RuntimeCallTimer during tests. We cannot rely on
52 : // the native timer since it's too unpredictable on the build bots.
53 48378 : static base::TimeTicks RuntimeCallStatsTestNow() {
54 48378 : return runtime_call_stats_test_time_;
55 : }
56 :
57 : class RuntimeCallStatsTest : public TestWithNativeContext {
58 : public:
59 26 : RuntimeCallStatsTest() {
60 : TracingFlags::runtime_stats.store(
61 : v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE,
62 : std::memory_order_relaxed);
63 : // We need to set {time_} to a non-zero value since it would otherwise
64 : // cause runtime call timers to think they are uninitialized.
65 : Sleep(1);
66 13 : stats()->Reset();
67 13 : }
68 :
69 26 : ~RuntimeCallStatsTest() override {
70 : // Disable RuntimeCallStats before tearing down the isolate to prevent
71 : // printing the tests table. Comment the following line for debugging
72 : // purposes.
73 : TracingFlags::runtime_stats.store(0, std::memory_order_relaxed);
74 13 : }
75 :
76 13 : static void SetUpTestCase() {
77 : TestWithIsolate::SetUpTestCase();
78 : // Use a custom time source to precisly emulate system time.
79 13 : RuntimeCallTimer::Now = &RuntimeCallStatsTestNow;
80 13 : }
81 :
82 13 : static void TearDownTestCase() {
83 : TestWithIsolate::TearDownTestCase();
84 : // Restore the original time source.
85 13 : RuntimeCallTimer::Now = &base::TimeTicks::HighResolutionNow;
86 13 : }
87 :
88 : RuntimeCallStats* stats() {
89 : return isolate()->counters()->runtime_call_stats();
90 : }
91 :
92 : // Print current RuntimeCallStats table. For debugging purposes.
93 4 : void PrintStats() { stats()->Print(); }
94 :
95 : RuntimeCallCounterId counter_id() {
96 : return RuntimeCallCounterId::kTestCounter1;
97 : }
98 :
99 : RuntimeCallCounterId counter_id2() {
100 : return RuntimeCallCounterId::kTestCounter2;
101 : }
102 :
103 : RuntimeCallCounterId counter_id3() {
104 : return RuntimeCallCounterId::kTestCounter3;
105 : }
106 :
107 : RuntimeCallCounter* js_counter() {
108 : return stats()->GetCounter(RuntimeCallCounterId::kJS_Execution);
109 : }
110 : RuntimeCallCounter* counter() { return stats()->GetCounter(counter_id()); }
111 : RuntimeCallCounter* counter2() { return stats()->GetCounter(counter_id2()); }
112 : RuntimeCallCounter* counter3() { return stats()->GetCounter(counter_id3()); }
113 :
114 : void Sleep(int64_t microseconds) {
115 : base::TimeDelta delta = base::TimeDelta::FromMicroseconds(microseconds);
116 : time_ += delta;
117 : runtime_call_stats_test_time_ =
118 8066 : base::TimeTicks::FromInternalValue(time_.InMicroseconds());
119 : }
120 :
121 : private:
122 : base::TimeDelta time_;
123 : };
124 :
125 : // Temporarily use the native time to modify the test time.
126 : class ElapsedTimeScope {
127 : public:
128 : explicit ElapsedTimeScope(RuntimeCallStatsTest* test) : test_(test) {
129 : timer_.Start();
130 : }
131 : ~ElapsedTimeScope() { test_->Sleep(timer_.Elapsed().InMicroseconds()); }
132 :
133 : private:
134 : base::ElapsedTimer timer_;
135 : RuntimeCallStatsTest* test_;
136 : };
137 :
138 : // Temporarily use the default time source.
139 : class NativeTimeScope {
140 : public:
141 6 : NativeTimeScope() {
142 6 : CHECK_EQ(RuntimeCallTimer::Now, &RuntimeCallStatsTestNow);
143 6 : RuntimeCallTimer::Now = &base::TimeTicks::HighResolutionNow;
144 6 : }
145 6 : ~NativeTimeScope() {
146 6 : CHECK_EQ(RuntimeCallTimer::Now, &base::TimeTicks::HighResolutionNow);
147 6 : RuntimeCallTimer::Now = &RuntimeCallStatsTestNow;
148 6 : }
149 : };
150 :
151 6 : class SnapshotNativeCounterTest : public TestWithNativeContextAndCounters {
152 : public:
153 3 : SnapshotNativeCounterTest() {}
154 :
155 : bool SupportsNativeCounters() const {
156 : #ifdef V8_USE_SNAPSHOT
157 : #ifdef V8_SNAPSHOT_NATIVE_CODE_COUNTERS
158 : return true;
159 : #else
160 : return false;
161 : #endif // V8_SNAPSHOT_NATIVE_CODE_COUNTERS
162 : #else
163 : // If we do not have a snapshot then we rely on the runtime option.
164 : return internal::FLAG_native_code_counters;
165 : #endif // V8_USE_SNAPSHOT
166 : }
167 :
168 : #define SC(name, caption) \
169 : int name() { \
170 : CHECK(isolate()->counters()->name()->Enabled()); \
171 : return *isolate()->counters()->name()->GetInternalPointer(); \
172 : }
173 108 : STATS_COUNTER_NATIVE_CODE_LIST(SC)
174 : #undef SC
175 :
176 3 : void PrintAll() {
177 : #define SC(name, caption) PrintF(#caption " = %d\n", name());
178 3 : STATS_COUNTER_NATIVE_CODE_LIST(SC)
179 : #undef SC
180 3 : }
181 : };
182 :
183 : } // namespace
184 :
185 :
186 15443 : TEST_F(AggregatedMemoryHistogramTest, OneSample1) {
187 1 : FLAG_histogram_interval = 10;
188 : AddSample(10, 1000);
189 : AddSample(20, 1000);
190 2 : EXPECT_EQ(1U, samples()->size());
191 2 : EXPECT_EQ(1000, (*samples())[0]);
192 1 : }
193 :
194 :
195 15443 : TEST_F(AggregatedMemoryHistogramTest, OneSample2) {
196 1 : FLAG_histogram_interval = 10;
197 : AddSample(10, 500);
198 : AddSample(20, 1000);
199 2 : EXPECT_EQ(1U, samples()->size());
200 2 : EXPECT_EQ(750, (*samples())[0]);
201 1 : }
202 :
203 :
204 15443 : TEST_F(AggregatedMemoryHistogramTest, OneSample3) {
205 1 : FLAG_histogram_interval = 10;
206 : AddSample(10, 500);
207 : AddSample(15, 500);
208 : AddSample(15, 1000);
209 : AddSample(20, 1000);
210 2 : EXPECT_EQ(1U, samples()->size());
211 2 : EXPECT_EQ(750, (*samples())[0]);
212 1 : }
213 :
214 :
215 15443 : TEST_F(AggregatedMemoryHistogramTest, OneSample4) {
216 1 : FLAG_histogram_interval = 10;
217 : AddSample(10, 500);
218 : AddSample(15, 750);
219 : AddSample(20, 1000);
220 2 : EXPECT_EQ(1U, samples()->size());
221 2 : EXPECT_EQ(750, (*samples())[0]);
222 1 : }
223 :
224 :
225 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples1) {
226 1 : FLAG_histogram_interval = 10;
227 : AddSample(10, 1000);
228 : AddSample(30, 1000);
229 2 : EXPECT_EQ(2U, samples()->size());
230 2 : EXPECT_EQ(1000, (*samples())[0]);
231 2 : EXPECT_EQ(1000, (*samples())[1]);
232 1 : }
233 :
234 :
235 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples2) {
236 1 : FLAG_histogram_interval = 10;
237 : AddSample(10, 1000);
238 : AddSample(20, 1000);
239 : AddSample(30, 1000);
240 2 : EXPECT_EQ(2U, samples()->size());
241 2 : EXPECT_EQ(1000, (*samples())[0]);
242 2 : EXPECT_EQ(1000, (*samples())[1]);
243 1 : }
244 :
245 :
246 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples3) {
247 1 : FLAG_histogram_interval = 10;
248 : AddSample(10, 1000);
249 : AddSample(20, 1000);
250 : AddSample(20, 500);
251 : AddSample(30, 500);
252 2 : EXPECT_EQ(2U, samples()->size());
253 2 : EXPECT_EQ(1000, (*samples())[0]);
254 2 : EXPECT_EQ(500, (*samples())[1]);
255 1 : }
256 :
257 :
258 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples4) {
259 1 : FLAG_histogram_interval = 10;
260 : AddSample(10, 1000);
261 : AddSample(30, 0);
262 2 : EXPECT_EQ(2U, samples()->size());
263 2 : EXPECT_EQ(750, (*samples())[0]);
264 2 : EXPECT_EQ(250, (*samples())[1]);
265 1 : }
266 :
267 :
268 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples5) {
269 1 : FLAG_histogram_interval = 10;
270 : AddSample(10, 0);
271 : AddSample(30, 1000);
272 2 : EXPECT_EQ(2U, samples()->size());
273 2 : EXPECT_EQ(250, (*samples())[0]);
274 2 : EXPECT_EQ(750, (*samples())[1]);
275 : }
276 :
277 :
278 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples6) {
279 1 : FLAG_histogram_interval = 10;
280 : AddSample(10, 0);
281 : AddSample(15, 1000);
282 : AddSample(30, 1000);
283 2 : EXPECT_EQ(2U, samples()->size());
284 2 : EXPECT_EQ((500 + 1000) / 2, (*samples())[0]);
285 2 : EXPECT_EQ(1000, (*samples())[1]);
286 1 : }
287 :
288 :
289 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples7) {
290 1 : FLAG_histogram_interval = 10;
291 : AddSample(10, 0);
292 : AddSample(15, 1000);
293 : AddSample(25, 0);
294 : AddSample(30, 1000);
295 2 : EXPECT_EQ(2U, samples()->size());
296 2 : EXPECT_EQ((500 + 750) / 2, (*samples())[0]);
297 2 : EXPECT_EQ((250 + 500) / 2, (*samples())[1]);
298 1 : }
299 :
300 :
301 15443 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples8) {
302 1 : FLAG_histogram_interval = 10;
303 : AddSample(10, 1000);
304 : AddSample(15, 0);
305 : AddSample(25, 1000);
306 : AddSample(30, 0);
307 2 : EXPECT_EQ(2U, samples()->size());
308 2 : EXPECT_EQ((500 + 250) / 2, (*samples())[0]);
309 2 : EXPECT_EQ((750 + 500) / 2, (*samples())[1]);
310 1 : }
311 :
312 :
313 15443 : TEST_F(AggregatedMemoryHistogramTest, ManySamples1) {
314 1 : FLAG_histogram_interval = 10;
315 : const int kMaxSamples = 1000;
316 : AddSample(0, 0);
317 : AddSample(10 * kMaxSamples, 10 * kMaxSamples);
318 2 : EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
319 2001 : for (int i = 0; i < kMaxSamples; i++) {
320 3000 : EXPECT_EQ(i * 10 + 5, (*samples())[i]);
321 : }
322 1 : }
323 :
324 :
325 15443 : TEST_F(AggregatedMemoryHistogramTest, ManySamples2) {
326 1 : FLAG_histogram_interval = 10;
327 : const int kMaxSamples = 1000;
328 : AddSample(0, 0);
329 : AddSample(10 * (2 * kMaxSamples), 10 * (2 * kMaxSamples));
330 2 : EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
331 2001 : for (int i = 0; i < kMaxSamples; i++) {
332 3000 : EXPECT_EQ(i * 10 + 5, (*samples())[i]);
333 : }
334 1 : }
335 :
336 15443 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimer) {
337 : RuntimeCallTimer timer;
338 :
339 : Sleep(50);
340 1 : stats()->Enter(&timer, counter_id());
341 3 : EXPECT_EQ(counter(), timer.counter());
342 1 : EXPECT_EQ(nullptr, timer.parent());
343 1 : EXPECT_TRUE(timer.IsStarted());
344 2 : EXPECT_EQ(&timer, stats()->current_timer());
345 :
346 : Sleep(100);
347 :
348 1 : stats()->Leave(&timer);
349 : Sleep(50);
350 2 : EXPECT_FALSE(timer.IsStarted());
351 2 : EXPECT_EQ(1, counter()->count());
352 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
353 1 : }
354 :
355 15443 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerSubTimer) {
356 : RuntimeCallTimer timer;
357 : RuntimeCallTimer timer2;
358 :
359 1 : stats()->Enter(&timer, counter_id());
360 1 : EXPECT_TRUE(timer.IsStarted());
361 2 : EXPECT_FALSE(timer2.IsStarted());
362 3 : EXPECT_EQ(counter(), timer.counter());
363 1 : EXPECT_EQ(nullptr, timer.parent());
364 2 : EXPECT_EQ(&timer, stats()->current_timer());
365 :
366 : Sleep(50);
367 :
368 1 : stats()->Enter(&timer2, counter_id2());
369 : // timer 1 is paused, while timer 2 is active.
370 1 : EXPECT_TRUE(timer2.IsStarted());
371 3 : EXPECT_EQ(counter(), timer.counter());
372 3 : EXPECT_EQ(counter2(), timer2.counter());
373 1 : EXPECT_EQ(nullptr, timer.parent());
374 2 : EXPECT_EQ(&timer, timer2.parent());
375 2 : EXPECT_EQ(&timer2, stats()->current_timer());
376 :
377 : Sleep(100);
378 1 : stats()->Leave(&timer2);
379 :
380 : // The subtimer subtracts its time from the parent timer.
381 1 : EXPECT_TRUE(timer.IsStarted());
382 2 : EXPECT_FALSE(timer2.IsStarted());
383 2 : EXPECT_EQ(0, counter()->count());
384 2 : EXPECT_EQ(1, counter2()->count());
385 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
386 2 : EXPECT_EQ(100, counter2()->time().InMicroseconds());
387 2 : EXPECT_EQ(&timer, stats()->current_timer());
388 :
389 : Sleep(100);
390 :
391 1 : stats()->Leave(&timer);
392 2 : EXPECT_FALSE(timer.IsStarted());
393 2 : EXPECT_EQ(1, counter()->count());
394 2 : EXPECT_EQ(1, counter2()->count());
395 2 : EXPECT_EQ(150, counter()->time().InMicroseconds());
396 2 : EXPECT_EQ(100, counter2()->time().InMicroseconds());
397 1 : EXPECT_EQ(nullptr, stats()->current_timer());
398 1 : }
399 :
400 15443 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerRecursive) {
401 : RuntimeCallTimer timer;
402 : RuntimeCallTimer timer2;
403 :
404 1 : stats()->Enter(&timer, counter_id());
405 3 : EXPECT_EQ(counter(), timer.counter());
406 1 : EXPECT_EQ(nullptr, timer.parent());
407 1 : EXPECT_TRUE(timer.IsStarted());
408 2 : EXPECT_EQ(&timer, stats()->current_timer());
409 :
410 1 : stats()->Enter(&timer2, counter_id());
411 3 : EXPECT_EQ(counter(), timer2.counter());
412 1 : EXPECT_EQ(nullptr, timer.parent());
413 2 : EXPECT_EQ(&timer, timer2.parent());
414 1 : EXPECT_TRUE(timer2.IsStarted());
415 2 : EXPECT_EQ(&timer2, stats()->current_timer());
416 :
417 : Sleep(50);
418 :
419 1 : stats()->Leave(&timer2);
420 1 : EXPECT_EQ(nullptr, timer.parent());
421 2 : EXPECT_FALSE(timer2.IsStarted());
422 1 : EXPECT_TRUE(timer.IsStarted());
423 2 : EXPECT_EQ(1, counter()->count());
424 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
425 :
426 : Sleep(100);
427 :
428 1 : stats()->Leave(&timer);
429 2 : EXPECT_FALSE(timer.IsStarted());
430 2 : EXPECT_EQ(2, counter()->count());
431 2 : EXPECT_EQ(150, counter()->time().InMicroseconds());
432 1 : }
433 :
434 15443 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScope) {
435 : {
436 1 : RuntimeCallTimerScope scope(stats(), counter_id());
437 : Sleep(50);
438 : }
439 : Sleep(100);
440 2 : EXPECT_EQ(1, counter()->count());
441 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
442 : {
443 1 : RuntimeCallTimerScope scope(stats(), counter_id());
444 : Sleep(50);
445 : }
446 2 : EXPECT_EQ(2, counter()->count());
447 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
448 1 : }
449 :
450 15443 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) {
451 : {
452 1 : RuntimeCallTimerScope scope(stats(), counter_id());
453 : Sleep(50);
454 2 : EXPECT_EQ(0, counter()->count());
455 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
456 : {
457 1 : RuntimeCallTimerScope scope(stats(), counter_id());
458 : Sleep(50);
459 : }
460 2 : EXPECT_EQ(1, counter()->count());
461 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
462 : }
463 2 : EXPECT_EQ(2, counter()->count());
464 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
465 1 : }
466 :
467 15443 : TEST_F(RuntimeCallStatsTest, RenameTimer) {
468 : {
469 1 : RuntimeCallTimerScope scope(stats(), counter_id());
470 : Sleep(50);
471 2 : EXPECT_EQ(0, counter()->count());
472 2 : EXPECT_EQ(0, counter2()->count());
473 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
474 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
475 : {
476 1 : RuntimeCallTimerScope scope(stats(), counter_id());
477 : Sleep(100);
478 : }
479 3 : CHANGE_CURRENT_RUNTIME_COUNTER(stats(),
480 : RuntimeCallCounterId::kTestCounter2);
481 2 : EXPECT_EQ(1, counter()->count());
482 2 : EXPECT_EQ(0, counter2()->count());
483 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
484 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
485 : }
486 2 : EXPECT_EQ(1, counter()->count());
487 2 : EXPECT_EQ(1, counter2()->count());
488 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
489 2 : EXPECT_EQ(50, counter2()->time().InMicroseconds());
490 1 : }
491 :
492 15443 : TEST_F(RuntimeCallStatsTest, BasicPrintAndSnapshot) {
493 2 : std::ostringstream out;
494 1 : stats()->Print(out);
495 2 : EXPECT_EQ(0, counter()->count());
496 2 : EXPECT_EQ(0, counter2()->count());
497 2 : EXPECT_EQ(0, counter3()->count());
498 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
499 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
500 2 : EXPECT_EQ(0, counter3()->time().InMicroseconds());
501 :
502 : {
503 1 : RuntimeCallTimerScope scope(stats(), counter_id());
504 : Sleep(50);
505 1 : stats()->Print(out);
506 : }
507 1 : stats()->Print(out);
508 2 : EXPECT_EQ(1, counter()->count());
509 2 : EXPECT_EQ(0, counter2()->count());
510 2 : EXPECT_EQ(0, counter3()->count());
511 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
512 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
513 2 : EXPECT_EQ(0, counter3()->time().InMicroseconds());
514 1 : }
515 :
516 15443 : TEST_F(RuntimeCallStatsTest, PrintAndSnapshot) {
517 : {
518 1 : RuntimeCallTimerScope scope(stats(), counter_id());
519 : Sleep(100);
520 2 : EXPECT_EQ(0, counter()->count());
521 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
522 : {
523 1 : RuntimeCallTimerScope scope(stats(), counter_id2());
524 2 : EXPECT_EQ(0, counter2()->count());
525 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
526 : Sleep(50);
527 :
528 : // This calls Snapshot on the current active timer and sychronizes and
529 : // commits the whole timer stack.
530 2 : std::ostringstream out;
531 1 : stats()->Print(out);
532 2 : EXPECT_EQ(0, counter()->count());
533 2 : EXPECT_EQ(0, counter2()->count());
534 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
535 2 : EXPECT_EQ(50, counter2()->time().InMicroseconds());
536 : // Calling Print several times shouldn't have a (big) impact on the
537 : // measured times.
538 1 : stats()->Print(out);
539 2 : EXPECT_EQ(0, counter()->count());
540 2 : EXPECT_EQ(0, counter2()->count());
541 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
542 2 : EXPECT_EQ(50, counter2()->time().InMicroseconds());
543 :
544 : Sleep(50);
545 1 : stats()->Print(out);
546 2 : EXPECT_EQ(0, counter()->count());
547 2 : EXPECT_EQ(0, counter2()->count());
548 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
549 2 : EXPECT_EQ(100, counter2()->time().InMicroseconds());
550 : Sleep(50);
551 : }
552 : Sleep(50);
553 2 : EXPECT_EQ(0, counter()->count());
554 2 : EXPECT_EQ(1, counter2()->count());
555 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
556 2 : EXPECT_EQ(150, counter2()->time().InMicroseconds());
557 : Sleep(50);
558 : }
559 2 : EXPECT_EQ(1, counter()->count());
560 2 : EXPECT_EQ(1, counter2()->count());
561 2 : EXPECT_EQ(200, counter()->time().InMicroseconds());
562 2 : EXPECT_EQ(150, counter2()->time().InMicroseconds());
563 1 : }
564 :
565 15443 : TEST_F(RuntimeCallStatsTest, NestedScopes) {
566 : {
567 1 : RuntimeCallTimerScope scope(stats(), counter_id());
568 : Sleep(100);
569 : {
570 1 : RuntimeCallTimerScope scope(stats(), counter_id2());
571 : Sleep(100);
572 : {
573 1 : RuntimeCallTimerScope scope(stats(), counter_id3());
574 : Sleep(50);
575 : }
576 : Sleep(50);
577 : {
578 1 : RuntimeCallTimerScope scope(stats(), counter_id3());
579 : Sleep(50);
580 : }
581 : Sleep(50);
582 : }
583 : Sleep(100);
584 : {
585 1 : RuntimeCallTimerScope scope(stats(), counter_id2());
586 : Sleep(100);
587 : }
588 : Sleep(50);
589 : }
590 2 : EXPECT_EQ(1, counter()->count());
591 2 : EXPECT_EQ(2, counter2()->count());
592 2 : EXPECT_EQ(2, counter3()->count());
593 2 : EXPECT_EQ(250, counter()->time().InMicroseconds());
594 2 : EXPECT_EQ(300, counter2()->time().InMicroseconds());
595 2 : EXPECT_EQ(100, counter3()->time().InMicroseconds());
596 1 : }
597 :
598 15443 : TEST_F(RuntimeCallStatsTest, BasicJavaScript) {
599 : RuntimeCallCounter* counter =
600 : stats()->GetCounter(RuntimeCallCounterId::kJS_Execution);
601 2 : EXPECT_EQ(0, counter->count());
602 2 : EXPECT_EQ(0, counter->time().InMicroseconds());
603 :
604 : {
605 2 : NativeTimeScope native_timer_scope;
606 : RunJS("function f() { return 1; };");
607 : }
608 2 : EXPECT_EQ(1, counter->count());
609 1 : int64_t time = counter->time().InMicroseconds();
610 1 : EXPECT_LT(0, time);
611 :
612 : {
613 2 : NativeTimeScope native_timer_scope;
614 : RunJS("f();");
615 : }
616 2 : EXPECT_EQ(2, counter->count());
617 1 : EXPECT_LE(time, counter->time().InMicroseconds());
618 1 : }
619 :
620 15443 : TEST_F(RuntimeCallStatsTest, FunctionLengthGetter) {
621 : RuntimeCallCounter* getter_counter =
622 : stats()->GetCounter(RuntimeCallCounterId::kFunctionLengthGetter);
623 2 : EXPECT_EQ(0, getter_counter->count());
624 2 : EXPECT_EQ(0, js_counter()->count());
625 2 : EXPECT_EQ(0, getter_counter->time().InMicroseconds());
626 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
627 :
628 : {
629 2 : NativeTimeScope native_timer_scope;
630 : RunJS("function f(array) { return array.length; };");
631 : }
632 2 : EXPECT_EQ(0, getter_counter->count());
633 2 : EXPECT_EQ(1, js_counter()->count());
634 2 : EXPECT_EQ(0, getter_counter->time().InMicroseconds());
635 1 : int64_t js_time = js_counter()->time().InMicroseconds();
636 1 : EXPECT_LT(0, js_time);
637 :
638 : {
639 2 : NativeTimeScope native_timer_scope;
640 : RunJS("f.length;");
641 : }
642 2 : EXPECT_EQ(1, getter_counter->count());
643 2 : EXPECT_EQ(2, js_counter()->count());
644 1 : EXPECT_LE(0, getter_counter->time().InMicroseconds());
645 1 : EXPECT_LE(js_time, js_counter()->time().InMicroseconds());
646 :
647 : {
648 2 : NativeTimeScope native_timer_scope;
649 : RunJS("for (let i = 0; i < 50; i++) { f.length };");
650 : }
651 2 : EXPECT_EQ(51, getter_counter->count());
652 2 : EXPECT_EQ(3, js_counter()->count());
653 :
654 : {
655 2 : NativeTimeScope native_timer_scope;
656 : RunJS("for (let i = 0; i < 1000; i++) { f.length; };");
657 : }
658 2 : EXPECT_EQ(1051, getter_counter->count());
659 2 : EXPECT_EQ(4, js_counter()->count());
660 1 : }
661 :
662 : namespace {
663 : static RuntimeCallStatsTest* current_test;
664 : static const int kCustomCallbackTime = 1234;
665 8020 : static void CustomCallback(const v8::FunctionCallbackInfo<v8::Value>& info) {
666 : RuntimeCallTimerScope scope(current_test->stats(),
667 8020 : current_test->counter_id2());
668 8020 : current_test->Sleep(kCustomCallbackTime);
669 8020 : }
670 : } // namespace
671 :
672 15443 : TEST_F(RuntimeCallStatsTest, CallbackFunction) {
673 : RuntimeCallCounter* callback_counter =
674 : stats()->GetCounter(RuntimeCallCounterId::kFunctionCallback);
675 :
676 1 : current_test = this;
677 : // Set up a function template with a custom callback.
678 : v8::Isolate* isolate = v8_isolate();
679 2 : v8::HandleScope scope(isolate);
680 :
681 : v8::Local<v8::ObjectTemplate> object_template =
682 1 : v8::ObjectTemplate::New(isolate);
683 2 : object_template->Set(isolate, "callback",
684 : v8::FunctionTemplate::New(isolate, CustomCallback));
685 : v8::Local<v8::Object> object =
686 1 : object_template->NewInstance(v8_context()).ToLocalChecked();
687 1 : SetGlobalProperty("custom_object", object);
688 :
689 2 : EXPECT_EQ(0, js_counter()->count());
690 2 : EXPECT_EQ(0, counter()->count());
691 2 : EXPECT_EQ(0, callback_counter->count());
692 2 : EXPECT_EQ(0, counter2()->count());
693 : {
694 1 : RuntimeCallTimerScope scope(stats(), counter_id());
695 : Sleep(100);
696 : RunJS("custom_object.callback();");
697 : }
698 2 : EXPECT_EQ(1, js_counter()->count());
699 2 : EXPECT_EQ(1, counter()->count());
700 2 : EXPECT_EQ(1, callback_counter->count());
701 2 : EXPECT_EQ(1, counter2()->count());
702 : // Given that no native timers are used, only the two scopes explitly
703 : // mentioned above will track the time.
704 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
705 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
706 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
707 2 : EXPECT_EQ(kCustomCallbackTime, counter2()->time().InMicroseconds());
708 :
709 : RunJS("for (let i = 0; i < 9; i++) { custom_object.callback(); };");
710 2 : EXPECT_EQ(2, js_counter()->count());
711 2 : EXPECT_EQ(1, counter()->count());
712 2 : EXPECT_EQ(10, callback_counter->count());
713 2 : EXPECT_EQ(10, counter2()->count());
714 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
715 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
716 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
717 2 : EXPECT_EQ(kCustomCallbackTime * 10, counter2()->time().InMicroseconds());
718 :
719 : RunJS("for (let i = 0; i < 4000; i++) { custom_object.callback(); };");
720 2 : EXPECT_EQ(3, js_counter()->count());
721 2 : EXPECT_EQ(1, counter()->count());
722 2 : EXPECT_EQ(4010, callback_counter->count());
723 2 : EXPECT_EQ(4010, counter2()->count());
724 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
725 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
726 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
727 2 : EXPECT_EQ(kCustomCallbackTime * 4010, counter2()->time().InMicroseconds());
728 1 : }
729 :
730 15443 : TEST_F(RuntimeCallStatsTest, ApiGetter) {
731 : RuntimeCallCounter* callback_counter =
732 : stats()->GetCounter(RuntimeCallCounterId::kFunctionCallback);
733 1 : current_test = this;
734 : // Set up a function template with an api accessor.
735 : v8::Isolate* isolate = v8_isolate();
736 2 : v8::HandleScope scope(isolate);
737 :
738 : v8::Local<v8::ObjectTemplate> object_template =
739 1 : v8::ObjectTemplate::New(isolate);
740 2 : object_template->SetAccessorProperty(
741 : NewString("apiGetter"),
742 1 : v8::FunctionTemplate::New(isolate, CustomCallback));
743 : v8::Local<v8::Object> object =
744 1 : object_template->NewInstance(v8_context()).ToLocalChecked();
745 1 : SetGlobalProperty("custom_object", object);
746 :
747 : // TODO(cbruni): Check api accessor timer (one above the custom callback).
748 2 : EXPECT_EQ(0, js_counter()->count());
749 2 : EXPECT_EQ(0, counter()->count());
750 2 : EXPECT_EQ(0, callback_counter->count());
751 2 : EXPECT_EQ(0, counter2()->count());
752 :
753 : {
754 1 : RuntimeCallTimerScope scope(stats(), counter_id());
755 : Sleep(100);
756 : RunJS("custom_object.apiGetter;");
757 : }
758 : PrintStats();
759 :
760 2 : EXPECT_EQ(1, js_counter()->count());
761 2 : EXPECT_EQ(1, counter()->count());
762 2 : EXPECT_EQ(1, callback_counter->count());
763 2 : EXPECT_EQ(1, counter2()->count());
764 : // Given that no native timers are used, only the two scopes explitly
765 : // mentioned above will track the time.
766 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
767 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
768 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
769 2 : EXPECT_EQ(kCustomCallbackTime, counter2()->time().InMicroseconds());
770 :
771 : RunJS("for (let i = 0; i < 9; i++) { custom_object.apiGetter };");
772 : PrintStats();
773 :
774 2 : EXPECT_EQ(2, js_counter()->count());
775 2 : EXPECT_EQ(1, counter()->count());
776 2 : EXPECT_EQ(10, callback_counter->count());
777 2 : EXPECT_EQ(10, counter2()->count());
778 :
779 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
780 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
781 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
782 2 : EXPECT_EQ(kCustomCallbackTime * 10, counter2()->time().InMicroseconds());
783 :
784 : RunJS("for (let i = 0; i < 4000; i++) { custom_object.apiGetter };");
785 : PrintStats();
786 :
787 2 : EXPECT_EQ(3, js_counter()->count());
788 2 : EXPECT_EQ(1, counter()->count());
789 2 : EXPECT_EQ(4010, callback_counter->count());
790 2 : EXPECT_EQ(4010, counter2()->count());
791 :
792 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
793 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
794 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
795 2 : EXPECT_EQ(kCustomCallbackTime * 4010, counter2()->time().InMicroseconds());
796 :
797 : PrintStats();
798 1 : }
799 :
800 15445 : TEST_F(SnapshotNativeCounterTest, StringAddNative) {
801 : RunJS("let s = 'hello, ' + 'world!'");
802 :
803 : if (SupportsNativeCounters()) {
804 : EXPECT_NE(0, string_add_native());
805 : } else {
806 2 : EXPECT_EQ(0, string_add_native());
807 : }
808 :
809 1 : PrintAll();
810 1 : }
811 :
812 15445 : TEST_F(SnapshotNativeCounterTest, SubStringNative) {
813 : RunJS("'hello, world!'.substring(6);");
814 :
815 : if (SupportsNativeCounters()) {
816 : EXPECT_NE(0, sub_string_native());
817 : } else {
818 2 : EXPECT_EQ(0, sub_string_native());
819 : }
820 :
821 1 : PrintAll();
822 1 : }
823 :
824 15445 : TEST_F(SnapshotNativeCounterTest, WriteBarrier) {
825 : RunJS("let o = {a: 42};");
826 :
827 : if (SupportsNativeCounters()) {
828 : EXPECT_NE(0, write_barriers());
829 : } else {
830 2 : EXPECT_EQ(0, write_barriers());
831 : }
832 :
833 1 : PrintAll();
834 1 : }
835 :
836 : } // namespace internal
837 9264 : } // namespace v8
|
