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 : 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 28 : 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 : base::AsAtomic32::Relaxed_Store(
61 : &FLAG_runtime_stats,
62 : v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE);
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 : base::AsAtomic32::Relaxed_Store(&FLAG_runtime_stats, 0);
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 : } // namespace
152 :
153 :
154 15128 : TEST_F(AggregatedMemoryHistogramTest, OneSample1) {
155 1 : FLAG_histogram_interval = 10;
156 : AddSample(10, 1000);
157 : AddSample(20, 1000);
158 3 : EXPECT_EQ(1U, samples()->size());
159 2 : EXPECT_EQ(1000, (*samples())[0]);
160 1 : }
161 :
162 :
163 15128 : TEST_F(AggregatedMemoryHistogramTest, OneSample2) {
164 1 : FLAG_histogram_interval = 10;
165 : AddSample(10, 500);
166 : AddSample(20, 1000);
167 3 : EXPECT_EQ(1U, samples()->size());
168 2 : EXPECT_EQ(750, (*samples())[0]);
169 1 : }
170 :
171 :
172 15128 : TEST_F(AggregatedMemoryHistogramTest, OneSample3) {
173 1 : FLAG_histogram_interval = 10;
174 : AddSample(10, 500);
175 : AddSample(15, 500);
176 : AddSample(15, 1000);
177 : AddSample(20, 1000);
178 3 : EXPECT_EQ(1U, samples()->size());
179 2 : EXPECT_EQ(750, (*samples())[0]);
180 1 : }
181 :
182 :
183 15128 : TEST_F(AggregatedMemoryHistogramTest, OneSample4) {
184 1 : FLAG_histogram_interval = 10;
185 : AddSample(10, 500);
186 : AddSample(15, 750);
187 : AddSample(20, 1000);
188 3 : EXPECT_EQ(1U, samples()->size());
189 2 : EXPECT_EQ(750, (*samples())[0]);
190 1 : }
191 :
192 :
193 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples1) {
194 1 : FLAG_histogram_interval = 10;
195 : AddSample(10, 1000);
196 : AddSample(30, 1000);
197 3 : EXPECT_EQ(2U, samples()->size());
198 2 : EXPECT_EQ(1000, (*samples())[0]);
199 2 : EXPECT_EQ(1000, (*samples())[1]);
200 1 : }
201 :
202 :
203 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples2) {
204 1 : FLAG_histogram_interval = 10;
205 : AddSample(10, 1000);
206 : AddSample(20, 1000);
207 : AddSample(30, 1000);
208 3 : EXPECT_EQ(2U, samples()->size());
209 2 : EXPECT_EQ(1000, (*samples())[0]);
210 2 : EXPECT_EQ(1000, (*samples())[1]);
211 1 : }
212 :
213 :
214 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples3) {
215 1 : FLAG_histogram_interval = 10;
216 : AddSample(10, 1000);
217 : AddSample(20, 1000);
218 : AddSample(20, 500);
219 : AddSample(30, 500);
220 3 : EXPECT_EQ(2U, samples()->size());
221 2 : EXPECT_EQ(1000, (*samples())[0]);
222 2 : EXPECT_EQ(500, (*samples())[1]);
223 1 : }
224 :
225 :
226 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples4) {
227 1 : FLAG_histogram_interval = 10;
228 : AddSample(10, 1000);
229 : AddSample(30, 0);
230 3 : EXPECT_EQ(2U, samples()->size());
231 2 : EXPECT_EQ(750, (*samples())[0]);
232 2 : EXPECT_EQ(250, (*samples())[1]);
233 1 : }
234 :
235 :
236 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples5) {
237 1 : FLAG_histogram_interval = 10;
238 : AddSample(10, 0);
239 : AddSample(30, 1000);
240 3 : EXPECT_EQ(2U, samples()->size());
241 2 : EXPECT_EQ(250, (*samples())[0]);
242 2 : EXPECT_EQ(750, (*samples())[1]);
243 1 : }
244 :
245 :
246 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples6) {
247 1 : FLAG_histogram_interval = 10;
248 : AddSample(10, 0);
249 : AddSample(15, 1000);
250 : AddSample(30, 1000);
251 3 : EXPECT_EQ(2U, samples()->size());
252 2 : EXPECT_EQ((500 + 1000) / 2, (*samples())[0]);
253 2 : EXPECT_EQ(1000, (*samples())[1]);
254 1 : }
255 :
256 :
257 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples7) {
258 1 : FLAG_histogram_interval = 10;
259 : AddSample(10, 0);
260 : AddSample(15, 1000);
261 : AddSample(25, 0);
262 : AddSample(30, 1000);
263 3 : EXPECT_EQ(2U, samples()->size());
264 2 : EXPECT_EQ((500 + 750) / 2, (*samples())[0]);
265 2 : EXPECT_EQ((250 + 500) / 2, (*samples())[1]);
266 1 : }
267 :
268 :
269 15128 : TEST_F(AggregatedMemoryHistogramTest, TwoSamples8) {
270 1 : FLAG_histogram_interval = 10;
271 : AddSample(10, 1000);
272 : AddSample(15, 0);
273 : AddSample(25, 1000);
274 : AddSample(30, 0);
275 3 : EXPECT_EQ(2U, samples()->size());
276 2 : EXPECT_EQ((500 + 250) / 2, (*samples())[0]);
277 2 : EXPECT_EQ((750 + 500) / 2, (*samples())[1]);
278 1 : }
279 :
280 :
281 15128 : TEST_F(AggregatedMemoryHistogramTest, ManySamples1) {
282 1 : FLAG_histogram_interval = 10;
283 : const int kMaxSamples = 1000;
284 : AddSample(0, 0);
285 : AddSample(10 * kMaxSamples, 10 * kMaxSamples);
286 3 : EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
287 1001 : for (int i = 0; i < kMaxSamples; i++) {
288 3000 : EXPECT_EQ(i * 10 + 5, (*samples())[i]);
289 : }
290 1 : }
291 :
292 :
293 15128 : TEST_F(AggregatedMemoryHistogramTest, ManySamples2) {
294 1 : FLAG_histogram_interval = 10;
295 : const int kMaxSamples = 1000;
296 : AddSample(0, 0);
297 : AddSample(10 * (2 * kMaxSamples), 10 * (2 * kMaxSamples));
298 3 : EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
299 1001 : for (int i = 0; i < kMaxSamples; i++) {
300 3000 : EXPECT_EQ(i * 10 + 5, (*samples())[i]);
301 : }
302 1 : }
303 :
304 15128 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimer) {
305 : RuntimeCallTimer timer;
306 :
307 : Sleep(50);
308 1 : stats()->Enter(&timer, counter_id());
309 3 : EXPECT_EQ(counter(), timer.counter());
310 1 : EXPECT_EQ(nullptr, timer.parent());
311 1 : EXPECT_TRUE(timer.IsStarted());
312 2 : EXPECT_EQ(&timer, stats()->current_timer());
313 :
314 : Sleep(100);
315 :
316 1 : stats()->Leave(&timer);
317 : Sleep(50);
318 2 : EXPECT_FALSE(timer.IsStarted());
319 2 : EXPECT_EQ(1, counter()->count());
320 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
321 1 : }
322 :
323 15128 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerSubTimer) {
324 : RuntimeCallTimer timer;
325 : RuntimeCallTimer timer2;
326 :
327 1 : stats()->Enter(&timer, counter_id());
328 1 : EXPECT_TRUE(timer.IsStarted());
329 2 : EXPECT_FALSE(timer2.IsStarted());
330 3 : EXPECT_EQ(counter(), timer.counter());
331 1 : EXPECT_EQ(nullptr, timer.parent());
332 2 : EXPECT_EQ(&timer, stats()->current_timer());
333 :
334 : Sleep(50);
335 :
336 1 : stats()->Enter(&timer2, counter_id2());
337 : // timer 1 is paused, while timer 2 is active.
338 1 : EXPECT_TRUE(timer2.IsStarted());
339 3 : EXPECT_EQ(counter(), timer.counter());
340 3 : EXPECT_EQ(counter2(), timer2.counter());
341 1 : EXPECT_EQ(nullptr, timer.parent());
342 2 : EXPECT_EQ(&timer, timer2.parent());
343 2 : EXPECT_EQ(&timer2, stats()->current_timer());
344 :
345 : Sleep(100);
346 1 : stats()->Leave(&timer2);
347 :
348 : // The subtimer subtracts its time from the parent timer.
349 1 : EXPECT_TRUE(timer.IsStarted());
350 2 : EXPECT_FALSE(timer2.IsStarted());
351 2 : EXPECT_EQ(0, counter()->count());
352 2 : EXPECT_EQ(1, counter2()->count());
353 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
354 2 : EXPECT_EQ(100, counter2()->time().InMicroseconds());
355 2 : EXPECT_EQ(&timer, stats()->current_timer());
356 :
357 : Sleep(100);
358 :
359 1 : stats()->Leave(&timer);
360 2 : EXPECT_FALSE(timer.IsStarted());
361 2 : EXPECT_EQ(1, counter()->count());
362 2 : EXPECT_EQ(1, counter2()->count());
363 2 : EXPECT_EQ(150, counter()->time().InMicroseconds());
364 2 : EXPECT_EQ(100, counter2()->time().InMicroseconds());
365 1 : EXPECT_EQ(nullptr, stats()->current_timer());
366 1 : }
367 :
368 15128 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerRecursive) {
369 : RuntimeCallTimer timer;
370 : RuntimeCallTimer timer2;
371 :
372 1 : stats()->Enter(&timer, counter_id());
373 3 : EXPECT_EQ(counter(), timer.counter());
374 1 : EXPECT_EQ(nullptr, timer.parent());
375 1 : EXPECT_TRUE(timer.IsStarted());
376 2 : EXPECT_EQ(&timer, stats()->current_timer());
377 :
378 1 : stats()->Enter(&timer2, counter_id());
379 3 : EXPECT_EQ(counter(), timer2.counter());
380 1 : EXPECT_EQ(nullptr, timer.parent());
381 2 : EXPECT_EQ(&timer, timer2.parent());
382 1 : EXPECT_TRUE(timer2.IsStarted());
383 2 : EXPECT_EQ(&timer2, stats()->current_timer());
384 :
385 : Sleep(50);
386 :
387 1 : stats()->Leave(&timer2);
388 1 : EXPECT_EQ(nullptr, timer.parent());
389 2 : EXPECT_FALSE(timer2.IsStarted());
390 1 : EXPECT_TRUE(timer.IsStarted());
391 2 : EXPECT_EQ(1, counter()->count());
392 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
393 :
394 : Sleep(100);
395 :
396 1 : stats()->Leave(&timer);
397 2 : EXPECT_FALSE(timer.IsStarted());
398 2 : EXPECT_EQ(2, counter()->count());
399 2 : EXPECT_EQ(150, counter()->time().InMicroseconds());
400 1 : }
401 :
402 15128 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScope) {
403 : {
404 1 : RuntimeCallTimerScope scope(stats(), counter_id());
405 : Sleep(50);
406 : }
407 : Sleep(100);
408 2 : EXPECT_EQ(1, counter()->count());
409 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
410 : {
411 1 : RuntimeCallTimerScope scope(stats(), counter_id());
412 : Sleep(50);
413 : }
414 2 : EXPECT_EQ(2, counter()->count());
415 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
416 1 : }
417 :
418 15128 : TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) {
419 : {
420 1 : RuntimeCallTimerScope scope(stats(), counter_id());
421 : Sleep(50);
422 2 : EXPECT_EQ(0, counter()->count());
423 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
424 : {
425 1 : RuntimeCallTimerScope scope(stats(), counter_id());
426 : Sleep(50);
427 : }
428 2 : EXPECT_EQ(1, counter()->count());
429 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
430 : }
431 2 : EXPECT_EQ(2, counter()->count());
432 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
433 1 : }
434 :
435 15128 : TEST_F(RuntimeCallStatsTest, RenameTimer) {
436 : {
437 1 : RuntimeCallTimerScope scope(stats(), counter_id());
438 : Sleep(50);
439 2 : EXPECT_EQ(0, counter()->count());
440 2 : EXPECT_EQ(0, counter2()->count());
441 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
442 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
443 : {
444 1 : RuntimeCallTimerScope scope(stats(), counter_id());
445 : Sleep(100);
446 : }
447 3 : CHANGE_CURRENT_RUNTIME_COUNTER(stats(),
448 : RuntimeCallCounterId::kTestCounter2);
449 2 : EXPECT_EQ(1, counter()->count());
450 2 : EXPECT_EQ(0, counter2()->count());
451 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
452 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
453 : }
454 2 : EXPECT_EQ(1, counter()->count());
455 2 : EXPECT_EQ(1, counter2()->count());
456 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
457 2 : EXPECT_EQ(50, counter2()->time().InMicroseconds());
458 1 : }
459 :
460 15128 : TEST_F(RuntimeCallStatsTest, BasicPrintAndSnapshot) {
461 1 : std::ostringstream out;
462 1 : stats()->Print(out);
463 2 : EXPECT_EQ(0, counter()->count());
464 2 : EXPECT_EQ(0, counter2()->count());
465 2 : EXPECT_EQ(0, counter3()->count());
466 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
467 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
468 2 : EXPECT_EQ(0, counter3()->time().InMicroseconds());
469 :
470 : {
471 1 : RuntimeCallTimerScope scope(stats(), counter_id());
472 : Sleep(50);
473 1 : stats()->Print(out);
474 : }
475 1 : stats()->Print(out);
476 2 : EXPECT_EQ(1, counter()->count());
477 2 : EXPECT_EQ(0, counter2()->count());
478 2 : EXPECT_EQ(0, counter3()->count());
479 2 : EXPECT_EQ(50, counter()->time().InMicroseconds());
480 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
481 3 : EXPECT_EQ(0, counter3()->time().InMicroseconds());
482 1 : }
483 :
484 15128 : TEST_F(RuntimeCallStatsTest, PrintAndSnapshot) {
485 : {
486 1 : RuntimeCallTimerScope scope(stats(), counter_id());
487 : Sleep(100);
488 2 : EXPECT_EQ(0, counter()->count());
489 2 : EXPECT_EQ(0, counter()->time().InMicroseconds());
490 : {
491 1 : RuntimeCallTimerScope scope(stats(), counter_id2());
492 2 : EXPECT_EQ(0, counter2()->count());
493 2 : EXPECT_EQ(0, counter2()->time().InMicroseconds());
494 : Sleep(50);
495 :
496 : // This calls Snapshot on the current active timer and sychronizes and
497 : // commits the whole timer stack.
498 1 : std::ostringstream out;
499 1 : stats()->Print(out);
500 2 : EXPECT_EQ(0, counter()->count());
501 2 : EXPECT_EQ(0, counter2()->count());
502 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
503 2 : EXPECT_EQ(50, counter2()->time().InMicroseconds());
504 : // Calling Print several times shouldn't have a (big) impact on the
505 : // measured times.
506 1 : stats()->Print(out);
507 2 : EXPECT_EQ(0, counter()->count());
508 2 : EXPECT_EQ(0, counter2()->count());
509 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
510 2 : EXPECT_EQ(50, counter2()->time().InMicroseconds());
511 :
512 : Sleep(50);
513 1 : stats()->Print(out);
514 2 : EXPECT_EQ(0, counter()->count());
515 2 : EXPECT_EQ(0, counter2()->count());
516 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
517 2 : EXPECT_EQ(100, counter2()->time().InMicroseconds());
518 1 : Sleep(50);
519 : }
520 : Sleep(50);
521 2 : EXPECT_EQ(0, counter()->count());
522 2 : EXPECT_EQ(1, counter2()->count());
523 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
524 2 : EXPECT_EQ(150, counter2()->time().InMicroseconds());
525 : Sleep(50);
526 : }
527 2 : EXPECT_EQ(1, counter()->count());
528 2 : EXPECT_EQ(1, counter2()->count());
529 2 : EXPECT_EQ(200, counter()->time().InMicroseconds());
530 2 : EXPECT_EQ(150, counter2()->time().InMicroseconds());
531 1 : }
532 :
533 15128 : TEST_F(RuntimeCallStatsTest, NestedScopes) {
534 : {
535 1 : RuntimeCallTimerScope scope(stats(), counter_id());
536 : Sleep(100);
537 : {
538 1 : RuntimeCallTimerScope scope(stats(), counter_id2());
539 : Sleep(100);
540 : {
541 1 : RuntimeCallTimerScope scope(stats(), counter_id3());
542 : Sleep(50);
543 : }
544 : Sleep(50);
545 : {
546 1 : RuntimeCallTimerScope scope(stats(), counter_id3());
547 : Sleep(50);
548 : }
549 : Sleep(50);
550 : }
551 : Sleep(100);
552 : {
553 1 : RuntimeCallTimerScope scope(stats(), counter_id2());
554 : Sleep(100);
555 : }
556 : Sleep(50);
557 : }
558 2 : EXPECT_EQ(1, counter()->count());
559 2 : EXPECT_EQ(2, counter2()->count());
560 2 : EXPECT_EQ(2, counter3()->count());
561 2 : EXPECT_EQ(250, counter()->time().InMicroseconds());
562 2 : EXPECT_EQ(300, counter2()->time().InMicroseconds());
563 2 : EXPECT_EQ(100, counter3()->time().InMicroseconds());
564 1 : }
565 :
566 15128 : TEST_F(RuntimeCallStatsTest, BasicJavaScript) {
567 6 : RuntimeCallCounter* counter =
568 : stats()->GetCounter(RuntimeCallCounterId::kJS_Execution);
569 2 : EXPECT_EQ(0, counter->count());
570 2 : EXPECT_EQ(0, counter->time().InMicroseconds());
571 :
572 : {
573 1 : NativeTimeScope native_timer_scope;
574 1 : RunJS("function f() { return 1; };");
575 : }
576 2 : EXPECT_EQ(1, counter->count());
577 1 : int64_t time = counter->time().InMicroseconds();
578 1 : EXPECT_LT(0, time);
579 :
580 : {
581 1 : NativeTimeScope native_timer_scope;
582 1 : RunJS("f();");
583 : }
584 2 : EXPECT_EQ(2, counter->count());
585 1 : EXPECT_LE(time, counter->time().InMicroseconds());
586 1 : }
587 :
588 15128 : TEST_F(RuntimeCallStatsTest, FunctionLengthGetter) {
589 8 : RuntimeCallCounter* getter_counter =
590 : stats()->GetCounter(RuntimeCallCounterId::kFunctionLengthGetter);
591 2 : EXPECT_EQ(0, getter_counter->count());
592 2 : EXPECT_EQ(0, js_counter()->count());
593 2 : EXPECT_EQ(0, getter_counter->time().InMicroseconds());
594 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
595 :
596 : {
597 1 : NativeTimeScope native_timer_scope;
598 1 : RunJS("function f(array) { return array.length; };");
599 : }
600 2 : EXPECT_EQ(0, getter_counter->count());
601 2 : EXPECT_EQ(1, js_counter()->count());
602 2 : EXPECT_EQ(0, getter_counter->time().InMicroseconds());
603 1 : int64_t js_time = js_counter()->time().InMicroseconds();
604 1 : EXPECT_LT(0, js_time);
605 :
606 : {
607 1 : NativeTimeScope native_timer_scope;
608 1 : RunJS("f.length;");
609 : }
610 2 : EXPECT_EQ(1, getter_counter->count());
611 2 : EXPECT_EQ(2, js_counter()->count());
612 1 : EXPECT_LE(0, getter_counter->time().InMicroseconds());
613 1 : EXPECT_LE(js_time, js_counter()->time().InMicroseconds());
614 :
615 : {
616 1 : NativeTimeScope native_timer_scope;
617 1 : RunJS("for (let i = 0; i < 50; i++) { f.length };");
618 : }
619 2 : EXPECT_EQ(51, getter_counter->count());
620 2 : EXPECT_EQ(3, js_counter()->count());
621 :
622 : {
623 1 : NativeTimeScope native_timer_scope;
624 1 : RunJS("for (let i = 0; i < 1000; i++) { f.length; };");
625 : }
626 2 : EXPECT_EQ(1051, getter_counter->count());
627 2 : EXPECT_EQ(4, js_counter()->count());
628 1 : }
629 :
630 : namespace {
631 : static RuntimeCallStatsTest* current_test;
632 : static const int kCustomCallbackTime = 1234;
633 8020 : static void CustomCallback(const v8::FunctionCallbackInfo<v8::Value>& info) {
634 : RuntimeCallTimerScope scope(current_test->stats(),
635 8020 : current_test->counter_id2());
636 8020 : current_test->Sleep(kCustomCallbackTime);
637 8020 : }
638 : } // namespace
639 :
640 15128 : TEST_F(RuntimeCallStatsTest, CallbackFunction) {
641 7 : RuntimeCallCounter* callback_counter =
642 : stats()->GetCounter(RuntimeCallCounterId::kFunctionCallback);
643 :
644 1 : current_test = this;
645 : // Set up a function template with a custom callback.
646 : v8::Isolate* isolate = v8_isolate();
647 1 : v8::HandleScope scope(isolate);
648 :
649 : v8::Local<v8::ObjectTemplate> object_template =
650 1 : v8::ObjectTemplate::New(isolate);
651 : object_template->Set(isolate, "callback",
652 2 : v8::FunctionTemplate::New(isolate, CustomCallback));
653 : v8::Local<v8::Object> object =
654 1 : object_template->NewInstance(v8_context()).ToLocalChecked();
655 1 : SetGlobalProperty("custom_object", object);
656 :
657 2 : EXPECT_EQ(0, js_counter()->count());
658 2 : EXPECT_EQ(0, counter()->count());
659 2 : EXPECT_EQ(0, callback_counter->count());
660 2 : EXPECT_EQ(0, counter2()->count());
661 : {
662 1 : RuntimeCallTimerScope scope(stats(), counter_id());
663 : Sleep(100);
664 1 : RunJS("custom_object.callback();");
665 : }
666 2 : EXPECT_EQ(1, js_counter()->count());
667 2 : EXPECT_EQ(1, counter()->count());
668 2 : EXPECT_EQ(1, callback_counter->count());
669 2 : EXPECT_EQ(1, counter2()->count());
670 : // Given that no native timers are used, only the two scopes explitly
671 : // mentioned above will track the time.
672 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
673 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
674 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
675 2 : EXPECT_EQ(kCustomCallbackTime, counter2()->time().InMicroseconds());
676 :
677 1 : RunJS("for (let i = 0; i < 9; i++) { custom_object.callback(); };");
678 2 : EXPECT_EQ(2, js_counter()->count());
679 2 : EXPECT_EQ(1, counter()->count());
680 2 : EXPECT_EQ(10, callback_counter->count());
681 2 : EXPECT_EQ(10, counter2()->count());
682 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
683 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
684 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
685 2 : EXPECT_EQ(kCustomCallbackTime * 10, counter2()->time().InMicroseconds());
686 :
687 1 : RunJS("for (let i = 0; i < 4000; i++) { custom_object.callback(); };");
688 2 : EXPECT_EQ(3, js_counter()->count());
689 2 : EXPECT_EQ(1, counter()->count());
690 2 : EXPECT_EQ(4010, callback_counter->count());
691 2 : EXPECT_EQ(4010, counter2()->count());
692 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
693 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
694 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
695 3 : EXPECT_EQ(kCustomCallbackTime * 4010, counter2()->time().InMicroseconds());
696 1 : }
697 :
698 15128 : TEST_F(RuntimeCallStatsTest, ApiGetter) {
699 7 : RuntimeCallCounter* callback_counter =
700 : stats()->GetCounter(RuntimeCallCounterId::kFunctionCallback);
701 1 : current_test = this;
702 : // Set up a function template with an api accessor.
703 : v8::Isolate* isolate = v8_isolate();
704 1 : v8::HandleScope scope(isolate);
705 :
706 : v8::Local<v8::ObjectTemplate> object_template =
707 1 : v8::ObjectTemplate::New(isolate);
708 : object_template->SetAccessorProperty(
709 : NewString("apiGetter"),
710 2 : v8::FunctionTemplate::New(isolate, CustomCallback));
711 : v8::Local<v8::Object> object =
712 1 : object_template->NewInstance(v8_context()).ToLocalChecked();
713 1 : SetGlobalProperty("custom_object", object);
714 :
715 : // TODO(cbruni): Check api accessor timer (one above the custom callback).
716 2 : EXPECT_EQ(0, js_counter()->count());
717 2 : EXPECT_EQ(0, counter()->count());
718 2 : EXPECT_EQ(0, callback_counter->count());
719 2 : EXPECT_EQ(0, counter2()->count());
720 :
721 : {
722 1 : RuntimeCallTimerScope scope(stats(), counter_id());
723 : Sleep(100);
724 1 : RunJS("custom_object.apiGetter;");
725 : }
726 : PrintStats();
727 :
728 2 : EXPECT_EQ(1, js_counter()->count());
729 2 : EXPECT_EQ(1, counter()->count());
730 2 : EXPECT_EQ(1, callback_counter->count());
731 2 : EXPECT_EQ(1, counter2()->count());
732 : // Given that no native timers are used, only the two scopes explitly
733 : // mentioned above will track the time.
734 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
735 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
736 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
737 2 : EXPECT_EQ(kCustomCallbackTime, counter2()->time().InMicroseconds());
738 :
739 1 : RunJS("for (let i = 0; i < 9; i++) { custom_object.apiGetter };");
740 : PrintStats();
741 :
742 2 : EXPECT_EQ(2, js_counter()->count());
743 2 : EXPECT_EQ(1, counter()->count());
744 2 : EXPECT_EQ(10, callback_counter->count());
745 2 : EXPECT_EQ(10, counter2()->count());
746 :
747 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
748 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
749 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
750 2 : EXPECT_EQ(kCustomCallbackTime * 10, counter2()->time().InMicroseconds());
751 :
752 1 : RunJS("for (let i = 0; i < 4000; i++) { custom_object.apiGetter };");
753 : PrintStats();
754 :
755 2 : EXPECT_EQ(3, js_counter()->count());
756 2 : EXPECT_EQ(1, counter()->count());
757 2 : EXPECT_EQ(4010, callback_counter->count());
758 2 : EXPECT_EQ(4010, counter2()->count());
759 :
760 2 : EXPECT_EQ(0, js_counter()->time().InMicroseconds());
761 2 : EXPECT_EQ(100, counter()->time().InMicroseconds());
762 2 : EXPECT_EQ(0, callback_counter->time().InMicroseconds());
763 2 : EXPECT_EQ(kCustomCallbackTime * 4010, counter2()->time().InMicroseconds());
764 :
765 1 : PrintStats();
766 1 : }
767 :
768 : } // namespace internal
769 9075 : } // namespace v8
|
