1 // Copyright (c) 2012 The Chromium 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 // Test of classes in the tracked_objects.h classes.
6
7 #include "base/tracked_objects.h"
8
9 #include <stddef.h>
10 #include <stdint.h>
11
12 #include <memory>
13
14 #include "base/process/process_handle.h"
15 #include "base/time/time.h"
16 #include "base/tracking_info.h"
17 #include "testing/gtest/include/gtest/gtest.h"
18
19 const int kLineNumber = 1776;
20 const char kFile[] = "FixedUnitTestFileName";
21 const char kWorkerThreadName[] = "WorkerThread-1";
22 const char kMainThreadName[] = "SomeMainThreadName";
23 const char kStillAlive[] = "Still_Alive";
24
25 namespace tracked_objects {
26
27 class TrackedObjectsTest : public testing::Test {
28 protected:
TrackedObjectsTest()29 TrackedObjectsTest() {
30 // On entry, leak any database structures in case they are still in use by
31 // prior threads.
32 ThreadData::ShutdownSingleThreadedCleanup(true);
33
34 test_time_ = 0;
35 ThreadData::now_function_for_testing_ = &TrackedObjectsTest::GetTestTime;
36 }
37
~TrackedObjectsTest()38 ~TrackedObjectsTest() override {
39 // We should not need to leak any structures we create, since we are
40 // single threaded, and carefully accounting for items.
41 ThreadData::ShutdownSingleThreadedCleanup(false);
42 }
43
44 // Reset the profiler state.
Reset()45 void Reset() {
46 ThreadData::ShutdownSingleThreadedCleanup(false);
47 test_time_ = 0;
48 }
49
50 // Simulate a birth on the thread named |thread_name|, at the given
51 // |location|.
TallyABirth(const Location & location,const std::string & thread_name)52 void TallyABirth(const Location& location, const std::string& thread_name) {
53 // If the |thread_name| is empty, we don't initialize system with a thread
54 // name, so we're viewed as a worker thread.
55 if (!thread_name.empty())
56 ThreadData::InitializeThreadContext(kMainThreadName);
57
58 // Do not delete |birth|. We don't own it.
59 Births* birth = ThreadData::TallyABirthIfActive(location);
60
61 if (ThreadData::status() == ThreadData::DEACTIVATED)
62 EXPECT_EQ(reinterpret_cast<Births*>(NULL), birth);
63 else
64 EXPECT_NE(reinterpret_cast<Births*>(NULL), birth);
65 }
66
67 // Helper function to verify the most common test expectations.
ExpectSimpleProcessData(const ProcessDataSnapshot & process_data,const std::string & function_name,const std::string & birth_thread,const std::string & death_thread,int count,int run_ms,int queue_ms)68 void ExpectSimpleProcessData(const ProcessDataSnapshot& process_data,
69 const std::string& function_name,
70 const std::string& birth_thread,
71 const std::string& death_thread,
72 int count,
73 int run_ms,
74 int queue_ms) {
75 ASSERT_EQ(1u, process_data.phased_snapshots.size());
76 auto it = process_data.phased_snapshots.find(0);
77 ASSERT_TRUE(it != process_data.phased_snapshots.end());
78 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
79
80 ASSERT_EQ(1u, process_data_phase.tasks.size());
81
82 EXPECT_EQ(kFile, process_data_phase.tasks[0].birth.location.file_name);
83 EXPECT_EQ(function_name,
84 process_data_phase.tasks[0].birth.location.function_name);
85 EXPECT_EQ(kLineNumber,
86 process_data_phase.tasks[0].birth.location.line_number);
87
88 EXPECT_EQ(birth_thread, process_data_phase.tasks[0].birth.thread_name);
89
90 EXPECT_EQ(count, process_data_phase.tasks[0].death_data.count);
91 EXPECT_EQ(count * run_ms,
92 process_data_phase.tasks[0].death_data.run_duration_sum);
93 EXPECT_EQ(run_ms, process_data_phase.tasks[0].death_data.run_duration_max);
94 EXPECT_EQ(run_ms,
95 process_data_phase.tasks[0].death_data.run_duration_sample);
96 EXPECT_EQ(count * queue_ms,
97 process_data_phase.tasks[0].death_data.queue_duration_sum);
98 EXPECT_EQ(queue_ms,
99 process_data_phase.tasks[0].death_data.queue_duration_max);
100 EXPECT_EQ(queue_ms,
101 process_data_phase.tasks[0].death_data.queue_duration_sample);
102
103 EXPECT_EQ(death_thread, process_data_phase.tasks[0].death_thread_name);
104
105 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
106 }
107
108 // Sets time that will be returned by ThreadData::Now().
SetTestTime(unsigned int test_time)109 static void SetTestTime(unsigned int test_time) { test_time_ = test_time; }
110
111 private:
112 // Returns test time in milliseconds.
GetTestTime()113 static unsigned int GetTestTime() { return test_time_; }
114
115 // Test time in milliseconds.
116 static unsigned int test_time_;
117 };
118
119 // static
120 unsigned int TrackedObjectsTest::test_time_;
121
TEST_F(TrackedObjectsTest,TaskStopwatchNoStartStop)122 TEST_F(TrackedObjectsTest, TaskStopwatchNoStartStop) {
123 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
124
125 // Check that creating and destroying a stopwatch without starting it doesn't
126 // crash.
127 TaskStopwatch stopwatch;
128 }
129
TEST_F(TrackedObjectsTest,MinimalStartupShutdown)130 TEST_F(TrackedObjectsTest, MinimalStartupShutdown) {
131 // Minimal test doesn't even create any tasks.
132 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
133
134 EXPECT_FALSE(ThreadData::first()); // No activity even on this thread.
135 ThreadData* data = ThreadData::Get();
136 EXPECT_TRUE(ThreadData::first()); // Now class was constructed.
137 ASSERT_TRUE(data);
138 EXPECT_FALSE(data->next());
139 EXPECT_EQ(data, ThreadData::Get());
140 ThreadData::BirthMap birth_map;
141 ThreadData::DeathsSnapshot deaths;
142 data->SnapshotMaps(0, &birth_map, &deaths);
143 EXPECT_EQ(0u, birth_map.size());
144 EXPECT_EQ(0u, deaths.size());
145
146 // Clean up with no leaking.
147 Reset();
148
149 // Do it again, just to be sure we reset state completely.
150 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
151 EXPECT_FALSE(ThreadData::first()); // No activity even on this thread.
152 data = ThreadData::Get();
153 EXPECT_TRUE(ThreadData::first()); // Now class was constructed.
154 ASSERT_TRUE(data);
155 EXPECT_FALSE(data->next());
156 EXPECT_EQ(data, ThreadData::Get());
157 birth_map.clear();
158 deaths.clear();
159 data->SnapshotMaps(0, &birth_map, &deaths);
160 EXPECT_EQ(0u, birth_map.size());
161 EXPECT_EQ(0u, deaths.size());
162 }
163
TEST_F(TrackedObjectsTest,TinyStartupShutdown)164 TEST_F(TrackedObjectsTest, TinyStartupShutdown) {
165 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
166
167 // Instigate tracking on a single tracked object, on our thread.
168 const char kFunction[] = "TinyStartupShutdown";
169 Location location(kFunction, kFile, kLineNumber, NULL);
170 ThreadData::TallyABirthIfActive(location);
171
172 ThreadData* data = ThreadData::first();
173 ASSERT_TRUE(data);
174 EXPECT_FALSE(data->next());
175 EXPECT_EQ(data, ThreadData::Get());
176 ThreadData::BirthMap birth_map;
177 ThreadData::DeathsSnapshot deaths;
178 data->SnapshotMaps(0, &birth_map, &deaths);
179 EXPECT_EQ(1u, birth_map.size()); // 1 birth location.
180 EXPECT_EQ(1, birth_map.begin()->second->birth_count()); // 1 birth.
181 EXPECT_EQ(0u, deaths.size()); // No deaths.
182
183
184 // Now instigate another birth, while we are timing the run of the first
185 // execution.
186 // Create a child (using the same birth location).
187 // TrackingInfo will call TallyABirth() during construction.
188 const int32_t start_time = 1;
189 base::TimeTicks kBogusBirthTime = base::TimeTicks() +
190 base::TimeDelta::FromMilliseconds(start_time);
191 base::TrackingInfo pending_task(location, kBogusBirthTime);
192 SetTestTime(1);
193 TaskStopwatch stopwatch;
194 stopwatch.Start();
195 // Finally conclude the outer run.
196 const int32_t time_elapsed = 1000;
197 SetTestTime(start_time + time_elapsed);
198 stopwatch.Stop();
199
200 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
201
202 birth_map.clear();
203 deaths.clear();
204 data->SnapshotMaps(0, &birth_map, &deaths);
205 EXPECT_EQ(1u, birth_map.size()); // 1 birth location.
206 EXPECT_EQ(2, birth_map.begin()->second->birth_count()); // 2 births.
207 EXPECT_EQ(1u, deaths.size()); // 1 location.
208 EXPECT_EQ(1, deaths.begin()->second.death_data.count); // 1 death.
209
210 // The births were at the same location as the one known death.
211 EXPECT_EQ(birth_map.begin()->second, deaths.begin()->first);
212
213 ProcessDataSnapshot process_data;
214 ThreadData::Snapshot(0, &process_data);
215
216 ASSERT_EQ(1u, process_data.phased_snapshots.size());
217 auto it = process_data.phased_snapshots.find(0);
218 ASSERT_TRUE(it != process_data.phased_snapshots.end());
219 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
220 ASSERT_EQ(1u, process_data_phase.tasks.size());
221 EXPECT_EQ(kFile, process_data_phase.tasks[0].birth.location.file_name);
222 EXPECT_EQ(kFunction,
223 process_data_phase.tasks[0].birth.location.function_name);
224 EXPECT_EQ(kLineNumber,
225 process_data_phase.tasks[0].birth.location.line_number);
226 EXPECT_EQ(kWorkerThreadName, process_data_phase.tasks[0].birth.thread_name);
227 EXPECT_EQ(1, process_data_phase.tasks[0].death_data.count);
228 EXPECT_EQ(time_elapsed,
229 process_data_phase.tasks[0].death_data.run_duration_sum);
230 EXPECT_EQ(time_elapsed,
231 process_data_phase.tasks[0].death_data.run_duration_max);
232 EXPECT_EQ(time_elapsed,
233 process_data_phase.tasks[0].death_data.run_duration_sample);
234 EXPECT_EQ(0, process_data_phase.tasks[0].death_data.queue_duration_sum);
235 EXPECT_EQ(0, process_data_phase.tasks[0].death_data.queue_duration_max);
236 EXPECT_EQ(0, process_data_phase.tasks[0].death_data.queue_duration_sample);
237 EXPECT_EQ(kWorkerThreadName, process_data_phase.tasks[0].death_thread_name);
238 }
239
TEST_F(TrackedObjectsTest,DeathDataTestRecordDeath)240 TEST_F(TrackedObjectsTest, DeathDataTestRecordDeath) {
241 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
242
243 std::unique_ptr<DeathData> data(new DeathData());
244 ASSERT_NE(data, nullptr);
245 EXPECT_EQ(data->run_duration_sum(), 0);
246 EXPECT_EQ(data->run_duration_max(), 0);
247 EXPECT_EQ(data->run_duration_sample(), 0);
248 EXPECT_EQ(data->queue_duration_sum(), 0);
249 EXPECT_EQ(data->queue_duration_max(), 0);
250 EXPECT_EQ(data->queue_duration_sample(), 0);
251 EXPECT_EQ(data->count(), 0);
252 EXPECT_EQ(nullptr, data->last_phase_snapshot());
253
254 int32_t run_ms = 42;
255 int32_t queue_ms = 8;
256
257 const int kUnrandomInt = 0; // Fake random int that ensure we sample data.
258 data->RecordDeath(queue_ms, run_ms, kUnrandomInt);
259 EXPECT_EQ(data->run_duration_sum(), run_ms);
260 EXPECT_EQ(data->run_duration_max(), run_ms);
261 EXPECT_EQ(data->run_duration_sample(), run_ms);
262 EXPECT_EQ(data->queue_duration_sum(), queue_ms);
263 EXPECT_EQ(data->queue_duration_max(), queue_ms);
264 EXPECT_EQ(data->queue_duration_sample(), queue_ms);
265 EXPECT_EQ(data->count(), 1);
266 EXPECT_EQ(nullptr, data->last_phase_snapshot());
267
268 data->RecordDeath(queue_ms, run_ms, kUnrandomInt);
269 EXPECT_EQ(data->run_duration_sum(), run_ms + run_ms);
270 EXPECT_EQ(data->run_duration_max(), run_ms);
271 EXPECT_EQ(data->run_duration_sample(), run_ms);
272 EXPECT_EQ(data->queue_duration_sum(), queue_ms + queue_ms);
273 EXPECT_EQ(data->queue_duration_max(), queue_ms);
274 EXPECT_EQ(data->queue_duration_sample(), queue_ms);
275 EXPECT_EQ(data->count(), 2);
276 EXPECT_EQ(nullptr, data->last_phase_snapshot());
277 }
278
TEST_F(TrackedObjectsTest,DeathDataTest2Phases)279 TEST_F(TrackedObjectsTest, DeathDataTest2Phases) {
280 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
281
282 std::unique_ptr<DeathData> data(new DeathData());
283 ASSERT_NE(data, nullptr);
284
285 int32_t run_ms = 42;
286 int32_t queue_ms = 8;
287
288 const int kUnrandomInt = 0; // Fake random int that ensure we sample data.
289 data->RecordDeath(queue_ms, run_ms, kUnrandomInt);
290 data->RecordDeath(queue_ms, run_ms, kUnrandomInt);
291
292 data->OnProfilingPhaseCompleted(123);
293 EXPECT_EQ(data->run_duration_sum(), run_ms + run_ms);
294 EXPECT_EQ(data->run_duration_max(), 0);
295 EXPECT_EQ(data->run_duration_sample(), run_ms);
296 EXPECT_EQ(data->queue_duration_sum(), queue_ms + queue_ms);
297 EXPECT_EQ(data->queue_duration_max(), 0);
298 EXPECT_EQ(data->queue_duration_sample(), queue_ms);
299 EXPECT_EQ(data->count(), 2);
300 ASSERT_NE(nullptr, data->last_phase_snapshot());
301 EXPECT_EQ(123, data->last_phase_snapshot()->profiling_phase);
302 EXPECT_EQ(2, data->last_phase_snapshot()->death_data.count);
303 EXPECT_EQ(2 * run_ms,
304 data->last_phase_snapshot()->death_data.run_duration_sum);
305 EXPECT_EQ(run_ms, data->last_phase_snapshot()->death_data.run_duration_max);
306 EXPECT_EQ(run_ms,
307 data->last_phase_snapshot()->death_data.run_duration_sample);
308 EXPECT_EQ(2 * queue_ms,
309 data->last_phase_snapshot()->death_data.queue_duration_sum);
310 EXPECT_EQ(queue_ms,
311 data->last_phase_snapshot()->death_data.queue_duration_max);
312 EXPECT_EQ(queue_ms,
313 data->last_phase_snapshot()->death_data.queue_duration_sample);
314 EXPECT_EQ(nullptr, data->last_phase_snapshot()->prev);
315
316 int32_t run_ms1 = 21;
317 int32_t queue_ms1 = 4;
318
319 data->RecordDeath(queue_ms1, run_ms1, kUnrandomInt);
320 EXPECT_EQ(data->run_duration_sum(), run_ms + run_ms + run_ms1);
321 EXPECT_EQ(data->run_duration_max(), run_ms1);
322 EXPECT_EQ(data->run_duration_sample(), run_ms1);
323 EXPECT_EQ(data->queue_duration_sum(), queue_ms + queue_ms + queue_ms1);
324 EXPECT_EQ(data->queue_duration_max(), queue_ms1);
325 EXPECT_EQ(data->queue_duration_sample(), queue_ms1);
326 EXPECT_EQ(data->count(), 3);
327 ASSERT_NE(nullptr, data->last_phase_snapshot());
328 EXPECT_EQ(123, data->last_phase_snapshot()->profiling_phase);
329 EXPECT_EQ(2, data->last_phase_snapshot()->death_data.count);
330 EXPECT_EQ(2 * run_ms,
331 data->last_phase_snapshot()->death_data.run_duration_sum);
332 EXPECT_EQ(run_ms, data->last_phase_snapshot()->death_data.run_duration_max);
333 EXPECT_EQ(run_ms,
334 data->last_phase_snapshot()->death_data.run_duration_sample);
335 EXPECT_EQ(2 * queue_ms,
336 data->last_phase_snapshot()->death_data.queue_duration_sum);
337 EXPECT_EQ(queue_ms,
338 data->last_phase_snapshot()->death_data.queue_duration_max);
339 EXPECT_EQ(queue_ms,
340 data->last_phase_snapshot()->death_data.queue_duration_sample);
341 EXPECT_EQ(nullptr, data->last_phase_snapshot()->prev);
342 }
343
TEST_F(TrackedObjectsTest,Delta)344 TEST_F(TrackedObjectsTest, Delta) {
345 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
346
347 DeathDataSnapshot snapshot;
348 snapshot.count = 10;
349 snapshot.run_duration_sum = 100;
350 snapshot.run_duration_max = 50;
351 snapshot.run_duration_sample = 25;
352 snapshot.queue_duration_sum = 200;
353 snapshot.queue_duration_max = 101;
354 snapshot.queue_duration_sample = 26;
355
356 DeathDataSnapshot older_snapshot;
357 older_snapshot.count = 2;
358 older_snapshot.run_duration_sum = 95;
359 older_snapshot.run_duration_max = 48;
360 older_snapshot.run_duration_sample = 22;
361 older_snapshot.queue_duration_sum = 190;
362 older_snapshot.queue_duration_max = 99;
363 older_snapshot.queue_duration_sample = 21;
364
365 const DeathDataSnapshot& delta = snapshot.Delta(older_snapshot);
366 EXPECT_EQ(8, delta.count);
367 EXPECT_EQ(5, delta.run_duration_sum);
368 EXPECT_EQ(50, delta.run_duration_max);
369 EXPECT_EQ(25, delta.run_duration_sample);
370 EXPECT_EQ(10, delta.queue_duration_sum);
371 EXPECT_EQ(101, delta.queue_duration_max);
372 EXPECT_EQ(26, delta.queue_duration_sample);
373 }
374
TEST_F(TrackedObjectsTest,DeactivatedBirthOnlyToSnapshotWorkerThread)375 TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToSnapshotWorkerThread) {
376 // Start in the deactivated state.
377 ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED);
378
379 const char kFunction[] = "DeactivatedBirthOnlyToSnapshotWorkerThread";
380 Location location(kFunction, kFile, kLineNumber, NULL);
381 TallyABirth(location, std::string());
382
383 ProcessDataSnapshot process_data;
384 ThreadData::Snapshot(0, &process_data);
385
386 ASSERT_EQ(1u, process_data.phased_snapshots.size());
387
388 auto it = process_data.phased_snapshots.find(0);
389 ASSERT_TRUE(it != process_data.phased_snapshots.end());
390 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
391
392 ASSERT_EQ(0u, process_data_phase.tasks.size());
393
394 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
395 }
396
TEST_F(TrackedObjectsTest,DeactivatedBirthOnlyToSnapshotMainThread)397 TEST_F(TrackedObjectsTest, DeactivatedBirthOnlyToSnapshotMainThread) {
398 // Start in the deactivated state.
399 ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED);
400
401 const char kFunction[] = "DeactivatedBirthOnlyToSnapshotMainThread";
402 Location location(kFunction, kFile, kLineNumber, NULL);
403 TallyABirth(location, kMainThreadName);
404
405 ProcessDataSnapshot process_data;
406 ThreadData::Snapshot(0, &process_data);
407
408 ASSERT_EQ(1u, process_data.phased_snapshots.size());
409
410 auto it = process_data.phased_snapshots.find(0);
411 ASSERT_TRUE(it != process_data.phased_snapshots.end());
412 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
413
414 ASSERT_EQ(0u, process_data_phase.tasks.size());
415
416 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
417 }
418
TEST_F(TrackedObjectsTest,BirthOnlyToSnapshotWorkerThread)419 TEST_F(TrackedObjectsTest, BirthOnlyToSnapshotWorkerThread) {
420 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
421
422 const char kFunction[] = "BirthOnlyToSnapshotWorkerThread";
423 Location location(kFunction, kFile, kLineNumber, NULL);
424 TallyABirth(location, std::string());
425
426 ProcessDataSnapshot process_data;
427 ThreadData::Snapshot(0, &process_data);
428 ExpectSimpleProcessData(process_data, kFunction, kWorkerThreadName,
429 kStillAlive, 1, 0, 0);
430 }
431
TEST_F(TrackedObjectsTest,BirthOnlyToSnapshotMainThread)432 TEST_F(TrackedObjectsTest, BirthOnlyToSnapshotMainThread) {
433 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
434
435 const char kFunction[] = "BirthOnlyToSnapshotMainThread";
436 Location location(kFunction, kFile, kLineNumber, NULL);
437 TallyABirth(location, kMainThreadName);
438
439 ProcessDataSnapshot process_data;
440 ThreadData::Snapshot(0, &process_data);
441 ExpectSimpleProcessData(process_data, kFunction, kMainThreadName, kStillAlive,
442 1, 0, 0);
443 }
444
TEST_F(TrackedObjectsTest,LifeCycleToSnapshotMainThread)445 TEST_F(TrackedObjectsTest, LifeCycleToSnapshotMainThread) {
446 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
447
448 const char kFunction[] = "LifeCycleToSnapshotMainThread";
449 Location location(kFunction, kFile, kLineNumber, NULL);
450 TallyABirth(location, kMainThreadName);
451
452 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
453 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
454 // TrackingInfo will call TallyABirth() during construction.
455 base::TrackingInfo pending_task(location, kDelayedStartTime);
456 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
457
458 const unsigned int kStartOfRun = 5;
459 const unsigned int kEndOfRun = 7;
460 SetTestTime(kStartOfRun);
461 TaskStopwatch stopwatch;
462 stopwatch.Start();
463 SetTestTime(kEndOfRun);
464 stopwatch.Stop();
465
466 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
467
468 ProcessDataSnapshot process_data;
469 ThreadData::Snapshot(0, &process_data);
470 ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
471 kMainThreadName, 1, 2, 4);
472 }
473
TEST_F(TrackedObjectsTest,TwoPhases)474 TEST_F(TrackedObjectsTest, TwoPhases) {
475 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
476
477 const char kFunction[] = "TwoPhases";
478 Location location(kFunction, kFile, kLineNumber, NULL);
479 TallyABirth(location, kMainThreadName);
480
481 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
482 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
483 // TrackingInfo will call TallyABirth() during construction.
484 base::TrackingInfo pending_task(location, kDelayedStartTime);
485 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
486
487 const unsigned int kStartOfRun = 5;
488 const unsigned int kEndOfRun = 7;
489 SetTestTime(kStartOfRun);
490 TaskStopwatch stopwatch;
491 stopwatch.Start();
492 SetTestTime(kEndOfRun);
493 stopwatch.Stop();
494
495 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
496
497 ThreadData::OnProfilingPhaseCompleted(0);
498
499 TallyABirth(location, kMainThreadName);
500
501 const TrackedTime kTimePosted1 = TrackedTime::FromMilliseconds(9);
502 const base::TimeTicks kDelayedStartTime1 = base::TimeTicks();
503 // TrackingInfo will call TallyABirth() during construction.
504 base::TrackingInfo pending_task1(location, kDelayedStartTime1);
505 pending_task1.time_posted = kTimePosted1; // Overwrite implied Now().
506
507 const unsigned int kStartOfRun1 = 11;
508 const unsigned int kEndOfRun1 = 21;
509 SetTestTime(kStartOfRun1);
510 TaskStopwatch stopwatch1;
511 stopwatch1.Start();
512 SetTestTime(kEndOfRun1);
513 stopwatch1.Stop();
514
515 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task1, stopwatch1);
516
517 ProcessDataSnapshot process_data;
518 ThreadData::Snapshot(1, &process_data);
519
520 ASSERT_EQ(2u, process_data.phased_snapshots.size());
521
522 auto it0 = process_data.phased_snapshots.find(0);
523 ASSERT_TRUE(it0 != process_data.phased_snapshots.end());
524 const ProcessDataPhaseSnapshot& process_data_phase0 = it0->second;
525
526 ASSERT_EQ(1u, process_data_phase0.tasks.size());
527
528 EXPECT_EQ(kFile, process_data_phase0.tasks[0].birth.location.file_name);
529 EXPECT_EQ(kFunction,
530 process_data_phase0.tasks[0].birth.location.function_name);
531 EXPECT_EQ(kLineNumber,
532 process_data_phase0.tasks[0].birth.location.line_number);
533
534 EXPECT_EQ(kMainThreadName, process_data_phase0.tasks[0].birth.thread_name);
535
536 EXPECT_EQ(1, process_data_phase0.tasks[0].death_data.count);
537 EXPECT_EQ(2, process_data_phase0.tasks[0].death_data.run_duration_sum);
538 EXPECT_EQ(2, process_data_phase0.tasks[0].death_data.run_duration_max);
539 EXPECT_EQ(2, process_data_phase0.tasks[0].death_data.run_duration_sample);
540 EXPECT_EQ(4, process_data_phase0.tasks[0].death_data.queue_duration_sum);
541 EXPECT_EQ(4, process_data_phase0.tasks[0].death_data.queue_duration_max);
542 EXPECT_EQ(4, process_data_phase0.tasks[0].death_data.queue_duration_sample);
543
544 EXPECT_EQ(kMainThreadName, process_data_phase0.tasks[0].death_thread_name);
545
546 auto it1 = process_data.phased_snapshots.find(1);
547 ASSERT_TRUE(it1 != process_data.phased_snapshots.end());
548 const ProcessDataPhaseSnapshot& process_data_phase1 = it1->second;
549
550 ASSERT_EQ(1u, process_data_phase1.tasks.size());
551
552 EXPECT_EQ(kFile, process_data_phase1.tasks[0].birth.location.file_name);
553 EXPECT_EQ(kFunction,
554 process_data_phase1.tasks[0].birth.location.function_name);
555 EXPECT_EQ(kLineNumber,
556 process_data_phase1.tasks[0].birth.location.line_number);
557
558 EXPECT_EQ(kMainThreadName, process_data_phase1.tasks[0].birth.thread_name);
559
560 EXPECT_EQ(1, process_data_phase1.tasks[0].death_data.count);
561 EXPECT_EQ(10, process_data_phase1.tasks[0].death_data.run_duration_sum);
562 EXPECT_EQ(10, process_data_phase1.tasks[0].death_data.run_duration_max);
563 EXPECT_EQ(10, process_data_phase1.tasks[0].death_data.run_duration_sample);
564 EXPECT_EQ(2, process_data_phase1.tasks[0].death_data.queue_duration_sum);
565 EXPECT_EQ(2, process_data_phase1.tasks[0].death_data.queue_duration_max);
566 EXPECT_EQ(2, process_data_phase1.tasks[0].death_data.queue_duration_sample);
567
568 EXPECT_EQ(kMainThreadName, process_data_phase1.tasks[0].death_thread_name);
569
570 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
571 }
572
TEST_F(TrackedObjectsTest,ThreePhases)573 TEST_F(TrackedObjectsTest, ThreePhases) {
574 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
575
576 const char kFunction[] = "ThreePhases";
577 Location location(kFunction, kFile, kLineNumber, NULL);
578
579 // Phase 0
580 {
581 TallyABirth(location, kMainThreadName);
582
583 // TrackingInfo will call TallyABirth() during construction.
584 SetTestTime(10);
585 base::TrackingInfo pending_task(location, base::TimeTicks());
586
587 SetTestTime(17);
588 TaskStopwatch stopwatch;
589 stopwatch.Start();
590 SetTestTime(23);
591 stopwatch.Stop();
592
593 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
594 }
595
596 ThreadData::OnProfilingPhaseCompleted(0);
597
598 // Phase 1
599 {
600 TallyABirth(location, kMainThreadName);
601
602 SetTestTime(30);
603 base::TrackingInfo pending_task(location, base::TimeTicks());
604
605 SetTestTime(35);
606 TaskStopwatch stopwatch;
607 stopwatch.Start();
608 SetTestTime(39);
609 stopwatch.Stop();
610
611 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
612 }
613
614 ThreadData::OnProfilingPhaseCompleted(1);
615
616 // Phase 2
617 {
618 TallyABirth(location, kMainThreadName);
619
620 // TrackingInfo will call TallyABirth() during construction.
621 SetTestTime(40);
622 base::TrackingInfo pending_task(location, base::TimeTicks());
623
624 SetTestTime(43);
625 TaskStopwatch stopwatch;
626 stopwatch.Start();
627 SetTestTime(45);
628 stopwatch.Stop();
629
630 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
631 }
632
633 // Snapshot and check results.
634 ProcessDataSnapshot process_data;
635 ThreadData::Snapshot(2, &process_data);
636
637 ASSERT_EQ(3u, process_data.phased_snapshots.size());
638
639 auto it0 = process_data.phased_snapshots.find(0);
640 ASSERT_TRUE(it0 != process_data.phased_snapshots.end());
641 const ProcessDataPhaseSnapshot& process_data_phase0 = it0->second;
642
643 ASSERT_EQ(1u, process_data_phase0.tasks.size());
644
645 EXPECT_EQ(kFile, process_data_phase0.tasks[0].birth.location.file_name);
646 EXPECT_EQ(kFunction,
647 process_data_phase0.tasks[0].birth.location.function_name);
648 EXPECT_EQ(kLineNumber,
649 process_data_phase0.tasks[0].birth.location.line_number);
650
651 EXPECT_EQ(kMainThreadName, process_data_phase0.tasks[0].birth.thread_name);
652
653 EXPECT_EQ(1, process_data_phase0.tasks[0].death_data.count);
654 EXPECT_EQ(6, process_data_phase0.tasks[0].death_data.run_duration_sum);
655 EXPECT_EQ(6, process_data_phase0.tasks[0].death_data.run_duration_max);
656 EXPECT_EQ(6, process_data_phase0.tasks[0].death_data.run_duration_sample);
657 EXPECT_EQ(7, process_data_phase0.tasks[0].death_data.queue_duration_sum);
658 EXPECT_EQ(7, process_data_phase0.tasks[0].death_data.queue_duration_max);
659 EXPECT_EQ(7, process_data_phase0.tasks[0].death_data.queue_duration_sample);
660
661 EXPECT_EQ(kMainThreadName, process_data_phase0.tasks[0].death_thread_name);
662
663 auto it1 = process_data.phased_snapshots.find(1);
664 ASSERT_TRUE(it1 != process_data.phased_snapshots.end());
665 const ProcessDataPhaseSnapshot& process_data_phase1 = it1->second;
666
667 ASSERT_EQ(1u, process_data_phase1.tasks.size());
668
669 EXPECT_EQ(kFile, process_data_phase1.tasks[0].birth.location.file_name);
670 EXPECT_EQ(kFunction,
671 process_data_phase1.tasks[0].birth.location.function_name);
672 EXPECT_EQ(kLineNumber,
673 process_data_phase1.tasks[0].birth.location.line_number);
674
675 EXPECT_EQ(kMainThreadName, process_data_phase1.tasks[0].birth.thread_name);
676
677 EXPECT_EQ(1, process_data_phase1.tasks[0].death_data.count);
678 EXPECT_EQ(4, process_data_phase1.tasks[0].death_data.run_duration_sum);
679 EXPECT_EQ(4, process_data_phase1.tasks[0].death_data.run_duration_max);
680 EXPECT_EQ(4, process_data_phase1.tasks[0].death_data.run_duration_sample);
681 EXPECT_EQ(5, process_data_phase1.tasks[0].death_data.queue_duration_sum);
682 EXPECT_EQ(5, process_data_phase1.tasks[0].death_data.queue_duration_max);
683 EXPECT_EQ(5, process_data_phase1.tasks[0].death_data.queue_duration_sample);
684
685 EXPECT_EQ(kMainThreadName, process_data_phase1.tasks[0].death_thread_name);
686
687 auto it2 = process_data.phased_snapshots.find(2);
688 ASSERT_TRUE(it2 != process_data.phased_snapshots.end());
689 const ProcessDataPhaseSnapshot& process_data_phase2 = it2->second;
690
691 ASSERT_EQ(1u, process_data_phase2.tasks.size());
692
693 EXPECT_EQ(kFile, process_data_phase2.tasks[0].birth.location.file_name);
694 EXPECT_EQ(kFunction,
695 process_data_phase2.tasks[0].birth.location.function_name);
696 EXPECT_EQ(kLineNumber,
697 process_data_phase2.tasks[0].birth.location.line_number);
698
699 EXPECT_EQ(kMainThreadName, process_data_phase2.tasks[0].birth.thread_name);
700
701 EXPECT_EQ(1, process_data_phase2.tasks[0].death_data.count);
702 EXPECT_EQ(2, process_data_phase2.tasks[0].death_data.run_duration_sum);
703 EXPECT_EQ(2, process_data_phase2.tasks[0].death_data.run_duration_max);
704 EXPECT_EQ(2, process_data_phase2.tasks[0].death_data.run_duration_sample);
705 EXPECT_EQ(3, process_data_phase2.tasks[0].death_data.queue_duration_sum);
706 EXPECT_EQ(3, process_data_phase2.tasks[0].death_data.queue_duration_max);
707 EXPECT_EQ(3, process_data_phase2.tasks[0].death_data.queue_duration_sample);
708
709 EXPECT_EQ(kMainThreadName, process_data_phase2.tasks[0].death_thread_name);
710
711 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
712 }
713
TEST_F(TrackedObjectsTest,TwoPhasesSecondEmpty)714 TEST_F(TrackedObjectsTest, TwoPhasesSecondEmpty) {
715 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
716
717 const char kFunction[] = "TwoPhasesSecondEmpty";
718 Location location(kFunction, kFile, kLineNumber, NULL);
719 ThreadData::InitializeThreadContext(kMainThreadName);
720
721 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
722 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
723 // TrackingInfo will call TallyABirth() during construction.
724 base::TrackingInfo pending_task(location, kDelayedStartTime);
725 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
726
727 const unsigned int kStartOfRun = 5;
728 const unsigned int kEndOfRun = 7;
729 SetTestTime(kStartOfRun);
730 TaskStopwatch stopwatch;
731 stopwatch.Start();
732 SetTestTime(kEndOfRun);
733 stopwatch.Stop();
734
735 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
736
737 ThreadData::OnProfilingPhaseCompleted(0);
738
739 ProcessDataSnapshot process_data;
740 ThreadData::Snapshot(1, &process_data);
741
742 ASSERT_EQ(2u, process_data.phased_snapshots.size());
743
744 auto it0 = process_data.phased_snapshots.find(0);
745 ASSERT_TRUE(it0 != process_data.phased_snapshots.end());
746 const ProcessDataPhaseSnapshot& process_data_phase0 = it0->second;
747
748 ASSERT_EQ(1u, process_data_phase0.tasks.size());
749
750 EXPECT_EQ(kFile, process_data_phase0.tasks[0].birth.location.file_name);
751 EXPECT_EQ(kFunction,
752 process_data_phase0.tasks[0].birth.location.function_name);
753 EXPECT_EQ(kLineNumber,
754 process_data_phase0.tasks[0].birth.location.line_number);
755
756 EXPECT_EQ(kMainThreadName, process_data_phase0.tasks[0].birth.thread_name);
757
758 EXPECT_EQ(1, process_data_phase0.tasks[0].death_data.count);
759 EXPECT_EQ(2, process_data_phase0.tasks[0].death_data.run_duration_sum);
760 EXPECT_EQ(2, process_data_phase0.tasks[0].death_data.run_duration_max);
761 EXPECT_EQ(2, process_data_phase0.tasks[0].death_data.run_duration_sample);
762 EXPECT_EQ(4, process_data_phase0.tasks[0].death_data.queue_duration_sum);
763 EXPECT_EQ(4, process_data_phase0.tasks[0].death_data.queue_duration_max);
764 EXPECT_EQ(4, process_data_phase0.tasks[0].death_data.queue_duration_sample);
765
766 EXPECT_EQ(kMainThreadName, process_data_phase0.tasks[0].death_thread_name);
767
768 auto it1 = process_data.phased_snapshots.find(1);
769 ASSERT_TRUE(it1 != process_data.phased_snapshots.end());
770 const ProcessDataPhaseSnapshot& process_data_phase1 = it1->second;
771
772 ASSERT_EQ(0u, process_data_phase1.tasks.size());
773
774 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
775 }
776
TEST_F(TrackedObjectsTest,TwoPhasesFirstEmpty)777 TEST_F(TrackedObjectsTest, TwoPhasesFirstEmpty) {
778 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
779
780 ThreadData::OnProfilingPhaseCompleted(0);
781
782 const char kFunction[] = "TwoPhasesSecondEmpty";
783 Location location(kFunction, kFile, kLineNumber, NULL);
784 ThreadData::InitializeThreadContext(kMainThreadName);
785
786 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
787 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
788 // TrackingInfo will call TallyABirth() during construction.
789 base::TrackingInfo pending_task(location, kDelayedStartTime);
790 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
791
792 const unsigned int kStartOfRun = 5;
793 const unsigned int kEndOfRun = 7;
794 SetTestTime(kStartOfRun);
795 TaskStopwatch stopwatch;
796 stopwatch.Start();
797 SetTestTime(kEndOfRun);
798 stopwatch.Stop();
799
800 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
801
802 ProcessDataSnapshot process_data;
803 ThreadData::Snapshot(1, &process_data);
804
805 ASSERT_EQ(1u, process_data.phased_snapshots.size());
806
807 auto it1 = process_data.phased_snapshots.find(1);
808 ASSERT_TRUE(it1 != process_data.phased_snapshots.end());
809 const ProcessDataPhaseSnapshot& process_data_phase1 = it1->second;
810
811 ASSERT_EQ(1u, process_data_phase1.tasks.size());
812
813 EXPECT_EQ(kFile, process_data_phase1.tasks[0].birth.location.file_name);
814 EXPECT_EQ(kFunction,
815 process_data_phase1.tasks[0].birth.location.function_name);
816 EXPECT_EQ(kLineNumber,
817 process_data_phase1.tasks[0].birth.location.line_number);
818
819 EXPECT_EQ(kMainThreadName, process_data_phase1.tasks[0].birth.thread_name);
820
821 EXPECT_EQ(1, process_data_phase1.tasks[0].death_data.count);
822 EXPECT_EQ(2, process_data_phase1.tasks[0].death_data.run_duration_sum);
823 EXPECT_EQ(2, process_data_phase1.tasks[0].death_data.run_duration_max);
824 EXPECT_EQ(2, process_data_phase1.tasks[0].death_data.run_duration_sample);
825 EXPECT_EQ(4, process_data_phase1.tasks[0].death_data.queue_duration_sum);
826 EXPECT_EQ(4, process_data_phase1.tasks[0].death_data.queue_duration_max);
827 EXPECT_EQ(4, process_data_phase1.tasks[0].death_data.queue_duration_sample);
828
829 EXPECT_EQ(kMainThreadName, process_data_phase1.tasks[0].death_thread_name);
830
831 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
832 }
833
834 // We will deactivate tracking after the birth, and before the death, and
835 // demonstrate that the lifecycle is completely tallied. This ensures that
836 // our tallied births are matched by tallied deaths (except for when the
837 // task is still running, or is queued).
TEST_F(TrackedObjectsTest,LifeCycleMidDeactivatedToSnapshotMainThread)838 TEST_F(TrackedObjectsTest, LifeCycleMidDeactivatedToSnapshotMainThread) {
839 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
840
841 const char kFunction[] = "LifeCycleMidDeactivatedToSnapshotMainThread";
842 Location location(kFunction, kFile, kLineNumber, NULL);
843 TallyABirth(location, kMainThreadName);
844
845 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
846 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
847 // TrackingInfo will call TallyABirth() during construction.
848 base::TrackingInfo pending_task(location, kDelayedStartTime);
849 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
850
851 // Turn off tracking now that we have births.
852 ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED);
853
854 const unsigned int kStartOfRun = 5;
855 const unsigned int kEndOfRun = 7;
856 SetTestTime(kStartOfRun);
857 TaskStopwatch stopwatch;
858 stopwatch.Start();
859 SetTestTime(kEndOfRun);
860 stopwatch.Stop();
861
862 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
863
864 ProcessDataSnapshot process_data;
865 ThreadData::Snapshot(0, &process_data);
866 ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
867 kMainThreadName, 1, 2, 4);
868 }
869
870 // We will deactivate tracking before starting a life cycle, and neither
871 // the birth nor the death will be recorded.
TEST_F(TrackedObjectsTest,LifeCyclePreDeactivatedToSnapshotMainThread)872 TEST_F(TrackedObjectsTest, LifeCyclePreDeactivatedToSnapshotMainThread) {
873 // Start in the deactivated state.
874 ThreadData::InitializeAndSetTrackingStatus(ThreadData::DEACTIVATED);
875
876 const char kFunction[] = "LifeCyclePreDeactivatedToSnapshotMainThread";
877 Location location(kFunction, kFile, kLineNumber, NULL);
878 TallyABirth(location, kMainThreadName);
879
880 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
881 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
882 // TrackingInfo will call TallyABirth() during construction.
883 base::TrackingInfo pending_task(location, kDelayedStartTime);
884 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
885
886 const unsigned int kStartOfRun = 5;
887 const unsigned int kEndOfRun = 7;
888 SetTestTime(kStartOfRun);
889 TaskStopwatch stopwatch;
890 stopwatch.Start();
891 SetTestTime(kEndOfRun);
892 stopwatch.Stop();
893
894 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
895
896 ProcessDataSnapshot process_data;
897 ThreadData::Snapshot(0, &process_data);
898
899 ASSERT_EQ(1u, process_data.phased_snapshots.size());
900
901 auto it = process_data.phased_snapshots.find(0);
902 ASSERT_TRUE(it != process_data.phased_snapshots.end());
903 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
904
905 ASSERT_EQ(0u, process_data_phase.tasks.size());
906
907 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
908 }
909
TEST_F(TrackedObjectsTest,TwoLives)910 TEST_F(TrackedObjectsTest, TwoLives) {
911 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
912
913 const char kFunction[] = "TwoLives";
914 Location location(kFunction, kFile, kLineNumber, NULL);
915 TallyABirth(location, kMainThreadName);
916
917 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
918 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
919 // TrackingInfo will call TallyABirth() during construction.
920 base::TrackingInfo pending_task(location, kDelayedStartTime);
921 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
922
923 const unsigned int kStartOfRun = 5;
924 const unsigned int kEndOfRun = 7;
925 SetTestTime(kStartOfRun);
926 TaskStopwatch stopwatch;
927 stopwatch.Start();
928 SetTestTime(kEndOfRun);
929 stopwatch.Stop();
930
931 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
932
933 // TrackingInfo will call TallyABirth() during construction.
934 base::TrackingInfo pending_task2(location, kDelayedStartTime);
935 pending_task2.time_posted = kTimePosted; // Overwrite implied Now().
936 SetTestTime(kStartOfRun);
937 TaskStopwatch stopwatch2;
938 stopwatch2.Start();
939 SetTestTime(kEndOfRun);
940 stopwatch2.Stop();
941
942 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task2, stopwatch2);
943
944 ProcessDataSnapshot process_data;
945 ThreadData::Snapshot(0, &process_data);
946 ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
947 kMainThreadName, 2, 2, 4);
948 }
949
TEST_F(TrackedObjectsTest,DifferentLives)950 TEST_F(TrackedObjectsTest, DifferentLives) {
951 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
952
953 // Use a well named thread.
954 ThreadData::InitializeThreadContext(kMainThreadName);
955 const char kFunction[] = "DifferentLives";
956 Location location(kFunction, kFile, kLineNumber, NULL);
957
958 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
959 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
960 // TrackingInfo will call TallyABirth() during construction.
961 base::TrackingInfo pending_task(location, kDelayedStartTime);
962 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
963
964 const unsigned int kStartOfRun = 5;
965 const unsigned int kEndOfRun = 7;
966 SetTestTime(kStartOfRun);
967 TaskStopwatch stopwatch;
968 stopwatch.Start();
969 SetTestTime(kEndOfRun);
970 stopwatch.Stop();
971
972 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, stopwatch);
973
974 const int kSecondFakeLineNumber = 999;
975 Location second_location(kFunction, kFile, kSecondFakeLineNumber, NULL);
976
977 // TrackingInfo will call TallyABirth() during construction.
978 base::TrackingInfo pending_task2(second_location, kDelayedStartTime);
979 pending_task2.time_posted = kTimePosted; // Overwrite implied Now().
980
981 ProcessDataSnapshot process_data;
982 ThreadData::Snapshot(0, &process_data);
983
984 ASSERT_EQ(1u, process_data.phased_snapshots.size());
985 auto it = process_data.phased_snapshots.find(0);
986 ASSERT_TRUE(it != process_data.phased_snapshots.end());
987 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
988
989 ASSERT_EQ(2u, process_data_phase.tasks.size());
990
991 EXPECT_EQ(kFile, process_data_phase.tasks[0].birth.location.file_name);
992 EXPECT_EQ(kFunction,
993 process_data_phase.tasks[0].birth.location.function_name);
994 EXPECT_EQ(kLineNumber,
995 process_data_phase.tasks[0].birth.location.line_number);
996 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[0].birth.thread_name);
997 EXPECT_EQ(1, process_data_phase.tasks[0].death_data.count);
998 EXPECT_EQ(2, process_data_phase.tasks[0].death_data.run_duration_sum);
999 EXPECT_EQ(2, process_data_phase.tasks[0].death_data.run_duration_max);
1000 EXPECT_EQ(2, process_data_phase.tasks[0].death_data.run_duration_sample);
1001 EXPECT_EQ(4, process_data_phase.tasks[0].death_data.queue_duration_sum);
1002 EXPECT_EQ(4, process_data_phase.tasks[0].death_data.queue_duration_max);
1003 EXPECT_EQ(4, process_data_phase.tasks[0].death_data.queue_duration_sample);
1004 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[0].death_thread_name);
1005 EXPECT_EQ(kFile, process_data_phase.tasks[1].birth.location.file_name);
1006 EXPECT_EQ(kFunction,
1007 process_data_phase.tasks[1].birth.location.function_name);
1008 EXPECT_EQ(kSecondFakeLineNumber,
1009 process_data_phase.tasks[1].birth.location.line_number);
1010 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[1].birth.thread_name);
1011 EXPECT_EQ(1, process_data_phase.tasks[1].death_data.count);
1012 EXPECT_EQ(0, process_data_phase.tasks[1].death_data.run_duration_sum);
1013 EXPECT_EQ(0, process_data_phase.tasks[1].death_data.run_duration_max);
1014 EXPECT_EQ(0, process_data_phase.tasks[1].death_data.run_duration_sample);
1015 EXPECT_EQ(0, process_data_phase.tasks[1].death_data.queue_duration_sum);
1016 EXPECT_EQ(0, process_data_phase.tasks[1].death_data.queue_duration_max);
1017 EXPECT_EQ(0, process_data_phase.tasks[1].death_data.queue_duration_sample);
1018 EXPECT_EQ(kStillAlive, process_data_phase.tasks[1].death_thread_name);
1019 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
1020 }
1021
TEST_F(TrackedObjectsTest,TaskWithNestedExclusion)1022 TEST_F(TrackedObjectsTest, TaskWithNestedExclusion) {
1023 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
1024
1025 const char kFunction[] = "TaskWithNestedExclusion";
1026 Location location(kFunction, kFile, kLineNumber, NULL);
1027 TallyABirth(location, kMainThreadName);
1028
1029 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
1030 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
1031 // TrackingInfo will call TallyABirth() during construction.
1032 base::TrackingInfo pending_task(location, kDelayedStartTime);
1033 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
1034
1035 SetTestTime(5);
1036 TaskStopwatch task_stopwatch;
1037 task_stopwatch.Start();
1038 {
1039 SetTestTime(8);
1040 TaskStopwatch exclusion_stopwatch;
1041 exclusion_stopwatch.Start();
1042 SetTestTime(12);
1043 exclusion_stopwatch.Stop();
1044 }
1045 SetTestTime(15);
1046 task_stopwatch.Stop();
1047
1048 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, task_stopwatch);
1049
1050 ProcessDataSnapshot process_data;
1051 ThreadData::Snapshot(0, &process_data);
1052 ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
1053 kMainThreadName, 1, 6, 4);
1054 }
1055
TEST_F(TrackedObjectsTest,TaskWith2NestedExclusions)1056 TEST_F(TrackedObjectsTest, TaskWith2NestedExclusions) {
1057 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
1058
1059 const char kFunction[] = "TaskWith2NestedExclusions";
1060 Location location(kFunction, kFile, kLineNumber, NULL);
1061 TallyABirth(location, kMainThreadName);
1062
1063 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
1064 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
1065 // TrackingInfo will call TallyABirth() during construction.
1066 base::TrackingInfo pending_task(location, kDelayedStartTime);
1067 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
1068
1069 SetTestTime(5);
1070 TaskStopwatch task_stopwatch;
1071 task_stopwatch.Start();
1072 {
1073 SetTestTime(8);
1074 TaskStopwatch exclusion_stopwatch;
1075 exclusion_stopwatch.Start();
1076 SetTestTime(12);
1077 exclusion_stopwatch.Stop();
1078
1079 SetTestTime(15);
1080 TaskStopwatch exclusion_stopwatch2;
1081 exclusion_stopwatch2.Start();
1082 SetTestTime(18);
1083 exclusion_stopwatch2.Stop();
1084 }
1085 SetTestTime(25);
1086 task_stopwatch.Stop();
1087
1088 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, task_stopwatch);
1089
1090 ProcessDataSnapshot process_data;
1091 ThreadData::Snapshot(0, &process_data);
1092 ExpectSimpleProcessData(process_data, kFunction, kMainThreadName,
1093 kMainThreadName, 1, 13, 4);
1094 }
1095
TEST_F(TrackedObjectsTest,TaskWithNestedExclusionWithNestedTask)1096 TEST_F(TrackedObjectsTest, TaskWithNestedExclusionWithNestedTask) {
1097 ThreadData::InitializeAndSetTrackingStatus(ThreadData::PROFILING_ACTIVE);
1098
1099 const char kFunction[] = "TaskWithNestedExclusionWithNestedTask";
1100 Location location(kFunction, kFile, kLineNumber, NULL);
1101
1102 const int kSecondFakeLineNumber = 999;
1103
1104 TallyABirth(location, kMainThreadName);
1105
1106 const TrackedTime kTimePosted = TrackedTime::FromMilliseconds(1);
1107 const base::TimeTicks kDelayedStartTime = base::TimeTicks();
1108 // TrackingInfo will call TallyABirth() during construction.
1109 base::TrackingInfo pending_task(location, kDelayedStartTime);
1110 pending_task.time_posted = kTimePosted; // Overwrite implied Now().
1111
1112 SetTestTime(5);
1113 TaskStopwatch task_stopwatch;
1114 task_stopwatch.Start();
1115 {
1116 SetTestTime(8);
1117 TaskStopwatch exclusion_stopwatch;
1118 exclusion_stopwatch.Start();
1119 {
1120 Location second_location(kFunction, kFile, kSecondFakeLineNumber, NULL);
1121 base::TrackingInfo nested_task(second_location, kDelayedStartTime);
1122 // Overwrite implied Now().
1123 nested_task.time_posted = TrackedTime::FromMilliseconds(8);
1124 SetTestTime(9);
1125 TaskStopwatch nested_task_stopwatch;
1126 nested_task_stopwatch.Start();
1127 SetTestTime(11);
1128 nested_task_stopwatch.Stop();
1129 ThreadData::TallyRunOnNamedThreadIfTracking(
1130 nested_task, nested_task_stopwatch);
1131 }
1132 SetTestTime(12);
1133 exclusion_stopwatch.Stop();
1134 }
1135 SetTestTime(15);
1136 task_stopwatch.Stop();
1137
1138 ThreadData::TallyRunOnNamedThreadIfTracking(pending_task, task_stopwatch);
1139
1140 ProcessDataSnapshot process_data;
1141 ThreadData::Snapshot(0, &process_data);
1142
1143 ASSERT_EQ(1u, process_data.phased_snapshots.size());
1144 auto it = process_data.phased_snapshots.find(0);
1145 ASSERT_TRUE(it != process_data.phased_snapshots.end());
1146 const ProcessDataPhaseSnapshot& process_data_phase = it->second;
1147
1148 // The order in which the two task follow is platform-dependent.
1149 int t0 =
1150 (process_data_phase.tasks[0].birth.location.line_number == kLineNumber)
1151 ? 0
1152 : 1;
1153 int t1 = 1 - t0;
1154
1155 ASSERT_EQ(2u, process_data_phase.tasks.size());
1156 EXPECT_EQ(kFile, process_data_phase.tasks[t0].birth.location.file_name);
1157 EXPECT_EQ(kFunction,
1158 process_data_phase.tasks[t0].birth.location.function_name);
1159 EXPECT_EQ(kLineNumber,
1160 process_data_phase.tasks[t0].birth.location.line_number);
1161 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[t0].birth.thread_name);
1162 EXPECT_EQ(1, process_data_phase.tasks[t0].death_data.count);
1163 EXPECT_EQ(6, process_data_phase.tasks[t0].death_data.run_duration_sum);
1164 EXPECT_EQ(6, process_data_phase.tasks[t0].death_data.run_duration_max);
1165 EXPECT_EQ(6, process_data_phase.tasks[t0].death_data.run_duration_sample);
1166 EXPECT_EQ(4, process_data_phase.tasks[t0].death_data.queue_duration_sum);
1167 EXPECT_EQ(4, process_data_phase.tasks[t0].death_data.queue_duration_max);
1168 EXPECT_EQ(4, process_data_phase.tasks[t0].death_data.queue_duration_sample);
1169 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[t0].death_thread_name);
1170 EXPECT_EQ(kFile, process_data_phase.tasks[t1].birth.location.file_name);
1171 EXPECT_EQ(kFunction,
1172 process_data_phase.tasks[t1].birth.location.function_name);
1173 EXPECT_EQ(kSecondFakeLineNumber,
1174 process_data_phase.tasks[t1].birth.location.line_number);
1175 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[t1].birth.thread_name);
1176 EXPECT_EQ(1, process_data_phase.tasks[t1].death_data.count);
1177 EXPECT_EQ(2, process_data_phase.tasks[t1].death_data.run_duration_sum);
1178 EXPECT_EQ(2, process_data_phase.tasks[t1].death_data.run_duration_max);
1179 EXPECT_EQ(2, process_data_phase.tasks[t1].death_data.run_duration_sample);
1180 EXPECT_EQ(1, process_data_phase.tasks[t1].death_data.queue_duration_sum);
1181 EXPECT_EQ(1, process_data_phase.tasks[t1].death_data.queue_duration_max);
1182 EXPECT_EQ(1, process_data_phase.tasks[t1].death_data.queue_duration_sample);
1183 EXPECT_EQ(kMainThreadName, process_data_phase.tasks[t1].death_thread_name);
1184 EXPECT_EQ(base::GetCurrentProcId(), process_data.process_id);
1185 }
1186
1187 } // namespace tracked_objects
1188