Chromium Code Reviews| OLD | NEW |
|---|---|
| 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. | 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 | 2 // Use of this source code is governed by a BSD-style license that can be |
| 3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
| 4 | 4 |
| 5 #include "base/tracked_objects.h" | 5 #include "base/tracked_objects.h" |
| 6 | 6 |
| 7 #include <limits.h> | 7 #include <limits.h> |
| 8 #include <stdlib.h> | 8 #include <stdlib.h> |
| 9 | 9 |
| 10 #include "base/atomicops.h" | 10 #include "base/atomicops.h" |
| 11 #include "base/base_switches.h" | 11 #include "base/base_switches.h" |
| 12 #include "base/command_line.h" | 12 #include "base/command_line.h" |
| 13 #include "base/compiler_specific.h" | 13 #include "base/compiler_specific.h" |
| 14 #include "base/debug/leak_annotations.h" | 14 #include "base/debug/leak_annotations.h" |
| 15 #include "base/logging.h" | 15 #include "base/logging.h" |
| 16 #include "base/process/process_handle.h" | 16 #include "base/process/process_handle.h" |
| 17 #include "base/profiler/alternate_timer.h" | 17 #include "base/profiler/alternate_timer.h" |
| 18 #include "base/stl_util.h" | |
|
Alexei Svitkine (slow)
2015/04/10 15:27:27
Nit: Is this include needed?
vadimt
2015/04/14 15:52:05
Done.
| |
| 18 #include "base/strings/stringprintf.h" | 19 #include "base/strings/stringprintf.h" |
| 19 #include "base/third_party/valgrind/memcheck.h" | 20 #include "base/third_party/valgrind/memcheck.h" |
| 20 #include "base/tracking_info.h" | 21 #include "base/tracking_info.h" |
| 21 | 22 |
| 22 using base::TimeDelta; | 23 using base::TimeDelta; |
| 23 | 24 |
| 24 namespace base { | 25 namespace base { |
| 25 class TimeDelta; | 26 class TimeDelta; |
| 26 } | 27 } |
| 27 | 28 |
| (...skipping 58 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
| 86 } | 87 } |
| 87 return current_timing_enabled == ENABLED_TIMING; | 88 return current_timing_enabled == ENABLED_TIMING; |
| 88 } | 89 } |
| 89 | 90 |
| 90 } // namespace | 91 } // namespace |
| 91 | 92 |
| 92 //------------------------------------------------------------------------------ | 93 //------------------------------------------------------------------------------ |
| 93 // DeathData tallies durations when a death takes place. | 94 // DeathData tallies durations when a death takes place. |
| 94 | 95 |
| 95 DeathData::DeathData() { | 96 DeathData::DeathData() { |
| 96 Clear(); | 97 count_ = 0; |
| 98 sample_probability_count_ = 0; | |
| 99 run_duration_sum_ = 0; | |
| 100 run_duration_max_ = 0; | |
| 101 run_duration_sample_ = 0; | |
| 102 queue_duration_sum_ = 0; | |
| 103 queue_duration_max_ = 0; | |
| 104 queue_duration_sample_ = 0; | |
| 105 last_phase_snapshot_ = nullptr; | |
| 97 } | 106 } |
| 98 | 107 |
| 99 DeathData::DeathData(int count) { | 108 DeathData::~DeathData() { |
| 100 Clear(); | 109 while (last_phase_snapshot_) { |
| 101 count_ = count; | 110 DeathDataPhaseSnapshot* snapshot = last_phase_snapshot_; |
| 111 last_phase_snapshot_ = snapshot->prev; | |
| 112 delete snapshot; | |
| 113 } | |
| 102 } | 114 } |
| 103 | 115 |
| 104 // TODO(jar): I need to see if this macro to optimize branching is worth using. | 116 // TODO(jar): I need to see if this macro to optimize branching is worth using. |
| 105 // | 117 // |
| 106 // This macro has no branching, so it is surely fast, and is equivalent to: | 118 // This macro has no branching, so it is surely fast, and is equivalent to: |
| 107 // if (assign_it) | 119 // if (assign_it) |
| 108 // target = source; | 120 // target = source; |
| 109 // We use a macro rather than a template to force this to inline. | 121 // We use a macro rather than a template to force this to inline. |
| 110 // Related code for calculating max is discussed on the web. | 122 // Related code for calculating max is discussed on the web. |
| 111 #define CONDITIONAL_ASSIGN(assign_it, target, source) \ | 123 #define CONDITIONAL_ASSIGN(assign_it, target, source) \ |
| 112 ((target) ^= ((target) ^ (source)) & -static_cast<int32>(assign_it)) | 124 ((target) ^= ((target) ^ (source)) & -static_cast<int32>(assign_it)) |
| 113 | 125 |
| 114 void DeathData::RecordDeath(const int32 queue_duration, | 126 void DeathData::RecordDeath(const int32 queue_duration, |
| 115 const int32 run_duration, | 127 const int32 run_duration, |
| 116 const uint32 random_number) { | 128 const uint32 random_number) { |
| 117 // We'll just clamp at INT_MAX, but we should note this in the UI as such. | 129 // We'll just clamp at INT_MAX, but we should note this in the UI as such. |
| 118 if (count_ < INT_MAX) | 130 if (count_ < INT_MAX) |
| 119 ++count_; | 131 ++count_; |
| 132 if (sample_probability_count_ < INT_MAX) | |
| 133 ++sample_probability_count_; | |
| 120 queue_duration_sum_ += queue_duration; | 134 queue_duration_sum_ += queue_duration; |
| 121 run_duration_sum_ += run_duration; | 135 run_duration_sum_ += run_duration; |
| 122 | 136 |
| 123 if (queue_duration_max_ < queue_duration) | 137 if (queue_duration_max_ < queue_duration) |
| 124 queue_duration_max_ = queue_duration; | 138 queue_duration_max_ = queue_duration; |
| 125 if (run_duration_max_ < run_duration) | 139 if (run_duration_max_ < run_duration) |
| 126 run_duration_max_ = run_duration; | 140 run_duration_max_ = run_duration; |
| 127 | 141 |
| 128 // Take a uniformly distributed sample over all durations ever supplied. | 142 // Take a uniformly distributed sample over all durations ever supplied during |
| 129 // The probability that we (instead) use this new sample is 1/count_. This | 143 // currrent profiling phase. |
| 130 // results in a completely uniform selection of the sample (at least when we | 144 // The probability that we (instead) use this new sample is |
| 131 // don't clamp count_... but that should be inconsequentially likely). | 145 // 1/sample_probability_count_. This results in a completely uniform selection |
| 132 // We ignore the fact that we correlated our selection of a sample to the run | 146 // of the sample (at least when we don't clamp sample_probability_count_... |
| 133 // and queue times (i.e., we used them to generate random_number). | 147 // but that should be inconsequentially likely). We ignore the fact that we |
| 134 CHECK_GT(count_, 0); | 148 // correlated our selection of a sample to the run and queue times (i.e., we |
| 135 if (0 == (random_number % count_)) { | 149 // used them to generate random_number). |
| 150 CHECK_GT(sample_probability_count_, 0); | |
| 151 if (0 == (random_number % sample_probability_count_)) { | |
| 136 queue_duration_sample_ = queue_duration; | 152 queue_duration_sample_ = queue_duration; |
| 137 run_duration_sample_ = run_duration; | 153 run_duration_sample_ = run_duration; |
| 138 } | 154 } |
| 139 } | 155 } |
| 140 | 156 |
| 141 int DeathData::count() const { return count_; } | 157 int DeathData::count() const { return count_; } |
| 142 | 158 |
| 143 int32 DeathData::run_duration_sum() const { return run_duration_sum_; } | 159 int32 DeathData::run_duration_sum() const { return run_duration_sum_; } |
| 144 | 160 |
| 145 int32 DeathData::run_duration_max() const { return run_duration_max_; } | 161 int32 DeathData::run_duration_max() const { return run_duration_max_; } |
| 146 | 162 |
| 147 int32 DeathData::run_duration_sample() const { | 163 int32 DeathData::run_duration_sample() const { |
| 148 return run_duration_sample_; | 164 return run_duration_sample_; |
| 149 } | 165 } |
| 150 | 166 |
| 151 int32 DeathData::queue_duration_sum() const { | 167 int32 DeathData::queue_duration_sum() const { |
| 152 return queue_duration_sum_; | 168 return queue_duration_sum_; |
| 153 } | 169 } |
| 154 | 170 |
| 155 int32 DeathData::queue_duration_max() const { | 171 int32 DeathData::queue_duration_max() const { |
| 156 return queue_duration_max_; | 172 return queue_duration_max_; |
| 157 } | 173 } |
| 158 | 174 |
| 159 int32 DeathData::queue_duration_sample() const { | 175 int32 DeathData::queue_duration_sample() const { |
| 160 return queue_duration_sample_; | 176 return queue_duration_sample_; |
| 161 } | 177 } |
| 162 | 178 |
| 163 void DeathData::Clear() { | 179 DeathDataPhaseSnapshot* DeathData::last_phase_snapshot() const { |
| 164 count_ = 0; | 180 return last_phase_snapshot_; |
| 165 run_duration_sum_ = 0; | 181 } |
| 182 | |
| 183 void DeathData::OnProfilingPhaseCompleted(int profiling_phase) { | |
| 184 // Snapshotting and storing current state. | |
| 185 last_phase_snapshot_ = new DeathDataPhaseSnapshot( | |
| 186 profiling_phase, count_, run_duration_sum_, run_duration_max_, | |
| 187 run_duration_sample_, queue_duration_sum_, queue_duration_max_, | |
| 188 queue_duration_sample_, last_phase_snapshot_); | |
| 189 | |
| 190 // Not touching fields for which a delta can be computed by comparing with a | |
| 191 // snapshot from previos phase. Resetting other fields. Sample values will be | |
| 192 // reset upon next death recording because sample_probability_count_ is set to | |
| 193 // 0. | |
| 194 // We avoid resetting to 0 in favor of deltas whenever possible. The reason is | |
| 195 // that for incrementable fields, resetting to 0 from the snapshot thread | |
| 196 // potentially in parallel with incrementing in the death thread may result in | |
| 197 // significant data corruption that has a potential to grow with time. Not | |
| 198 // resetting incrementable fields and using deltas will cause any | |
| 199 // off-by-little corruptions to be likely fixed at the next snapshot. | |
| 200 // The max values are not incrementable, and cannot be deduced using deltas | |
| 201 // for a given phase. Hence, we have to reset them to 0. But the potential | |
| 202 // damage is limited to getting the previous phase's max to apply for the next | |
| 203 // phase, and the error doesn't have a potential to keep growing with new | |
| 204 // resets. | |
| 205 // sample_probability_count_ is incrementable, but must be reset to 0 at the | |
| 206 // phase end, so that we start a new uniformly randomized sample selection | |
| 207 // after the reset. Corruptions due to race conditions are possible, but the | |
| 208 // damage is limited to selecting a wrong sample, which is not something that | |
| 209 // can cause accumulating or cascading effects. | |
|
Alexei Svitkine (slow)
2015/04/10 15:27:27
Thanks for this write-up - this makes sense.
I wo
| |
| 210 sample_probability_count_ = 0; | |
| 166 run_duration_max_ = 0; | 211 run_duration_max_ = 0; |
| 167 run_duration_sample_ = 0; | |
| 168 queue_duration_sum_ = 0; | |
| 169 queue_duration_max_ = 0; | 212 queue_duration_max_ = 0; |
| 170 queue_duration_sample_ = 0; | |
| 171 } | 213 } |
| 172 | 214 |
| 173 //------------------------------------------------------------------------------ | 215 //------------------------------------------------------------------------------ |
| 174 DeathDataSnapshot::DeathDataSnapshot() | 216 DeathDataSnapshot::DeathDataSnapshot() |
| 175 : count(-1), | 217 : count(-1), |
| 176 run_duration_sum(-1), | 218 run_duration_sum(-1), |
| 177 run_duration_max(-1), | 219 run_duration_max(-1), |
| 178 run_duration_sample(-1), | 220 run_duration_sample(-1), |
| 179 queue_duration_sum(-1), | 221 queue_duration_sum(-1), |
| 180 queue_duration_max(-1), | 222 queue_duration_max(-1), |
| 181 queue_duration_sample(-1) { | 223 queue_duration_sample(-1) { |
| 182 } | 224 } |
| 183 | 225 |
| 184 DeathDataSnapshot::DeathDataSnapshot( | 226 DeathDataSnapshot::DeathDataSnapshot(int count, |
| 185 const tracked_objects::DeathData& death_data) | 227 int32 run_duration_sum, |
| 186 : count(death_data.count()), | 228 int32 run_duration_max, |
| 187 run_duration_sum(death_data.run_duration_sum()), | 229 int32 run_duration_sample, |
| 188 run_duration_max(death_data.run_duration_max()), | 230 int32 queue_duration_sum, |
| 189 run_duration_sample(death_data.run_duration_sample()), | 231 int32 queue_duration_max, |
| 190 queue_duration_sum(death_data.queue_duration_sum()), | 232 int32 queue_duration_sample) |
| 191 queue_duration_max(death_data.queue_duration_max()), | 233 : count(count), |
| 192 queue_duration_sample(death_data.queue_duration_sample()) { | 234 run_duration_sum(run_duration_sum), |
| 235 run_duration_max(run_duration_max), | |
| 236 run_duration_sample(run_duration_sample), | |
| 237 queue_duration_sum(queue_duration_sum), | |
| 238 queue_duration_max(queue_duration_max), | |
| 239 queue_duration_sample(queue_duration_sample) { | |
| 193 } | 240 } |
| 194 | 241 |
| 195 DeathDataSnapshot::~DeathDataSnapshot() { | 242 DeathDataSnapshot::~DeathDataSnapshot() { |
| 196 } | 243 } |
| 197 | 244 |
| 245 void DeathDataSnapshot::SubtractOlderSnapshot(const DeathDataSnapshot& older) { | |
| 246 count -= older.count; | |
| 247 run_duration_sum -= older.run_duration_sum; | |
| 248 queue_duration_sum -= older.queue_duration_sum; | |
| 249 } | |
| 250 | |
| 198 //------------------------------------------------------------------------------ | 251 //------------------------------------------------------------------------------ |
| 199 BirthOnThread::BirthOnThread(const Location& location, | 252 BirthOnThread::BirthOnThread(const Location& location, |
| 200 const ThreadData& current) | 253 const ThreadData& current) |
| 201 : location_(location), | 254 : location_(location), |
| 202 birth_thread_(¤t) { | 255 birth_thread_(¤t) { |
| 203 } | 256 } |
| 204 | 257 |
| 205 //------------------------------------------------------------------------------ | 258 //------------------------------------------------------------------------------ |
| 206 BirthOnThreadSnapshot::BirthOnThreadSnapshot() { | 259 BirthOnThreadSnapshot::BirthOnThreadSnapshot() { |
| 207 } | 260 } |
| 208 | 261 |
| 209 BirthOnThreadSnapshot::BirthOnThreadSnapshot( | 262 BirthOnThreadSnapshot::BirthOnThreadSnapshot(const BirthOnThread& birth) |
| 210 const tracked_objects::BirthOnThread& birth) | |
| 211 : location(birth.location()), | 263 : location(birth.location()), |
| 212 thread_name(birth.birth_thread()->thread_name()) { | 264 thread_name(birth.birth_thread()->thread_name()) { |
| 213 } | 265 } |
| 214 | 266 |
| 215 BirthOnThreadSnapshot::~BirthOnThreadSnapshot() { | 267 BirthOnThreadSnapshot::~BirthOnThreadSnapshot() { |
| 216 } | 268 } |
| 217 | 269 |
| 218 //------------------------------------------------------------------------------ | 270 //------------------------------------------------------------------------------ |
| 219 Births::Births(const Location& location, const ThreadData& current) | 271 Births::Births(const Location& location, const ThreadData& current) |
| 220 : BirthOnThread(location, current), | 272 : BirthOnThread(location, current), |
| (...skipping 36 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
| 257 ThreadData* ThreadData::all_thread_data_list_head_ = NULL; | 309 ThreadData* ThreadData::all_thread_data_list_head_ = NULL; |
| 258 | 310 |
| 259 // static | 311 // static |
| 260 ThreadData* ThreadData::first_retired_worker_ = NULL; | 312 ThreadData* ThreadData::first_retired_worker_ = NULL; |
| 261 | 313 |
| 262 // static | 314 // static |
| 263 base::LazyInstance<base::Lock>::Leaky | 315 base::LazyInstance<base::Lock>::Leaky |
| 264 ThreadData::list_lock_ = LAZY_INSTANCE_INITIALIZER; | 316 ThreadData::list_lock_ = LAZY_INSTANCE_INITIALIZER; |
| 265 | 317 |
| 266 // static | 318 // static |
| 319 base::LazyInstance<base::ThreadChecker>::Leaky | |
| 320 ThreadData::snapshot_thread_checker_ = LAZY_INSTANCE_INITIALIZER; | |
| 321 | |
| 322 // static | |
| 267 ThreadData::Status ThreadData::status_ = ThreadData::UNINITIALIZED; | 323 ThreadData::Status ThreadData::status_ = ThreadData::UNINITIALIZED; |
| 268 | 324 |
| 269 ThreadData::ThreadData(const std::string& suggested_name) | 325 ThreadData::ThreadData(const std::string& suggested_name) |
| 270 : next_(NULL), | 326 : next_(NULL), |
| 271 next_retired_worker_(NULL), | 327 next_retired_worker_(NULL), |
| 272 worker_thread_number_(0), | 328 worker_thread_number_(0), |
| 273 incarnation_count_for_pool_(-1), | 329 incarnation_count_for_pool_(-1), |
| 274 current_stopwatch_(NULL) { | 330 current_stopwatch_(NULL) { |
| 275 DCHECK_GE(suggested_name.size(), 0u); | 331 DCHECK_GE(suggested_name.size(), 0u); |
| 276 thread_name_ = suggested_name; | 332 thread_name_ = suggested_name; |
| (...skipping 101 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
| 378 return; | 434 return; |
| 379 } | 435 } |
| 380 // We must NOT do any allocations during this callback. | 436 // We must NOT do any allocations during this callback. |
| 381 // Using the simple linked lists avoids all allocations. | 437 // Using the simple linked lists avoids all allocations. |
| 382 DCHECK_EQ(this->next_retired_worker_, reinterpret_cast<ThreadData*>(NULL)); | 438 DCHECK_EQ(this->next_retired_worker_, reinterpret_cast<ThreadData*>(NULL)); |
| 383 this->next_retired_worker_ = first_retired_worker_; | 439 this->next_retired_worker_ = first_retired_worker_; |
| 384 first_retired_worker_ = this; | 440 first_retired_worker_ = this; |
| 385 } | 441 } |
| 386 | 442 |
| 387 // static | 443 // static |
| 388 void ThreadData::Snapshot(ProcessDataSnapshot* process_data_snapshot) { | 444 void ThreadData::Snapshot(int current_profiling_phase, |
| 389 ThreadData::SnapshotCurrentPhase( | 445 ProcessDataSnapshot* process_data_snapshot) { |
| 390 &process_data_snapshot->phased_process_data_snapshots[0]); | 446 DCHECK(snapshot_thread_checker_.Get().CalledOnValidThread()); |
| 447 BirthCountMap birth_counts; | |
|
Alexei Svitkine (slow)
2015/04/10 15:27:27
Nit: Move this closer to where it's used .. e.g. a
vadimt
2015/04/14 15:52:05
Done.
| |
| 448 | |
| 449 // Get an unchanging copy of a ThreadData list. | |
| 450 ThreadData* my_list = ThreadData::first(); | |
| 451 | |
| 452 // Gather data serially. | |
| 453 // This hackish approach *can* get some slighly corrupt tallies, as we are | |
| 454 // grabbing values without the protection of a lock, but it has the advantage | |
| 455 // of working even with threads that don't have message loops. If a user | |
| 456 // sees any strangeness, they can always just run their stats gathering a | |
| 457 // second time. | |
| 458 for (ThreadData* thread_data = my_list; thread_data; | |
| 459 thread_data = thread_data->next()) { | |
| 460 thread_data->SnapshotExecutedTasks( | |
| 461 current_profiling_phase, | |
| 462 &process_data_snapshot->phased_process_data_snapshots, &birth_counts); | |
| 463 } | |
| 464 | |
| 465 // Add births that are still active -- i.e. objects that have tallied a birth, | |
| 466 // but have not yet tallied a matching death, and hence must be either | |
| 467 // running, queued up, or being held in limbo for future posting. | |
| 468 auto current_phase_tasks = | |
| 469 &process_data_snapshot | |
| 470 ->phased_process_data_snapshots[current_profiling_phase] | |
| 471 .tasks; | |
|
Alexei Svitkine (slow)
2015/04/09 22:19:44
Nit: The .tasks can definitely go on the previous
vadimt
2015/04/09 22:42:20
git cl format will return it to the new line after
Alexei Svitkine (slow)
2015/04/10 15:27:27
Hmm, that's too bad.
I really dislike excessive w
| |
| 472 for (const auto& birth_count : birth_counts) { | |
| 473 if (birth_count.second > 0) { | |
| 474 current_phase_tasks->push_back( | |
| 475 TaskSnapshot(BirthOnThreadSnapshot(*birth_count.first), | |
| 476 DeathDataSnapshot(birth_count.second, 0, 0, 0, 0, 0, 0), | |
| 477 "Still_Alive")); | |
| 478 } | |
| 479 } | |
| 480 } | |
| 481 | |
| 482 // static | |
| 483 void ThreadData::OnProfilingPhaseCompleted(int profiling_phase) { | |
| 484 DCHECK(snapshot_thread_checker_.Get().CalledOnValidThread()); | |
| 485 // Get an unchanging copy of a ThreadData list. | |
| 486 ThreadData* my_list = ThreadData::first(); | |
| 487 | |
| 488 // Add snapshots for all death datas in all threads serially. | |
| 489 // This hackish approach *can* get some slighly corrupt tallies, as we are | |
| 490 // grabbing values without the protection of a lock, but it has the advantage | |
| 491 // of working even with threads that don't have message loops. Any corruption | |
| 492 // shouldn't cause "cascading damage" to anything else (in later phases). | |
| 493 for (ThreadData* thread_data = my_list; thread_data; | |
| 494 thread_data = thread_data->next()) { | |
| 495 thread_data->OnProfilingPhaseCompletionOnThread(profiling_phase); | |
| 496 } | |
| 391 } | 497 } |
| 392 | 498 |
| 393 Births* ThreadData::TallyABirth(const Location& location) { | 499 Births* ThreadData::TallyABirth(const Location& location) { |
| 394 BirthMap::iterator it = birth_map_.find(location); | 500 BirthMap::iterator it = birth_map_.find(location); |
| 395 Births* child; | 501 Births* child; |
| 396 if (it != birth_map_.end()) { | 502 if (it != birth_map_.end()) { |
| 397 child = it->second; | 503 child = it->second; |
| 398 child->RecordBirth(); | 504 child->RecordBirth(); |
| 399 } else { | 505 } else { |
| 400 child = new Births(location, *this); // Leak this. | 506 child = new Births(location, *this); // Leak this. |
| (...skipping 11 matching lines...) Expand all Loading... | |
| 412 // Lock since the map may get relocated now, and other threads sometimes | 518 // Lock since the map may get relocated now, and other threads sometimes |
| 413 // snapshot it (but they lock before copying it). | 519 // snapshot it (but they lock before copying it). |
| 414 base::AutoLock lock(map_lock_); | 520 base::AutoLock lock(map_lock_); |
| 415 parent_child_set_.insert(pair); | 521 parent_child_set_.insert(pair); |
| 416 } | 522 } |
| 417 } | 523 } |
| 418 | 524 |
| 419 return child; | 525 return child; |
| 420 } | 526 } |
| 421 | 527 |
| 422 void ThreadData::TallyADeath(const Births& birth, | 528 void ThreadData::TallyADeath(const Births& births, |
| 423 int32 queue_duration, | 529 int32 queue_duration, |
| 424 const TaskStopwatch& stopwatch) { | 530 const TaskStopwatch& stopwatch) { |
| 425 int32 run_duration = stopwatch.RunDurationMs(); | 531 int32 run_duration = stopwatch.RunDurationMs(); |
| 426 | 532 |
| 427 // Stir in some randomness, plus add constant in case durations are zero. | 533 // Stir in some randomness, plus add constant in case durations are zero. |
| 428 const uint32 kSomePrimeNumber = 2147483647; | 534 const uint32 kSomePrimeNumber = 2147483647; |
| 429 random_number_ += queue_duration + run_duration + kSomePrimeNumber; | 535 random_number_ += queue_duration + run_duration + kSomePrimeNumber; |
| 430 // An address is going to have some randomness to it as well ;-). | 536 // An address is going to have some randomness to it as well ;-). |
| 431 random_number_ ^= static_cast<uint32>(&birth - reinterpret_cast<Births*>(0)); | 537 random_number_ ^= static_cast<uint32>(&births - reinterpret_cast<Births*>(0)); |
| 432 | 538 |
| 433 // We don't have queue durations without OS timer. OS timer is automatically | 539 // We don't have queue durations without OS timer. OS timer is automatically |
| 434 // used for task-post-timing, so the use of an alternate timer implies all | 540 // used for task-post-timing, so the use of an alternate timer implies all |
| 435 // queue times are invalid, unless it was explicitly said that we can trust | 541 // queue times are invalid, unless it was explicitly said that we can trust |
| 436 // the alternate timer. | 542 // the alternate timer. |
| 437 if (kAllowAlternateTimeSourceHandling && | 543 if (kAllowAlternateTimeSourceHandling && |
| 438 now_function_ && | 544 now_function_ && |
| 439 !now_function_is_time_) { | 545 !now_function_is_time_) { |
| 440 queue_duration = 0; | 546 queue_duration = 0; |
| 441 } | 547 } |
| 442 | 548 |
| 443 DeathMap::iterator it = death_map_.find(&birth); | 549 DeathMap::iterator it = death_map_.find(&births); |
| 444 DeathData* death_data; | 550 DeathData* death_data; |
| 445 if (it != death_map_.end()) { | 551 if (it != death_map_.end()) { |
| 446 death_data = &it->second; | 552 death_data = &it->second; |
| 447 } else { | 553 } else { |
| 448 base::AutoLock lock(map_lock_); // Lock as the map may get relocated now. | 554 base::AutoLock lock(map_lock_); // Lock as the map may get relocated now. |
| 449 death_data = &death_map_[&birth]; | 555 death_data = &death_map_[&births]; |
| 450 } // Release lock ASAP. | 556 } // Release lock ASAP. |
| 451 death_data->RecordDeath(queue_duration, run_duration, random_number_); | 557 death_data->RecordDeath(queue_duration, run_duration, random_number_); |
| 452 | 558 |
| 453 if (!kTrackParentChildLinks) | 559 if (!kTrackParentChildLinks) |
| 454 return; | 560 return; |
| 455 if (!parent_stack_.empty()) { // We might get turned off. | 561 if (!parent_stack_.empty()) { // We might get turned off. |
| 456 DCHECK_EQ(parent_stack_.top(), &birth); | 562 DCHECK_EQ(parent_stack_.top(), &births); |
| 457 parent_stack_.pop(); | 563 parent_stack_.pop(); |
| 458 } | 564 } |
| 459 } | 565 } |
| 460 | 566 |
| 461 // static | 567 // static |
| 462 Births* ThreadData::TallyABirthIfActive(const Location& location) { | 568 Births* ThreadData::TallyABirthIfActive(const Location& location) { |
| 463 if (!TrackingStatus()) | 569 if (!TrackingStatus()) |
| 464 return NULL; | 570 return NULL; |
| 465 ThreadData* current_thread_data = Get(); | 571 ThreadData* current_thread_data = Get(); |
| 466 if (!current_thread_data) | 572 if (!current_thread_data) |
| 467 return NULL; | 573 return NULL; |
| 468 return current_thread_data->TallyABirth(location); | 574 return current_thread_data->TallyABirth(location); |
| 469 } | 575 } |
| 470 | 576 |
| 471 // static | 577 // static |
| 472 void ThreadData::TallyRunOnNamedThreadIfTracking( | 578 void ThreadData::TallyRunOnNamedThreadIfTracking( |
| 473 const base::TrackingInfo& completed_task, | 579 const base::TrackingInfo& completed_task, |
| 474 const TaskStopwatch& stopwatch) { | 580 const TaskStopwatch& stopwatch) { |
| 475 // Even if we have been DEACTIVATED, we will process any pending births so | 581 // Even if we have been DEACTIVATED, we will process any pending births so |
| 476 // that our data structures (which counted the outstanding births) remain | 582 // that our data structures (which counted the outstanding births) remain |
| 477 // consistent. | 583 // consistent. |
| 478 const Births* birth = completed_task.birth_tally; | 584 const Births* births = completed_task.birth_tally; |
| 479 if (!birth) | 585 if (!births) |
| 480 return; | 586 return; |
| 481 ThreadData* current_thread_data = stopwatch.GetThreadData(); | 587 ThreadData* current_thread_data = stopwatch.GetThreadData(); |
| 482 if (!current_thread_data) | 588 if (!current_thread_data) |
| 483 return; | 589 return; |
| 484 | 590 |
| 485 // Watch out for a race where status_ is changing, and hence one or both | 591 // Watch out for a race where status_ is changing, and hence one or both |
| 486 // of start_of_run or end_of_run is zero. In that case, we didn't bother to | 592 // of start_of_run or end_of_run is zero. In that case, we didn't bother to |
| 487 // get a time value since we "weren't tracking" and we were trying to be | 593 // get a time value since we "weren't tracking" and we were trying to be |
| 488 // efficient by not calling for a genuine time value. For simplicity, we'll | 594 // efficient by not calling for a genuine time value. For simplicity, we'll |
| 489 // use a default zero duration when we can't calculate a true value. | 595 // use a default zero duration when we can't calculate a true value. |
| 490 TrackedTime start_of_run = stopwatch.StartTime(); | 596 TrackedTime start_of_run = stopwatch.StartTime(); |
| 491 int32 queue_duration = 0; | 597 int32 queue_duration = 0; |
| 492 if (!start_of_run.is_null()) { | 598 if (!start_of_run.is_null()) { |
| 493 queue_duration = (start_of_run - completed_task.EffectiveTimePosted()) | 599 queue_duration = (start_of_run - completed_task.EffectiveTimePosted()) |
| 494 .InMilliseconds(); | 600 .InMilliseconds(); |
| 495 } | 601 } |
| 496 current_thread_data->TallyADeath(*birth, queue_duration, stopwatch); | 602 current_thread_data->TallyADeath(*births, queue_duration, stopwatch); |
| 497 } | 603 } |
| 498 | 604 |
| 499 // static | 605 // static |
| 500 void ThreadData::TallyRunOnWorkerThreadIfTracking( | 606 void ThreadData::TallyRunOnWorkerThreadIfTracking( |
| 501 const Births* birth, | 607 const Births* births, |
| 502 const TrackedTime& time_posted, | 608 const TrackedTime& time_posted, |
| 503 const TaskStopwatch& stopwatch) { | 609 const TaskStopwatch& stopwatch) { |
| 504 // Even if we have been DEACTIVATED, we will process any pending births so | 610 // Even if we have been DEACTIVATED, we will process any pending births so |
| 505 // that our data structures (which counted the outstanding births) remain | 611 // that our data structures (which counted the outstanding births) remain |
| 506 // consistent. | 612 // consistent. |
| 507 if (!birth) | 613 if (!births) |
| 508 return; | 614 return; |
| 509 | 615 |
| 510 // TODO(jar): Support the option to coalesce all worker-thread activity under | 616 // TODO(jar): Support the option to coalesce all worker-thread activity under |
| 511 // one ThreadData instance that uses locks to protect *all* access. This will | 617 // one ThreadData instance that uses locks to protect *all* access. This will |
| 512 // reduce memory (making it provably bounded), but run incrementally slower | 618 // reduce memory (making it provably bounded), but run incrementally slower |
| 513 // (since we'll use locks on TallyABirth and TallyADeath). The good news is | 619 // (since we'll use locks on TallyABirth and TallyADeath). The good news is |
| 514 // that the locks on TallyADeath will be *after* the worker thread has run, | 620 // that the locks on TallyADeath will be *after* the worker thread has run, |
| 515 // and hence nothing will be waiting for the completion (... besides some | 621 // and hence nothing will be waiting for the completion (... besides some |
| 516 // other thread that might like to run). Also, the worker threads tasks are | 622 // other thread that might like to run). Also, the worker threads tasks are |
| 517 // generally longer, and hence the cost of the lock may perchance be amortized | 623 // generally longer, and hence the cost of the lock may perchance be amortized |
| 518 // over the long task's lifetime. | 624 // over the long task's lifetime. |
| 519 ThreadData* current_thread_data = stopwatch.GetThreadData(); | 625 ThreadData* current_thread_data = stopwatch.GetThreadData(); |
| 520 if (!current_thread_data) | 626 if (!current_thread_data) |
| 521 return; | 627 return; |
| 522 | 628 |
| 523 TrackedTime start_of_run = stopwatch.StartTime(); | 629 TrackedTime start_of_run = stopwatch.StartTime(); |
| 524 int32 queue_duration = 0; | 630 int32 queue_duration = 0; |
| 525 if (!start_of_run.is_null()) { | 631 if (!start_of_run.is_null()) { |
| 526 queue_duration = (start_of_run - time_posted).InMilliseconds(); | 632 queue_duration = (start_of_run - time_posted).InMilliseconds(); |
| 527 } | 633 } |
| 528 current_thread_data->TallyADeath(*birth, queue_duration, stopwatch); | 634 current_thread_data->TallyADeath(*births, queue_duration, stopwatch); |
| 529 } | 635 } |
| 530 | 636 |
| 531 // static | 637 // static |
| 532 void ThreadData::TallyRunInAScopedRegionIfTracking( | 638 void ThreadData::TallyRunInAScopedRegionIfTracking( |
| 533 const Births* birth, | 639 const Births* births, |
| 534 const TaskStopwatch& stopwatch) { | 640 const TaskStopwatch& stopwatch) { |
| 535 // Even if we have been DEACTIVATED, we will process any pending births so | 641 // Even if we have been DEACTIVATED, we will process any pending births so |
| 536 // that our data structures (which counted the outstanding births) remain | 642 // that our data structures (which counted the outstanding births) remain |
| 537 // consistent. | 643 // consistent. |
| 538 if (!birth) | 644 if (!births) |
| 539 return; | 645 return; |
| 540 | 646 |
| 541 ThreadData* current_thread_data = stopwatch.GetThreadData(); | 647 ThreadData* current_thread_data = stopwatch.GetThreadData(); |
| 542 if (!current_thread_data) | 648 if (!current_thread_data) |
| 543 return; | 649 return; |
| 544 | 650 |
| 545 int32 queue_duration = 0; | 651 int32 queue_duration = 0; |
| 546 current_thread_data->TallyADeath(*birth, queue_duration, stopwatch); | 652 current_thread_data->TallyADeath(*births, queue_duration, stopwatch); |
| 547 } | |
| 548 | |
| 549 // static | |
| 550 void ThreadData::SnapshotAllExecutedTasks( | |
| 551 ProcessDataPhaseSnapshot* process_data_phase, | |
| 552 BirthCountMap* birth_counts) { | |
| 553 // Get an unchanging copy of a ThreadData list. | |
| 554 ThreadData* my_list = ThreadData::first(); | |
| 555 | |
| 556 // Gather data serially. | |
| 557 // This hackish approach *can* get some slighly corrupt tallies, as we are | |
| 558 // grabbing values without the protection of a lock, but it has the advantage | |
| 559 // of working even with threads that don't have message loops. If a user | |
| 560 // sees any strangeness, they can always just run their stats gathering a | |
| 561 // second time. | |
| 562 for (ThreadData* thread_data = my_list; | |
| 563 thread_data; | |
| 564 thread_data = thread_data->next()) { | |
| 565 thread_data->SnapshotExecutedTasks(process_data_phase, birth_counts); | |
| 566 } | |
| 567 } | |
| 568 | |
| 569 // static | |
| 570 void ThreadData::SnapshotCurrentPhase( | |
| 571 ProcessDataPhaseSnapshot* process_data_phase) { | |
| 572 // Add births that have run to completion to |collected_data|. | |
| 573 // |birth_counts| tracks the total number of births recorded at each location | |
| 574 // for which we have not seen a death count. | |
| 575 BirthCountMap birth_counts; | |
| 576 ThreadData::SnapshotAllExecutedTasks(process_data_phase, &birth_counts); | |
| 577 | |
| 578 // Add births that are still active -- i.e. objects that have tallied a birth, | |
| 579 // but have not yet tallied a matching death, and hence must be either | |
| 580 // running, queued up, or being held in limbo for future posting. | |
| 581 for (const auto& birth_count : birth_counts) { | |
| 582 if (birth_count.second > 0) { | |
| 583 process_data_phase->tasks.push_back(TaskSnapshot( | |
| 584 *birth_count.first, DeathData(birth_count.second), "Still_Alive")); | |
| 585 } | |
| 586 } | |
| 587 } | 653 } |
| 588 | 654 |
| 589 void ThreadData::SnapshotExecutedTasks( | 655 void ThreadData::SnapshotExecutedTasks( |
| 590 ProcessDataPhaseSnapshot* process_data_phase, | 656 int current_profiling_phase, |
| 657 PhasedProcessDataSnapshotMap* phased_process_data_snapshots, | |
| 591 BirthCountMap* birth_counts) { | 658 BirthCountMap* birth_counts) { |
| 592 // Get copy of data, so that the data will not change during the iterations | 659 // Get copy of data, so that the data will not change during the iterations |
| 593 // and processing. | 660 // and processing. |
| 594 ThreadData::BirthMap birth_map; | 661 BirthMap birth_map; |
| 595 ThreadData::DeathMap death_map; | 662 DeathsSnapshot deaths; |
| 596 ThreadData::ParentChildSet parent_child_set; | 663 ParentChildSet parent_child_set; |
| 597 SnapshotMaps(&birth_map, &death_map, &parent_child_set); | 664 SnapshotMaps(current_profiling_phase, &birth_map, &deaths, &parent_child_set); |
| 598 | |
| 599 for (const auto& death : death_map) { | |
| 600 process_data_phase->tasks.push_back( | |
| 601 TaskSnapshot(*death.first, death.second, thread_name())); | |
| 602 (*birth_counts)[death.first] -= death.first->birth_count(); | |
| 603 } | |
| 604 | 665 |
| 605 for (const auto& birth : birth_map) { | 666 for (const auto& birth : birth_map) { |
| 606 (*birth_counts)[birth.second] += birth.second->birth_count(); | 667 (*birth_counts)[birth.second] += birth.second->birth_count(); |
| 607 } | 668 } |
| 608 | 669 |
| 609 if (!kTrackParentChildLinks) | 670 for (const auto& death : deaths) { |
| 610 return; | 671 (*birth_counts)[death.first] -= death.first->birth_count(); |
|
Alexei Svitkine (slow)
2015/04/10 15:27:27
Can you add a DCHECK that the existing value is in
vadimt
2015/04/14 15:52:05
This value can temporarily be negative. We may fir
| |
| 611 | 672 |
| 612 for (const auto& parent_child : parent_child_set) { | 673 // For the current death data, walk through all its snapshots, starting from |
| 613 process_data_phase->descendants.push_back( | 674 // the current one, then from the previous profiling phase etc., and for |
| 614 ParentChildPairSnapshot(parent_child)); | 675 // each snapshot calculate the delta between the snapshot and the previous |
| 676 // phase, if any. Store the deltas in the result. | |
| 677 for (const DeathDataPhaseSnapshot* phase = &death.second; phase; | |
| 678 phase = phase->prev) { | |
| 679 // Taking a temporary copy of the DeathDataSnapshot. We need this copy to | |
| 680 // avoid modification of the original snapshots in the DeathDatas list by | |
| 681 // calling SubtractOlderSnapshot on them. If we modified them, then future | |
| 682 // calls to SnapshotExecutedTasks would return increasingly corrupt | |
| 683 // results. | |
| 684 DeathDataSnapshot death_data = phase->death_data; | |
| 685 | |
| 686 if (phase->prev) | |
| 687 death_data.SubtractOlderSnapshot(phase->prev->death_data); | |
| 688 | |
| 689 if (death_data.count > 0) { | |
| 690 (*phased_process_data_snapshots)[phase->profiling_phase] | |
| 691 .tasks.push_back(TaskSnapshot(BirthOnThreadSnapshot(*death.first), | |
| 692 death_data, thread_name())); | |
| 693 } | |
| 694 } | |
| 615 } | 695 } |
| 616 } | 696 } |
| 617 | 697 |
| 618 // This may be called from another thread. | 698 // This may be called from another thread. |
| 619 void ThreadData::SnapshotMaps(BirthMap* birth_map, | 699 void ThreadData::SnapshotMaps(int profiling_phase, |
| 620 DeathMap* death_map, | 700 BirthMap* birth_map, |
| 701 DeathsSnapshot* deaths, | |
| 621 ParentChildSet* parent_child_set) { | 702 ParentChildSet* parent_child_set) { |
| 622 base::AutoLock lock(map_lock_); | 703 base::AutoLock lock(map_lock_); |
| 704 | |
| 623 for (const auto& birth : birth_map_) | 705 for (const auto& birth : birth_map_) |
| 624 (*birth_map)[birth.first] = birth.second; | 706 (*birth_map)[birth.first] = birth.second; |
| 625 for (const auto& death : death_map_) | 707 |
| 626 (*death_map)[death.first] = death.second; | 708 for (const auto& death : death_map_) { |
| 709 deaths->push_back(DeathsSnapshot::value_type( | |
| 710 death.first, | |
| 711 DeathDataPhaseSnapshot(profiling_phase, death.second.count(), | |
| 712 death.second.run_duration_sum(), | |
| 713 death.second.run_duration_max(), | |
| 714 death.second.run_duration_sample(), | |
| 715 death.second.queue_duration_sum(), | |
| 716 death.second.queue_duration_max(), | |
| 717 death.second.queue_duration_sample(), | |
| 718 death.second.last_phase_snapshot()))); | |
| 719 } | |
| 627 | 720 |
| 628 if (!kTrackParentChildLinks) | 721 if (!kTrackParentChildLinks) |
| 629 return; | 722 return; |
| 630 | 723 |
| 631 for (const auto& parent_child : parent_child_set_) | 724 for (const auto& parent_child : parent_child_set_) |
| 632 parent_child_set->insert(parent_child); | 725 parent_child_set->insert(parent_child); |
| 633 } | 726 } |
| 634 | 727 |
| 728 void ThreadData::OnProfilingPhaseCompletionOnThread(int profiling_phase) { | |
| 729 base::AutoLock lock(map_lock_); | |
| 730 | |
| 731 for (auto& death : death_map_) { | |
| 732 death.second.OnProfilingPhaseCompleted(profiling_phase); | |
| 733 } | |
| 734 } | |
| 735 | |
| 635 static void OptionallyInitializeAlternateTimer() { | 736 static void OptionallyInitializeAlternateTimer() { |
| 636 NowFunction* alternate_time_source = GetAlternateTimeSource(); | 737 NowFunction* alternate_time_source = GetAlternateTimeSource(); |
| 637 if (alternate_time_source) | 738 if (alternate_time_source) |
| 638 ThreadData::SetAlternateTimeSource(alternate_time_source); | 739 ThreadData::SetAlternateTimeSource(alternate_time_source); |
| 639 } | 740 } |
| 640 | 741 |
| 641 bool ThreadData::Initialize() { | 742 bool ThreadData::Initialize() { |
| 642 if (status_ >= DEACTIVATED) | 743 if (status_ >= DEACTIVATED) |
| 643 return true; // Someone else did the initialization. | 744 return true; // Someone else did the initialization. |
| 644 // Due to racy lazy initialization in tests, we'll need to recheck status_ | 745 // Due to racy lazy initialization in tests, we'll need to recheck status_ |
| (...skipping 257 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
| 902 | 1003 |
| 903 ThreadData* TaskStopwatch::GetThreadData() const { | 1004 ThreadData* TaskStopwatch::GetThreadData() const { |
| 904 #if DCHECK_IS_ON() | 1005 #if DCHECK_IS_ON() |
| 905 DCHECK(state_ != CREATED); | 1006 DCHECK(state_ != CREATED); |
| 906 #endif | 1007 #endif |
| 907 | 1008 |
| 908 return current_thread_data_; | 1009 return current_thread_data_; |
| 909 } | 1010 } |
| 910 | 1011 |
| 911 //------------------------------------------------------------------------------ | 1012 //------------------------------------------------------------------------------ |
| 1013 // DeathDataPhaseSnapshot | |
| 1014 | |
| 1015 DeathDataPhaseSnapshot::DeathDataPhaseSnapshot(int profiling_phase, | |
| 1016 int count, | |
| 1017 int32 run_duration_sum, | |
| 1018 int32 run_duration_max, | |
| 1019 int32 run_duration_sample, | |
| 1020 int32 queue_duration_sum, | |
| 1021 int32 queue_duration_max, | |
| 1022 int32 queue_duration_sample, | |
| 1023 DeathDataPhaseSnapshot* prev) | |
| 1024 : profiling_phase(profiling_phase), | |
| 1025 death_data(count, | |
| 1026 run_duration_sum, | |
| 1027 run_duration_max, | |
| 1028 run_duration_sample, | |
| 1029 queue_duration_sum, | |
| 1030 queue_duration_max, | |
| 1031 queue_duration_sample), | |
| 1032 prev(prev) { | |
| 1033 } | |
| 1034 | |
| 1035 //------------------------------------------------------------------------------ | |
| 1036 // TaskSnapshot | |
| 1037 | |
| 912 TaskSnapshot::TaskSnapshot() { | 1038 TaskSnapshot::TaskSnapshot() { |
| 913 } | 1039 } |
| 914 | 1040 |
| 915 TaskSnapshot::TaskSnapshot(const BirthOnThread& birth, | 1041 TaskSnapshot::TaskSnapshot(const BirthOnThreadSnapshot& birth, |
| 916 const DeathData& death_data, | 1042 const DeathDataSnapshot& death_data, |
| 917 const std::string& death_thread_name) | 1043 const std::string& death_thread_name) |
| 918 : birth(birth), | 1044 : birth(birth), |
| 919 death_data(death_data), | 1045 death_data(death_data), |
| 920 death_thread_name(death_thread_name) { | 1046 death_thread_name(death_thread_name) { |
| 921 } | 1047 } |
| 922 | 1048 |
| 923 TaskSnapshot::~TaskSnapshot() { | 1049 TaskSnapshot::~TaskSnapshot() { |
| 924 } | 1050 } |
| 925 | 1051 |
| 926 //------------------------------------------------------------------------------ | 1052 //------------------------------------------------------------------------------ |
| (...skipping 28 matching lines...) Expand all Loading... | |
| 955 : process_id(base::GetCurrentProcId()) { | 1081 : process_id(base::GetCurrentProcId()) { |
| 956 #else | 1082 #else |
| 957 : process_id(base::kNullProcessId) { | 1083 : process_id(base::kNullProcessId) { |
| 958 #endif | 1084 #endif |
| 959 } | 1085 } |
| 960 | 1086 |
| 961 ProcessDataSnapshot::~ProcessDataSnapshot() { | 1087 ProcessDataSnapshot::~ProcessDataSnapshot() { |
| 962 } | 1088 } |
| 963 | 1089 |
| 964 } // namespace tracked_objects | 1090 } // namespace tracked_objects |
| OLD | NEW |