Add heap allocator usage to task profiler.

base/tracked_objects.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/tracked_objects.h"
 
 #include <limits.h>
 #include <stdlib.h>
 
 #include "base/atomicops.h"
 #include "base/base_switches.h"
 #include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/debug/leak_annotations.h"
 #include "base/logging.h"
+#include "base/numerics/safe_conversions.h"
+#include "base/numerics/safe_math.h"
 #include "base/process/process_handle.h"
 #include "base/strings/stringprintf.h"
 #include "base/third_party/valgrind/memcheck.h"
 #include "base/threading/worker_pool.h"
 #include "base/tracking_info.h"
 #include "build/build_config.h"
 
 using base::TimeDelta;
 
 namespace base {
@@ skipping 41 matching lines @@
              switches::kProfilerTiming) ==
          switches::kProfilerTimingDisabledValue)
             ? DISABLED_TIMING
             : ENABLED_TIMING;
     base::subtle::NoBarrier_Store(&g_profiler_timing_enabled,
                                   current_timing_enabled);
   }
   return current_timing_enabled == ENABLED_TIMING;
 }
 
+void SaturatingAdd(const uint32_t addend, base::subtle::Atomic32* sum) {
+  // Bail quick if no work or already saturated.
+  if (addend == 0U || *sum == INT_MAX)
+    return;
+
+  base::CheckedNumeric<int32_t> new_sum = *sum;

[dcheng, 2016/12/01 07:44:28]

How come it's safe to skip using an atomic load operation here?

(I see primiano@ made the same comment, and I share the same concerns: see
RecordDurations, which does use atomic loads to read out variables)

[dcheng, 2016/12/01 07:48:26]

(Argh, upon looking again, I see that it's just one thing that decided to Load,
everything else only uses atomics for store...)

Still, it seems hard to understand why this is considered correct... guess I'll
go do some reading.

[Sigurður Ásgeirsson, 2016/12/01 14:01:11]

This is done for consistency with all other DeathData member access. See
::RecordDurations for how this is originally authored. Presumably the original
author has a performance argument for doing it this way, but I believe this is
safe as only the owning thread will ever write DeathData members. There's also
documentation at the top of tracked_objects.h on how all this machinery
sacrifices absolute momentary correctness for performance and eventual
consistency, which I believe is the right tradeoff here.

I've turned this this function into a private member of the DeathData class to
enforce that this won't be applied to anything but members of that class.

Note that I'm in no way opposed to using the atomic methods for accessing these
members. However, I think that change should be made separately, for all
DeathData members, in a different CL. The performance impact of that CL should
be measured VERY carefully, as I don't pretend to understand the perf
implications to any of this.

[Sigurður Ásgeirsson, 2016/12/01 14:01:11]

Acknowledged.

+  new_sum += addend;
+  base::subtle::NoBarrier_Store(sum, new_sum.ValueOrDefault(INT_MAX));
+}
+
 }  // namespace
 
 //------------------------------------------------------------------------------
 // DeathData tallies durations when a death takes place.
 
 DeathData::DeathData()
     : count_(0),
       sample_probability_count_(0),
       run_duration_sum_(0),
       queue_duration_sum_(0),
       run_duration_max_(0),
       queue_duration_max_(0),
       run_duration_sample_(0),
       queue_duration_sample_(0),
-      last_phase_snapshot_(nullptr) {
-}
+      alloc_ops_(0),
+      free_ops_(0),
+      allocated_bytes_(0),
+      freed_bytes_(0),
+      alloc_overhead_bytes_(0),
+      max_allocated_bytes_(0),
+      last_phase_snapshot_(nullptr) {}
 
 DeathData::DeathData(const DeathData& other)
     : count_(other.count_),
       sample_probability_count_(other.sample_probability_count_),
       run_duration_sum_(other.run_duration_sum_),
       queue_duration_sum_(other.queue_duration_sum_),
       run_duration_max_(other.run_duration_max_),
       queue_duration_max_(other.queue_duration_max_),
       run_duration_sample_(other.run_duration_sample_),
       queue_duration_sample_(other.queue_duration_sample_),
+      alloc_ops_(other.alloc_ops_),
+      free_ops_(other.free_ops_),
+      allocated_bytes_(other.allocated_bytes_),
+      freed_bytes_(other.freed_bytes_),
+      alloc_overhead_bytes_(other.alloc_overhead_bytes_),
+      max_allocated_bytes_(other.max_allocated_bytes_),
       last_phase_snapshot_(nullptr) {
   // This constructor will be used by std::map when adding new DeathData values
   // to the map.  At that point, last_phase_snapshot_ is still NULL, so we don't
   // need to worry about ownership transfer.
   DCHECK(other.last_phase_snapshot_ == nullptr);
 }
 
 DeathData::~DeathData() {
   while (last_phase_snapshot_) {
     const DeathDataPhaseSnapshot* snapshot = last_phase_snapshot_;
     last_phase_snapshot_ = snapshot->prev;
     delete snapshot;
   }
 }
 
 // TODO(jar): I need to see if this macro to optimize branching is worth using.
 //
 // This macro has no branching, so it is surely fast, and is equivalent to:
 //             if (assign_it)
 //               target = source;
 // We use a macro rather than a template to force this to inline.
 // Related code for calculating max is discussed on the web.
 #define CONDITIONAL_ASSIGN(assign_it, target, source) \
   ((target) ^= ((target) ^ (source)) & -static_cast<int32_t>(assign_it))
 
-void DeathData::RecordDeath(const int32_t queue_duration,
-                            const int32_t run_duration,
-                            const uint32_t random_number) {
+void DeathData::RecordDurations(const int32_t queue_duration,
+                                const int32_t run_duration,
+                                const uint32_t random_number) {
   // We'll just clamp at INT_MAX, but we should note this in the UI as such.
   if (count_ < INT_MAX)
     base::subtle::NoBarrier_Store(&count_, count_ + 1);
 
   int sample_probability_count =
       base::subtle::NoBarrier_Load(&sample_probability_count_);
   if (sample_probability_count < INT_MAX)
     ++sample_probability_count;
   base::subtle::NoBarrier_Store(&sample_probability_count_,
                                 sample_probability_count);
@@ skipping 16 matching lines @@
   // but that should be inconsequentially likely).  We ignore the fact that we
   // correlated our selection of a sample to the run and queue times (i.e., we
   // used them to generate random_number).
   CHECK_GT(sample_probability_count, 0);
   if (0 == (random_number % sample_probability_count)) {
     base::subtle::NoBarrier_Store(&queue_duration_sample_, queue_duration);
     base::subtle::NoBarrier_Store(&run_duration_sample_, run_duration);
   }
 }
 
+void DeathData::RecordAllocations(const uint32_t alloc_ops,
+                                  const uint32_t free_ops,
+                                  const uint32_t allocated_bytes,
+                                  const uint32_t freed_bytes,
+                                  const uint32_t alloc_overhead_bytes,
+                                  const uint32_t max_allocated_bytes) {
+  // Use saturating arithmetic.
+  SaturatingAdd(alloc_ops, &alloc_ops_);
+  SaturatingAdd(free_ops, &free_ops_);
+  SaturatingAdd(allocated_bytes, &allocated_bytes_);
+  SaturatingAdd(freed_bytes, &freed_bytes_);
+  SaturatingAdd(alloc_overhead_bytes, &alloc_overhead_bytes_);
+
+  int32_t max = base::saturated_cast<int32_t>(max_allocated_bytes);
+  if (max > max_allocated_bytes_)
+    base::subtle::NoBarrier_Store(&max_allocated_bytes_, max);
+}
+
 void DeathData::OnProfilingPhaseCompleted(int profiling_phase) {
   // Snapshotting and storing current state.
-  last_phase_snapshot_ = new DeathDataPhaseSnapshot(
-      profiling_phase, count(), run_duration_sum(), run_duration_max(),
-      run_duration_sample(), queue_duration_sum(), queue_duration_max(),
-      queue_duration_sample(), last_phase_snapshot_);
+  last_phase_snapshot_ =
+      new DeathDataPhaseSnapshot(profiling_phase, *this, last_phase_snapshot_);
 
   // Not touching fields for which a delta can be computed by comparing with a
   // snapshot from the previous phase. Resetting other fields.  Sample values
   // will be reset upon next death recording because sample_probability_count_
   // is set to 0.
   // We avoid resetting to 0 in favor of deltas whenever possible.  The reason
   // is that for incrementable fields, resetting to 0 from the snapshot thread
   // potentially in parallel with incrementing in the death thread may result in
   // significant data corruption that has a potential to grow with time.  Not
   // resetting incrementable fields and using deltas will cause any
@@ skipping 19 matching lines @@
 }
 
 //------------------------------------------------------------------------------
 DeathDataSnapshot::DeathDataSnapshot()
     : count(-1),
       run_duration_sum(-1),
       run_duration_max(-1),
       run_duration_sample(-1),
       queue_duration_sum(-1),
       queue_duration_max(-1),
-      queue_duration_sample(-1) {
-}
+      queue_duration_sample(-1),
+      alloc_ops(-1),
+      free_ops(-1),
+      allocated_bytes(-1),
+      freed_bytes(-1),
+      alloc_overhead_bytes(-1),
+      max_allocated_bytes(-1) {}
 
 DeathDataSnapshot::DeathDataSnapshot(int count,
                                      int32_t run_duration_sum,
                                      int32_t run_duration_max,
                                      int32_t run_duration_sample,
                                      int32_t queue_duration_sum,
                                      int32_t queue_duration_max,
-                                     int32_t queue_duration_sample)
+                                     int32_t queue_duration_sample,
+                                     int32_t alloc_ops,
+                                     int32_t free_ops,
+                                     int32_t allocated_bytes,
+                                     int32_t freed_bytes,
+                                     int32_t alloc_overhead_bytes,
+                                     int32_t max_allocated_bytes)
     : count(count),
       run_duration_sum(run_duration_sum),
       run_duration_max(run_duration_max),
       run_duration_sample(run_duration_sample),
       queue_duration_sum(queue_duration_sum),
       queue_duration_max(queue_duration_max),
-      queue_duration_sample(queue_duration_sample) {}
+      queue_duration_sample(queue_duration_sample),
+      alloc_ops(alloc_ops),
+      free_ops(free_ops),
+      allocated_bytes(allocated_bytes),
+      freed_bytes(freed_bytes),
+      alloc_overhead_bytes(alloc_overhead_bytes),
+      max_allocated_bytes(max_allocated_bytes) {}
+
+DeathDataSnapshot::DeathDataSnapshot(const DeathData& death_data)
+    : count(death_data.count()),
+      run_duration_sum(death_data.run_duration_sum()),
+      run_duration_max(death_data.run_duration_max()),
+      run_duration_sample(death_data.run_duration_sample()),
+      queue_duration_sum(death_data.queue_duration_sum()),
+      queue_duration_max(death_data.queue_duration_max()),
+      queue_duration_sample(death_data.queue_duration_sample()),
+      alloc_ops(death_data.alloc_ops()),
+      free_ops(death_data.free_ops()),
+      allocated_bytes(death_data.allocated_bytes()),
+      freed_bytes(death_data.freed_bytes()),
+      alloc_overhead_bytes(death_data.alloc_overhead_bytes()),
+      max_allocated_bytes(death_data.max_allocated_bytes()) {}
+
+DeathDataSnapshot::DeathDataSnapshot(const DeathDataSnapshot& death_data) =
+    default;
 
 DeathDataSnapshot::~DeathDataSnapshot() {
 }
 
 DeathDataSnapshot DeathDataSnapshot::Delta(
     const DeathDataSnapshot& older) const {
-  return DeathDataSnapshot(count - older.count,
-                           run_duration_sum - older.run_duration_sum,
-                           run_duration_max, run_duration_sample,
-                           queue_duration_sum - older.queue_duration_sum,
-                           queue_duration_max, queue_duration_sample);
+  return DeathDataSnapshot(
+      count - older.count, run_duration_sum - older.run_duration_sum,
+      run_duration_max, run_duration_sample,
+      queue_duration_sum - older.queue_duration_sum, queue_duration_max,
+      queue_duration_sample, alloc_ops - older.alloc_ops,
+      free_ops - older.free_ops, allocated_bytes - older.allocated_bytes,
+      freed_bytes - older.freed_bytes,
+      alloc_overhead_bytes - older.alloc_overhead_bytes, max_allocated_bytes);
 }
 
 //------------------------------------------------------------------------------
 BirthOnThread::BirthOnThread(const Location& location,
                              const ThreadData& current)
     : location_(location),
       birth_thread_(&current) {
 }
 
 //------------------------------------------------------------------------------
@@ skipping 198 matching lines @@
 
   // Add births that are still active -- i.e. objects that have tallied a birth,
   // but have not yet tallied a matching death, and hence must be either
   // running, queued up, or being held in limbo for future posting.
   auto* current_phase_tasks =
       &process_data_snapshot->phased_snapshots[current_profiling_phase].tasks;
   for (const auto& birth_count : birth_counts) {
     if (birth_count.second > 0) {
       current_phase_tasks->push_back(
           TaskSnapshot(BirthOnThreadSnapshot(*birth_count.first),
-                       DeathDataSnapshot(birth_count.second, 0, 0, 0, 0, 0, 0),
+                       DeathDataSnapshot(birth_count.second, 0, 0, 0, 0, 0, 0,
+                                         0, 0, 0, 0, 0, 0),
                        "Still_Alive"));
     }
   }
 }
 
 // static
 void ThreadData::OnProfilingPhaseCompleted(int profiling_phase) {
   // Get an unchanging copy of a ThreadData list.
   ThreadData* my_list = ThreadData::first();
 
@@ skipping 38 matching lines @@
       static_cast<uint32_t>(&births - reinterpret_cast<Births*>(0));
 
   DeathMap::iterator it = death_map_.find(&births);
   DeathData* death_data;
   if (it != death_map_.end()) {
     death_data = &it->second;
   } else {
     base::AutoLock lock(map_lock_);  // Lock as the map may get relocated now.
     death_data = &death_map_[&births];
   }  // Release lock ASAP.
-  death_data->RecordDeath(queue_duration, run_duration, random_number_);
+  death_data->RecordDurations(queue_duration, run_duration, random_number_);
+
+#if BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+  if (stopwatch.heap_tracking_enabled()) {
+    base::debug::ThreadHeapUsage heap_usage = stopwatch.heap_usage().usage();
+    // Saturate the 64 bit counts on conversion to 32 bit storage.
+    death_data->RecordAllocations(
+        base::saturated_cast<int32_t>(heap_usage.alloc_ops),
+        base::saturated_cast<int32_t>(heap_usage.free_ops),
+        base::saturated_cast<int32_t>(heap_usage.alloc_bytes),
+        base::saturated_cast<int32_t>(heap_usage.free_bytes),
+        base::saturated_cast<int32_t>(heap_usage.alloc_overhead_bytes),
+        base::saturated_cast<int32_t>(heap_usage.max_allocated_bytes));
+  }
+#endif
 }
 
 // static
 Births* ThreadData::TallyABirthIfActive(const Location& location) {
   if (!TrackingStatus())
     return NULL;
   ThreadData* current_thread_data = Get();
   if (!current_thread_data)
     return NULL;
   return current_thread_data->TallyABirth(location);
@@ skipping 118 matching lines @@
                               BirthMap* birth_map,
                               DeathsSnapshot* deaths) {
   base::AutoLock lock(map_lock_);
 
   for (const auto& birth : birth_map_)
     (*birth_map)[birth.first] = birth.second;
 
   for (const auto& death : death_map_) {
     deaths->push_back(std::make_pair(
         death.first,
-        DeathDataPhaseSnapshot(profiling_phase, death.second.count(),
-                               death.second.run_duration_sum(),
-                               death.second.run_duration_max(),
-                               death.second.run_duration_sample(),
-                               death.second.queue_duration_sum(),
-                               death.second.queue_duration_max(),
-                               death.second.queue_duration_sample(),
+        DeathDataPhaseSnapshot(profiling_phase, death.second,
                                death.second.last_phase_snapshot())));
   }
 }
 
 void ThreadData::OnProfilingPhaseCompletedOnThread(int profiling_phase) {
   base::AutoLock lock(map_lock_);
 
   for (auto& death : death_map_) {
     death.second.OnProfilingPhaseCompleted(profiling_phase);
   }
@@ skipping 25 matching lines @@
 
   // Incarnation counter is only significant to testing, as it otherwise will
   // never again change in this process.
   ++incarnation_counter_;
 
   // The lock is not critical for setting status_, but it doesn't hurt.  It also
   // ensures that if we have a racy initialization, that we'll bail as soon as
   // we get the lock earlier in this method.
   base::subtle::Release_Store(&status_, kInitialStartupState);
   DCHECK(base::subtle::NoBarrier_Load(&status_) != UNINITIALIZED);
+
+#if BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+  // Make sure heap tracking is enabled ASAP if the default state is active.
+  if (kInitialStartupState == PROFILING_ACTIVE &&
+      !base::debug::ThreadHeapUsageTracker::IsHeapTrackingEnabled()) {
+    base::debug::ThreadHeapUsageTracker::EnableHeapTracking();
+  }
+#endif  // BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
 }
 
 // static
 void ThreadData::InitializeAndSetTrackingStatus(Status status) {
   DCHECK_GE(status, DEACTIVATED);
   DCHECK_LE(status, PROFILING_ACTIVE);
 
   EnsureTlsInitialization();  // No-op if already initialized.
 
-  if (status > DEACTIVATED)
+  if (status > DEACTIVATED) {
     status = PROFILING_ACTIVE;
+
+#if BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+    if (!base::debug::ThreadHeapUsageTracker::IsHeapTrackingEnabled())
+      base::debug::ThreadHeapUsageTracker::EnableHeapTracking();
+#endif  // BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+  }
   base::subtle::Release_Store(&status_, status);
 }
 
 // static
 ThreadData::Status ThreadData::status() {
   return static_cast<ThreadData::Status>(base::subtle::Acquire_Load(&status_));
 }
 
 // static
 bool ThreadData::TrackingStatus() {
@@ skipping 87 matching lines @@
 //------------------------------------------------------------------------------
 TaskStopwatch::TaskStopwatch()
     : wallclock_duration_ms_(0),
       current_thread_data_(NULL),
       excluded_duration_ms_(0),
       parent_(NULL) {
 #if DCHECK_IS_ON()
   state_ = CREATED;
   child_ = NULL;
 #endif
+#if BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+  heap_tracking_enabled_ =
+      base::debug::ThreadHeapUsageTracker::IsHeapTrackingEnabled();
+#endif
 }
 
 TaskStopwatch::~TaskStopwatch() {
 #if DCHECK_IS_ON()
   DCHECK(state_ != RUNNING);
   DCHECK(child_ == NULL);
 #endif
 }
 
 void TaskStopwatch::Start() {
 #if DCHECK_IS_ON()
   DCHECK(state_ == CREATED);
   state_ = RUNNING;
 #endif
 
   start_time_ = ThreadData::Now();
+#if BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+  if (heap_tracking_enabled_)
+    heap_usage_.Start();
+#endif
 
   current_thread_data_ = ThreadData::Get();
   if (!current_thread_data_)
     return;
 
   parent_ = current_thread_data_->current_stopwatch_;
 #if DCHECK_IS_ON()
   if (parent_) {
     DCHECK(parent_->state_ == RUNNING);
     DCHECK(parent_->child_ == NULL);
     parent_->child_ = this;
   }
 #endif
   current_thread_data_->current_stopwatch_ = this;
 }
 
 void TaskStopwatch::Stop() {
   const TrackedTime end_time = ThreadData::Now();
 #if DCHECK_IS_ON()
   DCHECK(state_ == RUNNING);
   state_ = STOPPED;
   DCHECK(child_ == NULL);
 #endif
+#if BUILDFLAG(ENABLE_MEMORY_TASK_PROFILER)
+  if (heap_tracking_enabled_)
+    heap_usage_.Stop(true);
+#endif
 
   if (!start_time_.is_null() && !end_time.is_null()) {
     wallclock_duration_ms_ = (end_time - start_time_).InMilliseconds();
   }
 
   if (!current_thread_data_)
     return;
 
   DCHECK(current_thread_data_->current_stopwatch_ == this);
   current_thread_data_->current_stopwatch_ = parent_;
@@ skipping 31 matching lines @@
 #endif
 
   return current_thread_data_;
 }
 
 //------------------------------------------------------------------------------
 // DeathDataPhaseSnapshot
 
 DeathDataPhaseSnapshot::DeathDataPhaseSnapshot(
     int profiling_phase,
-    int count,
-    int32_t run_duration_sum,
-    int32_t run_duration_max,
-    int32_t run_duration_sample,
-    int32_t queue_duration_sum,
-    int32_t queue_duration_max,
-    int32_t queue_duration_sample,
+    const DeathData& death,
     const DeathDataPhaseSnapshot* prev)
-    : profiling_phase(profiling_phase),
-      death_data(count,
-                 run_duration_sum,
-                 run_duration_max,
-                 run_duration_sample,
-                 queue_duration_sum,
-                 queue_duration_max,
-                 queue_duration_sample),
-      prev(prev) {}
+    : profiling_phase(profiling_phase), death_data(death), prev(prev) {}
 
 //------------------------------------------------------------------------------
 // TaskSnapshot
 
 TaskSnapshot::TaskSnapshot() {
 }
 
 TaskSnapshot::TaskSnapshot(const BirthOnThreadSnapshot& birth,
                            const DeathDataSnapshot& death_data,
                            const std::string& death_thread_name)
@@ skipping 28 matching lines @@
 #endif
 }
 
 ProcessDataSnapshot::ProcessDataSnapshot(const ProcessDataSnapshot& other) =
     default;
 
 ProcessDataSnapshot::~ProcessDataSnapshot() {
 }
 
 }  // namespace tracked_objects