base/tracked_objects_unittest.cc

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