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