Home | History | Annotate | Download | only in debug
      1 // Copyright 2013 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 #include "base/debug/trace_event_memory.h"
      6 
      7 #include "base/debug/leak_annotations.h"
      8 #include "base/debug/trace_event.h"
      9 #include "base/lazy_instance.h"
     10 #include "base/logging.h"
     11 #include "base/memory/scoped_ptr.h"
     12 #include "base/message_loop/message_loop.h"
     13 #include "base/strings/string_number_conversions.h"
     14 #include "base/strings/string_util.h"
     15 #include "base/threading/thread_local_storage.h"
     16 
     17 namespace base {
     18 namespace debug {
     19 
     20 namespace {
     21 
     22 // Maximum number of nested TRACE_MEMORY scopes to record. Must be greater than
     23 // or equal to HeapProfileTable::kMaxStackDepth.
     24 const size_t kMaxStackSize = 32;
     25 
     26 /////////////////////////////////////////////////////////////////////////////
     27 // Holds a memory dump until the tracing system needs to serialize it.
     28 class MemoryDumpHolder : public base::debug::ConvertableToTraceFormat {
     29  public:
     30   // Takes ownership of dump, which must be a JSON string, allocated with
     31   // malloc() and NULL terminated.
     32   explicit MemoryDumpHolder(char* dump) : dump_(dump) {}
     33   virtual ~MemoryDumpHolder() { free(dump_); }
     34 
     35   // base::debug::ConvertableToTraceFormat overrides:
     36   virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE {
     37     AppendHeapProfileAsTraceFormat(dump_, out);
     38   }
     39 
     40  private:
     41   char* dump_;
     42 
     43   DISALLOW_COPY_AND_ASSIGN(MemoryDumpHolder);
     44 };
     45 
     46 /////////////////////////////////////////////////////////////////////////////
     47 // Records a stack of TRACE_MEMORY events. One per thread is required.
     48 struct TraceMemoryStack {
     49   TraceMemoryStack() : index_(0) {
     50     memset(category_stack_, 0, kMaxStackSize * sizeof(category_stack_[0]));
     51   }
     52 
     53   // Points to the next free entry.
     54   size_t index_;
     55   const char* category_stack_[kMaxStackSize];
     56 };
     57 
     58 // Pointer to a TraceMemoryStack per thread.
     59 base::ThreadLocalStorage::StaticSlot tls_trace_memory_stack = TLS_INITIALIZER;
     60 
     61 // Clean up memory pointed to by our thread-local storage.
     62 void DeleteStackOnThreadCleanup(void* value) {
     63   TraceMemoryStack* stack = static_cast<TraceMemoryStack*>(value);
     64   delete stack;
     65 }
     66 
     67 // Initializes the thread-local TraceMemoryStack pointer. Returns true on
     68 // success or if it is already initialized.
     69 bool InitThreadLocalStorage() {
     70   if (tls_trace_memory_stack.initialized())
     71     return true;
     72   // Initialize the thread-local storage key, returning true on success.
     73   return tls_trace_memory_stack.Initialize(&DeleteStackOnThreadCleanup);
     74 }
     75 
     76 // Clean up thread-local-storage in the main thread.
     77 void CleanupThreadLocalStorage() {
     78   if (!tls_trace_memory_stack.initialized())
     79     return;
     80   TraceMemoryStack* stack =
     81       static_cast<TraceMemoryStack*>(tls_trace_memory_stack.Get());
     82   delete stack;
     83   tls_trace_memory_stack.Set(NULL);
     84   // Intentionally do not release the thread-local-storage key here, that is,
     85   // do not call tls_trace_memory_stack.Free(). Other threads have lazily
     86   // created pointers in thread-local-storage via GetTraceMemoryStack() below.
     87   // Those threads need to run the DeleteStack() destructor function when they
     88   // exit. If we release the key the destructor will not be called and those
     89   // threads will not clean up their memory.
     90 }
     91 
     92 // Returns the thread-local trace memory stack for the current thread, creating
     93 // one if needed. Returns NULL if the thread-local storage key isn't
     94 // initialized, which indicates that heap profiling isn't running.
     95 TraceMemoryStack* GetTraceMemoryStack() {
     96   TraceMemoryStack* stack =
     97       static_cast<TraceMemoryStack*>(tls_trace_memory_stack.Get());
     98   // Lazily initialize TraceMemoryStack objects for new threads.
     99   if (!stack) {
    100     stack = new TraceMemoryStack;
    101     tls_trace_memory_stack.Set(stack);
    102   }
    103   return stack;
    104 }
    105 
    106 // Returns a "pseudo-stack" of pointers to trace events.
    107 // TODO(jamescook): Record both category and name, perhaps in a pair for speed.
    108 int GetPseudoStack(int skip_count_ignored, void** stack_out) {
    109   // If the tracing system isn't fully initialized, just skip this allocation.
    110   // Attempting to initialize will allocate memory, causing this function to
    111   // be called recursively from inside the allocator.
    112   if (!tls_trace_memory_stack.initialized() || !tls_trace_memory_stack.Get())
    113     return 0;
    114   TraceMemoryStack* stack =
    115       static_cast<TraceMemoryStack*>(tls_trace_memory_stack.Get());
    116   // Copy at most kMaxStackSize stack entries.
    117   const size_t count = std::min(stack->index_, kMaxStackSize);
    118   // Notes that memcpy() works for zero bytes.
    119   memcpy(stack_out,
    120          stack->category_stack_,
    121          count * sizeof(stack->category_stack_[0]));
    122   // Function must return an int to match the signature required by tcmalloc.
    123   return static_cast<int>(count);
    124 }
    125 
    126 }  // namespace
    127 
    128 //////////////////////////////////////////////////////////////////////////////
    129 
    130 TraceMemoryController::TraceMemoryController(
    131     scoped_refptr<MessageLoopProxy> message_loop_proxy,
    132     HeapProfilerStartFunction heap_profiler_start_function,
    133     HeapProfilerStopFunction heap_profiler_stop_function,
    134     GetHeapProfileFunction get_heap_profile_function)
    135     : message_loop_proxy_(message_loop_proxy),
    136       heap_profiler_start_function_(heap_profiler_start_function),
    137       heap_profiler_stop_function_(heap_profiler_stop_function),
    138       get_heap_profile_function_(get_heap_profile_function),
    139       weak_factory_(this) {
    140   // Force the "memory" category to show up in the trace viewer.
    141   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("memory"), "init");
    142   // Watch for the tracing system being enabled.
    143   TraceLog::GetInstance()->AddEnabledStateObserver(this);
    144 }
    145 
    146 TraceMemoryController::~TraceMemoryController() {
    147   if (dump_timer_.IsRunning())
    148     StopProfiling();
    149   TraceLog::GetInstance()->RemoveEnabledStateObserver(this);
    150 }
    151 
    152   // base::debug::TraceLog::EnabledStateChangedObserver overrides:
    153 void TraceMemoryController::OnTraceLogEnabled() {
    154   // Check to see if tracing is enabled for the memory category.
    155   bool enabled;
    156   TRACE_EVENT_CATEGORY_GROUP_ENABLED(TRACE_DISABLED_BY_DEFAULT("memory"),
    157                                      &enabled);
    158   if (!enabled)
    159     return;
    160   DVLOG(1) << "OnTraceLogEnabled";
    161   message_loop_proxy_->PostTask(
    162       FROM_HERE,
    163       base::Bind(&TraceMemoryController::StartProfiling,
    164                  weak_factory_.GetWeakPtr()));
    165 }
    166 
    167 void TraceMemoryController::OnTraceLogDisabled() {
    168   // The memory category is always disabled before OnTraceLogDisabled() is
    169   // called, so we cannot tell if it was enabled before. Always try to turn
    170   // off profiling.
    171   DVLOG(1) << "OnTraceLogDisabled";
    172   message_loop_proxy_->PostTask(
    173       FROM_HERE,
    174       base::Bind(&TraceMemoryController::StopProfiling,
    175                  weak_factory_.GetWeakPtr()));
    176 }
    177 
    178 void TraceMemoryController::StartProfiling() {
    179   // Watch for the tracing framework sending enabling more than once.
    180   if (dump_timer_.IsRunning())
    181     return;
    182   DVLOG(1) << "Starting trace memory";
    183   if (!InitThreadLocalStorage())
    184     return;
    185   ScopedTraceMemory::set_enabled(true);
    186   // Call ::HeapProfilerWithPseudoStackStart().
    187   heap_profiler_start_function_(&GetPseudoStack);
    188   const int kDumpIntervalSeconds = 5;
    189   dump_timer_.Start(FROM_HERE,
    190                     TimeDelta::FromSeconds(kDumpIntervalSeconds),
    191                     base::Bind(&TraceMemoryController::DumpMemoryProfile,
    192                                weak_factory_.GetWeakPtr()));
    193 }
    194 
    195 void TraceMemoryController::DumpMemoryProfile() {
    196   // Don't trace allocations here in the memory tracing system.
    197   INTERNAL_TRACE_MEMORY(TRACE_DISABLED_BY_DEFAULT("memory"),
    198                         TRACE_MEMORY_IGNORE);
    199 
    200   DVLOG(1) << "DumpMemoryProfile";
    201   // MemoryDumpHolder takes ownership of this string. See GetHeapProfile() in
    202   // tcmalloc for details.
    203   char* dump = get_heap_profile_function_();
    204   scoped_ptr<MemoryDumpHolder> dump_holder(new MemoryDumpHolder(dump));
    205   const int kSnapshotId = 1;
    206   TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
    207       TRACE_DISABLED_BY_DEFAULT("memory"),
    208       "memory::Heap",
    209       kSnapshotId,
    210       dump_holder.PassAs<base::debug::ConvertableToTraceFormat>());
    211 }
    212 
    213 void TraceMemoryController::StopProfiling() {
    214   // Watch for the tracing framework sending disabled more than once.
    215   if (!dump_timer_.IsRunning())
    216     return;
    217   DVLOG(1) << "Stopping trace memory";
    218   dump_timer_.Stop();
    219   ScopedTraceMemory::set_enabled(false);
    220   CleanupThreadLocalStorage();
    221   // Call ::HeapProfilerStop().
    222   heap_profiler_stop_function_();
    223 }
    224 
    225 bool TraceMemoryController::IsTimerRunningForTest() const {
    226   return dump_timer_.IsRunning();
    227 }
    228 
    229 /////////////////////////////////////////////////////////////////////////////
    230 
    231 // static
    232 bool ScopedTraceMemory::enabled_ = false;
    233 
    234 ScopedTraceMemory::ScopedTraceMemory(const char* category) {
    235   // Not enabled indicates that the trace system isn't running, so don't
    236   // record anything.
    237   if (!enabled_)
    238     return;
    239   // Get our thread's copy of the stack.
    240   TraceMemoryStack* trace_memory_stack = GetTraceMemoryStack();
    241   const size_t index = trace_memory_stack->index_;
    242   // Allow deep nesting of stacks (needed for tests), but only record
    243   // |kMaxStackSize| entries.
    244   if (index < kMaxStackSize)
    245     trace_memory_stack->category_stack_[index] = category;
    246   trace_memory_stack->index_++;
    247 }
    248 
    249 ScopedTraceMemory::~ScopedTraceMemory() {
    250   // Not enabled indicates that the trace system isn't running, so don't
    251   // record anything.
    252   if (!enabled_)
    253     return;
    254   // Get our thread's copy of the stack.
    255   TraceMemoryStack* trace_memory_stack = GetTraceMemoryStack();
    256   // The tracing system can be turned on with ScopedTraceMemory objects
    257   // allocated on the stack, so avoid potential underflow as they are destroyed.
    258   if (trace_memory_stack->index_ > 0)
    259     trace_memory_stack->index_--;
    260 }
    261 
    262 // static
    263 void ScopedTraceMemory::InitForTest() {
    264   InitThreadLocalStorage();
    265   enabled_ = true;
    266 }
    267 
    268 // static
    269 void ScopedTraceMemory::CleanupForTest() {
    270   enabled_ = false;
    271   CleanupThreadLocalStorage();
    272 }
    273 
    274 // static
    275 int ScopedTraceMemory::GetStackIndexForTest() {
    276   TraceMemoryStack* stack = GetTraceMemoryStack();
    277   return static_cast<int>(stack->index_);
    278 }
    279 
    280 // static
    281 const char* ScopedTraceMemory::GetItemForTest(int index) {
    282   TraceMemoryStack* stack = GetTraceMemoryStack();
    283   return stack->category_stack_[index];
    284 }
    285 
    286 /////////////////////////////////////////////////////////////////////////////
    287 
    288 void AppendHeapProfileAsTraceFormat(const char* input, std::string* output) {
    289   // Heap profile output has a header total line, then a list of stacks with
    290   // memory totals, like this:
    291   //
    292   // heap profile:    357:    55227 [ 14653:  2624014] @ heapprofile
    293   //    95:    40940 [   649:   114260] @ 0x7fa7f4b3be13
    294   //    77:    32546 [   742:   106234] @
    295   //    68:     4195 [  1087:    98009] @ 0x7fa7fa9b9ba0 0x7fa7f4b3be13
    296   //
    297   // MAPPED_LIBRARIES:
    298   // 1be411fc1000-1be4139e4000 rw-p 00000000 00:00 0
    299   // 1be4139e4000-1be4139e5000 ---p 00000000 00:00 0
    300   // ...
    301   //
    302   // Skip input after MAPPED_LIBRARIES.
    303   std::string input_string;
    304   const char* mapped_libraries = strstr(input, "MAPPED_LIBRARIES");
    305   if (mapped_libraries) {
    306     input_string.assign(input, mapped_libraries - input);
    307   } else {
    308     input_string.assign(input);
    309   }
    310 
    311   std::vector<std::string> lines;
    312   size_t line_count = Tokenize(input_string, "\n", &lines);
    313   if (line_count == 0) {
    314     DLOG(WARNING) << "No lines found";
    315     return;
    316   }
    317 
    318   // Handle the initial summary line.
    319   output->append("[");
    320   AppendHeapProfileTotalsAsTraceFormat(lines[0], output);
    321 
    322   // Handle the following stack trace lines.
    323   for (size_t i = 1; i < line_count; ++i) {
    324     const std::string& line = lines[i];
    325     AppendHeapProfileLineAsTraceFormat(line, output);
    326   }
    327   output->append("]\n");
    328 }
    329 
    330 void AppendHeapProfileTotalsAsTraceFormat(const std::string& line,
    331                                           std::string* output) {
    332   // This is what a line looks like:
    333   // heap profile:    357:    55227 [ 14653:  2624014] @ heapprofile
    334   //
    335   // The numbers represent total allocations since profiling was enabled.
    336   // From the example above:
    337   //     357 = Outstanding allocations (mallocs - frees)
    338   //   55227 = Outstanding bytes (malloc bytes - free bytes)
    339   //   14653 = Total allocations (mallocs)
    340   // 2624014 = Total bytes (malloc bytes)
    341   std::vector<std::string> tokens;
    342   Tokenize(line, " :[]@", &tokens);
    343   if (tokens.size() < 4) {
    344     DLOG(WARNING) << "Invalid totals line " << line;
    345     return;
    346   }
    347   DCHECK_EQ(tokens[0], "heap");
    348   DCHECK_EQ(tokens[1], "profile");
    349   output->append("{\"current_allocs\": ");
    350   output->append(tokens[2]);
    351   output->append(", \"current_bytes\": ");
    352   output->append(tokens[3]);
    353   output->append(", \"trace\": \"\"}");
    354 }
    355 
    356 bool AppendHeapProfileLineAsTraceFormat(const std::string& line,
    357                                         std::string* output) {
    358   // This is what a line looks like:
    359   //    68:     4195 [  1087:    98009] @ 0x7fa7fa9b9ba0 0x7fa7f4b3be13
    360   //
    361   // The numbers represent allocations for a particular stack trace since
    362   // profiling was enabled. From the example above:
    363   //    68 = Outstanding allocations (mallocs - frees)
    364   //  4195 = Outstanding bytes (malloc bytes - free bytes)
    365   //  1087 = Total allocations (mallocs)
    366   // 98009 = Total bytes (malloc bytes)
    367   //
    368   // 0x7fa7fa9b9ba0 0x7fa7f4b3be13 = Stack trace represented as pointers to
    369   //                                 static strings from trace event names.
    370   std::vector<std::string> tokens;
    371   Tokenize(line, " :[]@", &tokens);
    372   // It's valid to have no stack addresses, so only require 4 tokens.
    373   if (tokens.size() < 4) {
    374     DLOG(WARNING) << "Invalid line " << line;
    375     return false;
    376   }
    377   // Don't bother with stacks that have no current allocations.
    378   if (tokens[0] == "0")
    379     return false;
    380   output->append(",\n");
    381   output->append("{\"current_allocs\": ");
    382   output->append(tokens[0]);
    383   output->append(", \"current_bytes\": ");
    384   output->append(tokens[1]);
    385   output->append(", \"trace\": \"");
    386 
    387   // Convert the "stack addresses" into strings.
    388   const std::string kSingleQuote = "'";
    389   for (size_t t = 4; t < tokens.size(); ++t) {
    390     // Each stack address is a pointer to a constant trace name string.
    391     uint64 address = 0;
    392     if (!base::HexStringToUInt64(tokens[t], &address))
    393       break;
    394     // This is ugly but otherwise tcmalloc would need to gain a special output
    395     // serializer for pseudo-stacks. Note that this cast also handles 64-bit to
    396     // 32-bit conversion if necessary. Tests use a null address.
    397     const char* trace_name =
    398         address ? reinterpret_cast<const char*>(address) : "null";
    399 
    400     // Some trace name strings have double quotes, convert them to single.
    401     std::string trace_name_string(trace_name);
    402     ReplaceChars(trace_name_string, "\"", kSingleQuote, &trace_name_string);
    403 
    404     output->append(trace_name_string);
    405 
    406     // Trace viewer expects a trailing space.
    407     output->append(" ");
    408   }
    409   output->append("\"}");
    410   return true;
    411 }
    412 
    413 }  // namespace debug
    414 }  // namespace base
    415