Record Chrome trace events in tcmalloc heap profiles

base/debug/trace_event_memory.cc

+// Copyright 2013 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/debug/trace_event_memory.h"
+
+#include "base/debug/leak_annotations.h"
+#include "base/debug/trace_event.h"
+#include "base/lazy_instance.h"
+#include "base/logging.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/message_loop.h"
+#include "base/strings/string_number_conversions.h"
+#include "base/strings/string_util.h"
+#include "base/threading/thread_local.h"
+
+// TODO(jamescook): Windows support for memory tracing.
+#if !defined(NO_TCMALLOC) && !defined(OS_NACL) && (defined(OS_LINUX) || defined(OS_ANDROID))

[jar (doing other things), 2013/07/04 02:18:30]

nit: I think you can backslash break this line.

[James Cook, 2013/07/08 23:21:34]

Done.

+#define TRACE_MEMORY_SUPPORTED 1
+#endif
+
+#if defined(TRACE_MEMORY_SUPPORTED)
+#include "third_party/tcmalloc/chromium/src/gperftools/heap-profiler.h"
+#endif
+
+namespace base {
+namespace debug {
+
+namespace {
+
+// Maximum number of nested TRACE_MEMORY scopes to record. Must be greater than
+// or equal to HeapProfileTable::kMaxStackDepth.
+const int kMaxStackSize = 32;
+
+/////////////////////////////////////////////////////////////////////////////
+// Holds a memory dump until the tracing system needs to serialize it.
+class MemoryDumpHolder : public base::debug::ConvertableToTraceFormat {
+ public:
+  // Takes ownership of dump, which must be a JSON string, allocated with
+  // malloc() and NULL terminated.
+  explicit MemoryDumpHolder(char* dump) : dump_(dump) {}
+  virtual ~MemoryDumpHolder() { free(dump_); }
+
+  // base::debug::ConvertableToTraceFormat overrides:
+  virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE {
+    AppendHeapProfileAsTraceFormat(dump_, out);
+  }
+
+ private:
+  char* dump_;
+
+  DISALLOW_COPY_AND_ASSIGN(MemoryDumpHolder);
+};
+
+/////////////////////////////////////////////////////////////////////////////
+// Records a stack of TRACE_MEMORY events. One per thread is required.
+struct TraceMemoryStack {
+  TraceMemoryStack() : index_(0) {
+    memset(category_stack_, 0, kMaxStackSize * sizeof(const char*));

[jar (doing other things), 2013/07/04 02:18:30]

nit: Always try to use variable, rather than a raw type, in a sizeof.  Better is
sizeof(category_stack_[0])

[James Cook, 2013/07/08 23:21:34]

Ah, I had forgotten that part of the style guide. Done, thanks!

+  }
+
+  // Points to the next free entry.
+  int index_;
+  const char* category_stack_[kMaxStackSize];
+};
+
+// One stack of TRACE_MEMORY event data per thread.
+LazyInstance<ThreadLocalPointer<TraceMemoryStack> >::Leaky
+    g_trace_memory_stack = LAZY_INSTANCE_INITIALIZER;
+
+// Returns the thread-local trace memory stack, initializing if necessary.
+TraceMemoryStack* GetTraceMemoryStack() {
+  TraceMemoryStack* stack = g_trace_memory_stack.Get().Get();
+  if (stack)
+    return stack;
+  // Intentionally leak one stack per thread.

[jar (doing other things), 2013/07/04 02:18:30]

How does this play with worker threads?  Is this really an unbounded leak, as
threads are recycled?

+  TraceMemoryStack* leaked_stack = new TraceMemoryStack;
+  ANNOTATE_LEAKING_OBJECT_PTR(leaked_stack);
+  g_trace_memory_stack.Get().Set(leaked_stack);
+  return leaked_stack;
+}
+
+// Returns a "pseudo-stack" of pointers to trace events.
+// TODO(jamescook): Record both category and name, perhaps in a pair for speed.
+int GetPseudoStack(int skip_count_ignored, void** stack_out) {
+  TraceMemoryStack* stack = g_trace_memory_stack.Get().Get();
+  // If the tracing system isn't fully initialized, just skip this allocation.
+  // Attempting to initialize will allocate memory, causing this function to
+  // be called recursively from inside the allocator.
+  if (!stack)
+    return 0;
+  // Copy out a maximum of kMaxStackSize stack entries.
+  const int count =
+      stack->index_ < kMaxStackSize ? stack->index_ : kMaxStackSize;

[jar (doing other things), 2013/07/04 02:18:30]

nit: std::max()

[James Cook, 2013/07/08 23:21:34]

Done (I actually need std::min here).

+  // Notes that memcpy() works for zero bytes.
+  memcpy(stack_out, stack->category_stack_, count * sizeof(void*));

[jar (doing other things), 2013/07/04 02:18:30]

nit: sizeof(stack->category_[0])

[James Cook, 2013/07/08 23:21:34]

Done.

+  return count;
+}
+
+// Caller owns the returned char* and must release it with free().
+char* TraceMemoryDumpAsString() {
+#if defined(TRACE_MEMORY_SUPPORTED)
+  DVLOG(1) << "TraceMemoryDumpAsString";
+  return ::GetHeapProfile();
+#else
+  NOTREACHED();
+  return NULL;
+#endif
+}
+
+// If memory tracing is enabled, dumps a memory profile to the tracing system.
+void DumpMemoryProfile() {
+  DVLOG(1) << "DumpMemoryProfile";

[jar (doing other things), 2013/07/04 02:18:30]

Do you care about allocations done by these logs? Should this be inside your the
block starting after 116?

[James Cook, 2013/07/08 23:21:34]

Good point. Moved below the macro that disables tracing allocations.

+  // Don't trace allocations here in the memory tracing system.
+  INTERNAL_TRACE_MEMORY(TRACE_DISABLED_BY_DEFAULT("memory"),
+                        TRACE_MEMORY_IGNORE);
+  // Check to see if tracing is enabled for the memory category.
+  bool enabled;
+  TRACE_EVENT_CATEGORY_GROUP_ENABLED(TRACE_DISABLED_BY_DEFAULT("memory"),
+                                     &enabled);
+  if (enabled) {

[jar (doing other things), 2013/07/04 02:18:30]

nit: (personal?): early returns often help readability, and avoid the need to
indent blocks.

[James Cook, 2013/07/08 23:21:34]

Done.

+    // MemoryDumpHolder takes ownership of this string.
+    char* dump = TraceMemoryDumpAsString();
+    scoped_ptr<MemoryDumpHolder> dump_holder(new MemoryDumpHolder(dump));
+    const int kSnapshotId = 1;
+    TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
+        TRACE_DISABLED_BY_DEFAULT("memory"),
+        "memory::Heap",
+        kSnapshotId,
+        dump_holder.PassAs<base::debug::ConvertableToTraceFormat>());
+  }
+}
+
+void TraceMemoryStart() {
+#if defined(TRACE_MEMORY_SUPPORTED)
+  DVLOG(1) << "Starting trace memory";
+  // Ensure thread-local-storage is initialized.
+  GetTraceMemoryStack();
+  ::HeapProfilerWithPseudoStackStart(&GetPseudoStack);
+#else
+  NOTREACHED();
+#endif
+}
+
+void TraceMemoryStop() {
+#if defined(TRACE_MEMORY_SUPPORTED)
+  DVLOG(1) << "Stopping trace memory";
+  ::HeapProfilerStop();
+#else
+  NOTREACHED();
+#endif
+}
+
+}  // namespace
+
+//////////////////////////////////////////////////////////////////////////////
+
+TraceMemoryController::TraceMemoryController(
+    scoped_refptr<MessageLoopProxy> message_loop_proxy)
+    : message_loop_proxy_(message_loop_proxy),
+      weak_factory_(this) {
+  // Force the "memory" category to show up in the trace viewer.
+  TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("memory"), "init");
+  // Allow this to be instantiated on unsupported platforms, but don't run.
+#if defined(TRACE_MEMORY_SUPPORTED)
+  TraceLog::GetInstance()->AddEnabledStateObserver(this);
+#endif
+}
+
+TraceMemoryController::~TraceMemoryController() {
+#if defined(TRACE_MEMORY_SUPPORTED)
+  if (dump_timer_.IsRunning())
+    StopProfiling();
+  TraceLog::GetInstance()->RemoveEnabledStateObserver(this);
+#endif
+}
+
+  // base::debug::TraceLog::EnabledStateChangedObserver overrides:
+void TraceMemoryController::OnTraceLogEnabled() {
+  DVLOG(1) << "OnTraceLogEnabled";
+  DCHECK(message_loop_proxy_->PostTask(

[jar (doing other things), 2013/07/04 02:18:30]

DCHECKs should never have side effects.

If you meant this, much better is:

if !defined(NDEBUG)


Same thing on line 189.

+      FROM_HERE,
+      base::Bind(&TraceMemoryController::StartProfiling,
+                 weak_factory_.GetWeakPtr())));
+}
+
+void TraceMemoryController::OnTraceLogDisabled() {
+  DVLOG(1) << "OnTraceLogDisabled";
+  DCHECK(message_loop_proxy_->PostTask(
+      FROM_HERE,
+      base::Bind(&TraceMemoryController::StopProfiling,
+                 weak_factory_.GetWeakPtr())));
+}
+
+void TraceMemoryController::StartProfiling() {
+  // Watch for the tracing framework sending enabling more than once.
+  if (dump_timer_.IsRunning())
+    return;
+  TraceMemoryStart();
+  const int kDumpIntervalSeconds = 5;
+  dump_timer_.Start(FROM_HERE,
+                    TimeDelta::FromSeconds(kDumpIntervalSeconds),
+                    base::Bind(&DumpMemoryProfile));
+}
+
+void TraceMemoryController::StopProfiling() {
+  dump_timer_.Stop();
+  TraceMemoryStop();
+}
+
+bool TraceMemoryController::IsTimerRunningForTest() const {
+  return dump_timer_.IsRunning();
+}
+
+/////////////////////////////////////////////////////////////////////////////
+
+ScopedTraceMemory::ScopedTraceMemory(const char* category) {
+  // Get our thread's copy of the stack.
+  TraceMemoryStack* stack = GetTraceMemoryStack();
+  const int index = stack->index_;
+  // Allow deep nesting of stacks (needed for tests), but only record
+  // |kMaxStackSize| entries.
+  if (index < kMaxStackSize)
+    stack->category_stack_[index] = category;
+  stack->index_++;
+}
+
+ScopedTraceMemory::~ScopedTraceMemory() {
+  // Get our thread's copy of the stack.
+  TraceMemoryStack* stack = g_trace_memory_stack.Get().Get();
+  stack->index_--;
+  DCHECK_GE(stack->index_, 0) << "stack underflow";
+}
+
+// static
+int ScopedTraceMemory::GetStackIndexForTest() {
+  TraceMemoryStack* stack = GetTraceMemoryStack();
+  return stack->index_;
+}
+
+// static
+const char* ScopedTraceMemory::GetItemForTest(int index) {
+  TraceMemoryStack* stack = GetTraceMemoryStack();
+  return stack->category_stack_[index];
+}
+
+/////////////////////////////////////////////////////////////////////////////
+
+void AppendHeapProfileAsTraceFormat(const char* input, std::string* output) {
+  // Heap profile output has a header total line, then a list of stacks with
+  // memory totals, like this:
+  //
+  // heap profile:    357:    55227 [ 14653:  2624014] @ heapprofile
+  //    95:    40940 [   649:   114260] @ 0x7fa7f4b3be13
+  //    77:    32546 [   742:   106234] @
+  //    68:     4195 [  1087:    98009] @ 0x7fa7fa9b9ba0 0x7fa7f4b3be13
+  //
+  // MAPPED_LIBRARIES:
+  // 1be411fc1000-1be4139e4000 rw-p 00000000 00:00 0
+  // 1be4139e4000-1be4139e5000 ---p 00000000 00:00 0
+  // ...
+  //
+  // Skip input after MAPPED_LIBRARIES.
+  std::string input_string;
+  const char* mapped_libraries = strstr(input, "MAPPED_LIBRARIES");
+  if (mapped_libraries) {
+    input_string.assign(input, mapped_libraries - input);
+  } else {
+    input_string.assign(input);
+  }
+
+  std::vector<std::string> lines;
+  size_t line_count = Tokenize(input_string, "\n", &lines);
+  if (line_count == 0) {
+    DLOG(WARNING) << "No lines found";
+    return;
+  }
+
+  // Handle the initial summary line.
+  output->append("[");
+  AppendHeapProfileTotalsAsTraceFormat(lines[0], output);
+  output->append(",\n");
+
+  // Handle the following stack trace lines.
+  for (size_t i = 1; i < line_count; ++i) {
+    const std::string& line = lines[i];
+    bool added_entry = AppendHeapProfileLineAsTraceFormat(line, output);
+    if (added_entry)
+      output->append(",\n");
+  }
+  // Remove trailing ",\n".
+  output->resize(output->size() - 2);
+  output->append("]\n");
+}
+
+void AppendHeapProfileTotalsAsTraceFormat(const std::string& line,
+                                          std::string* output) {
+  // This is what a line looks like:
+  // heap profile:    357:    55227 [ 14653:  2624014] @ heapprofile
+  std::vector<std::string> tokens;
+  Tokenize(line, " :[]@", &tokens);
+  if (tokens.size() < 4) {
+    DLOG(WARNING) << "Invalid totals line " << line;
+    return;
+  }
+  DCHECK_EQ(tokens[0], "heap");
+  DCHECK_EQ(tokens[1], "profile");
+  output->append("{\"current_allocs\": ");
+  output->append(tokens[2]);
+  output->append(", \"current_bytes\": ");
+  output->append(tokens[3]);
+  output->append(", \"trace\": \"\"}");
+}
+
+bool AppendHeapProfileLineAsTraceFormat(const std::string& line,
+                                        std::string* output) {
+  // This is what a line looks like:
+  //    68:     4195 [  1087:    98009] @ 0x7fa7fa9b9ba0 0x7fa7f4b3be13
+  std::vector<std::string> tokens;
+  Tokenize(line, " :[]@", &tokens);
+  // It's valid to have no stack addresses, so only require 4 tokens.
+  if (tokens.size() < 4) {
+    DLOG(WARNING) << "Invalid line " << line;
+    return false;
+  }
+  // Don't bother with stacks that have no current allocations.
+  if (tokens[0] == "0")
+    return false;
+  output->append("{\"current_allocs\": ");
+  output->append(tokens[0]);
+  output->append(", \"current_bytes\": ");
+  output->append(tokens[1]);
+  output->append(", \"trace\": \"");
+
+  // Convert the "stack addresses" into strings.
+  const std::string kSingleQuote = "'";
+  for (size_t t = 4; t < tokens.size(); ++t) {
+    // Each stack address is a pointer to a constant trace name string.
+    uint64 address = 0;
+    if (!base::HexStringToUInt64(tokens[t], &address))
+      break;
+    // This is ugly but otherwise tcmalloc would need to gain a special output
+    // serializer for pseudo-stacks. Note that this cast also handles 64-bit to
+    // 32-bit conversion if necessary. Tests use a null address.
+    const char* trace_name =
+        address ? reinterpret_cast<const char*>(address) : "null";
+
+    // Some trace name strings have double quotes, convert them to single.
+    std::string trace_name_string(trace_name);
+    ReplaceChars(trace_name_string, "\"", kSingleQuote, &trace_name_string);
+
+    output->append(trace_name_string);
+
+    // Trace viewer expects a trailing space.
+    output->append(" ");
+  }
+  output->append("\"}");
+  return true;
+}
+
+}  // namespace debug
+}  // namespace base