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: 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 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. 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|. 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. 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(). 109 static void SetTestTime(unsigned int test_time) { test_time_ = test_time; } 110 111 private: 112 // Returns test time in milliseconds. 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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). 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. 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 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 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 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 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 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
