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