[memory-infra] Log reasons for memory dump failure

All memory dump failures will now lead to VLOG(1) error messages so that
the reason for failure could be determined from outside chrome (e.g. in
Telemetry).

BUG=616483
TBR=shatch

Review-Url: https://codereview.chromium.org/2049143002
Cr-Commit-Position: refs/heads/master@{#398838}

base/trace_event/memory_dump_manager.cc

@@ -97,6 +97,9 @@ struct SessionStateConvertableProxy : public ConvertableToTraceFormat {
 const char* const MemoryDumpManager::kTraceCategory =
     TRACE_DISABLED_BY_DEFAULT("memory-infra");
 
+// static
+const char* const MemoryDumpManager::kLogPrefix = "Memory-infra dump";
+
 // static
 const int MemoryDumpManager::kMaxConsecutiveFailuresCount = 3;
 
@@ -337,6 +340,8 @@ void MemoryDumpManager::RequestGlobalDump(
     const MemoryDumpCallback& callback) {
   // Bail out immediately if tracing is not enabled at all.
   if (!UNLIKELY(subtle::NoBarrier_Load(&memory_tracing_enabled_))) {
+    VLOG(1) << kLogPrefix << " failed because " << kTraceCategory
+            << " tracing category is not enabled";
     if (!callback.is_null())
       callback.Run(0u /* guid */, false /* success */);
     return;
@@ -422,6 +427,14 @@ void MemoryDumpManager::SetupNextMemoryDump(
   // Anyway either tracing is stopped or this was the last hop, create a trace
   // event, add it to the trace and finalize process dump invoking the callback.
   if (!pmd_async_state->dump_thread_task_runner.get()) {
+    if (pmd_async_state->pending_dump_providers.empty()) {
+      VLOG(1) << kLogPrefix << " failed because dump thread was destroyed"
+              << " before finalizing the dump";
+    } else {
+      VLOG(1) << kLogPrefix << " failed because dump thread was destroyed"
+              << " before dumping "
+              << pmd_async_state->pending_dump_providers.back().get()->name;
+    }
     pmd_async_state->dump_successful = false;
     pmd_async_state->pending_dump_providers.clear();
   }
@@ -596,8 +609,11 @@ void MemoryDumpManager::FinalizeDumpAndAddToTrace(
 
   bool tracing_still_enabled;
   TRACE_EVENT_CATEGORY_GROUP_ENABLED(kTraceCategory, &tracing_still_enabled);
-  if (!tracing_still_enabled)
+  if (!tracing_still_enabled) {
     pmd_async_state->dump_successful = false;
+    VLOG(1) << kLogPrefix << " failed because tracing was disabled before"
+            << " the dump was completed";
+  }
 
   if (!pmd_async_state->callback.is_null()) {
     pmd_async_state->callback.Run(dump_guid, pmd_async_state->dump_successful);

base/trace_event/memory_dump_manager.h

@@ -40,6 +40,7 @@ class MemoryDumpSessionState;
 class BASE_EXPORT MemoryDumpManager : public TraceLog::EnabledStateObserver {
  public:
   static const char* const kTraceCategory;
+  static const char* const kLogPrefix;
 
   // This value is returned as the tracing id of the child processes by
   // GetTracingProcessId() when tracing is not enabled.

components/tracing/child/child_memory_dump_manager_delegate_impl.cc

@@ -75,8 +75,12 @@ void ChildMemoryDumpManagerDelegateImpl::RequestGlobalMemoryDump(
 
   // Bail out if we receive a dump request from the manager before the
   // ChildTraceMessageFilter has been initialized.
-  if (!ctmf_task_runner)
+  if (!ctmf_task_runner) {
+    VLOG(1) << base::trace_event::MemoryDumpManager::kLogPrefix
+            << " failed because child trace message filter hasn't been"
+            << " initialized";
     return AbortDumpRequest(args, callback);
+  }
 
   // Make sure we access |ctmf_| only on the thread where it lives to avoid
   // races on shutdown.
@@ -92,8 +96,12 @@ void ChildMemoryDumpManagerDelegateImpl::RequestGlobalMemoryDump(
 
   // The ChildTraceMessageFilter could have been destroyed while hopping on the
   // right thread. If this is the case, bail out.
-  if (!ctmf_)
+  if (!ctmf_) {
+    VLOG(1) << base::trace_event::MemoryDumpManager::kLogPrefix
+            << " failed because child trace message filter was"
+            << " destroyed while switching threads";
     return AbortDumpRequest(args, callback);
+  }
 
   // Send the request up to the browser process' MessageDumpmanager.
   ctmf_->SendGlobalMemoryDumpRequest(args, callback);

content/browser/tracing/tracing_controller_impl.cc

@@ -922,8 +922,9 @@ void TracingControllerImpl::RequestGlobalMemoryDump(
   }
   // Abort if another dump is already in progress.
   if (pending_memory_dump_guid_) {
-    DVLOG(1) << "Requested memory dump " << args.dump_guid
-             << " while waiting for " << pending_memory_dump_guid_;
+    VLOG(1) << base::trace_event::MemoryDumpManager::kLogPrefix
+            << " (" << args.dump_guid << ") aborted because another dump ("
+            << pending_memory_dump_guid_ << ") is in progress";
     if (!callback.is_null())
       callback.Run(args.dump_guid, false /* success */);
     return;
@@ -1001,8 +1002,9 @@ void TracingControllerImpl::OnProcessMemoryDumpResponse(
   pending_memory_dump_filters_.erase(it);
   if (!success) {
     ++failed_memory_dump_count_;
-    DLOG(WARNING) << "Global memory dump failed because of NACK from child "
-                  << trace_message_filter->peer_pid();
+    VLOG(1) << base::trace_event::MemoryDumpManager::kLogPrefix
+            << " failed because of NACK from child "
+            << trace_message_filter->peer_pid();
   }
   FinalizeGlobalMemoryDumpIfAllProcessesReplied();
 }
@@ -1013,7 +1015,8 @@ void TracingControllerImpl::OnBrowserProcessMemoryDumpDone(uint64_t dump_guid,
   --pending_memory_dump_ack_count_;
   if (!success) {
     ++failed_memory_dump_count_;
-    DLOG(WARNING) << "Global memory dump aborted on the current process";
+    VLOG(1) << base::trace_event::MemoryDumpManager::kLogPrefix
+            << " aborted on the current process";
   }
   FinalizeGlobalMemoryDumpIfAllProcessesReplied();
 }