chromeos: Add VLOG(1)s around renderer-freezing for suspend.

chromeos/dbus/power_manager_client.cc

Index: chromeos/dbus/power_manager_client.cc
diff --git a/chromeos/dbus/power_manager_client.cc b/chromeos/dbus/power_manager_client.cc
index 5b3e4e8363778bdd7fe7ccaf0a95d0da5394d0dc..bf8a9ccf5f79557d9f4a0e5a586700beb2a7a936 100644
--- a/chromeos/dbus/power_manager_client.cc
+++ b/chromeos/dbus/power_manager_client.cc
@@ -88,6 +88,9 @@ class PowerManagerClientImpl : public PowerManagerClient {
 
   void SetRenderProcessManagerDelegate(
       base::WeakPtr<RenderProcessManagerDelegate> delegate) override {
+    // TODO(derat): Remove after http://crbug.com/648580 is fixed.
+    VLOG(1) << "Setting RenderProcessManagerDelegate to " << delegate.get();
+    VLOG(1) << "vtable is " << *reinterpret_cast<uintptr_t*>(delegate.get());

[llozano, 2016/10/06 22:55:11]

nit: you are not using parenthesis after * like in the other places.

[Daniel Erat, 2016/10/06 23:00:09]

true. i'll remove them from the other places

     DCHECK(!render_process_manager_delegate_)
         << "There can be only one! ...RenderProcessManagerDelegate";
     render_process_manager_delegate_ = delegate;
@@ -524,9 +527,10 @@ class PowerManagerClientImpl : public PowerManagerClient {
       return;
     }
 
-    POWER_LOG(EVENT) << "Got " << signal_name
-                     << " signal announcing suspend attempt "
-                     << proto.suspend_id();
+    // TODO(derat): Switch back to POWER_LOG(EVENT) after
+    // http://crbug.com/648580 is fixed.
+    VLOG(1) << "Got " << signal_name << " signal announcing suspend attempt "
+            << proto.suspend_id();
 
     // If a previous suspend is pending from the same state we are currently in
     // (fully powered on or in dark resume), then something's gone a little
@@ -563,19 +567,31 @@ class PowerManagerClientImpl : public PowerManagerClient {
 
     const base::TimeDelta duration =
         base::TimeDelta::FromInternalValue(proto.suspend_duration());
-    POWER_LOG(EVENT) << "Got " << power_manager::kSuspendDoneSignal
-                     << " signal:"
-                     << " suspend_id=" << proto.suspend_id()
-                     << " duration=" << duration.InSeconds() << " sec";
+    // TODO(derat): Switch back to POWER_LOG(EVENT) after
+    // http://crbug.com/648580 is fixed.
+    VLOG(1) << "Got " << power_manager::kSuspendDoneSignal << " signal:"
+            << " suspend_id=" << proto.suspend_id()
+            << " duration=" << duration.InSeconds() << " sec";
 
     // RenderProcessManagerDelegate is only notified that suspend is imminent
     // when readiness is being reported to powerd. If the suspend attempt was
     // cancelled before then, we shouldn't notify the delegate about completion.
     const bool cancelled_while_regular_suspend_pending =
         suspend_is_pending_ && !suspending_from_dark_resume_;
+    // TODO(derat): Remove VLOG(1)s after http://crbug.com/648580 is fixed.
+    VLOG(1) << "RenderProcessManagerDelegate is "
+            << render_process_manager_delegate_.get() << "; suspend is"
+            << (suspend_is_pending_ ? "" : "n't") << " pending and was"
+            << (suspending_from_dark_resume_ ? "" : "n't")
+            << " suspending from dark resume";
     if (render_process_manager_delegate_ &&
-        !cancelled_while_regular_suspend_pending)
+        !cancelled_while_regular_suspend_pending) {
+      VLOG(1) << "Calling RenderProcessManagerDelegate::SuspendDone()";
+      VLOG(1) << "vtable is "
+              << *(reinterpret_cast<uintptr_t*>(
+                     render_process_manager_delegate_.get()));
       render_process_manager_delegate_->SuspendDone();
+    }
 
     // powerd always pairs each SuspendImminent signal with SuspendDone before
     // starting the next suspend attempt, so we should no longer report
@@ -715,6 +731,10 @@ class PowerManagerClientImpl : public PowerManagerClient {
   // GetSuspendReadinessCallback().
   void HandleObserverSuspendReadiness(int32_t suspend_id, bool in_dark_resume) {
     DCHECK(OnOriginThread());
+    // TODO(derat): Remove after http://crbug.com/648580 is fixed.
+    VLOG(1) << "Got notification of observer readiness for "
+            << (in_dark_resume ? "dark" : "regular") << " suspend ID "
+            << suspend_id << " (pending " << pending_suspend_id_ << ")";
     if (!suspend_is_pending_ || suspend_id != pending_suspend_id_ ||
         in_dark_resume != suspending_from_dark_resume_)
       return;
@@ -728,8 +748,12 @@ class PowerManagerClientImpl : public PowerManagerClient {
   void MaybeReportSuspendReadiness() {
     CHECK(suspend_is_pending_);
 
-    if (num_pending_suspend_readiness_callbacks_ > 0)
+    if (num_pending_suspend_readiness_callbacks_ > 0) {
+      // TODO(derat): Remove after http://crbug.com/648580 is fixed.
+      VLOG(1) << "Not reporting suspend readiness; waiting for "
+              << num_pending_suspend_readiness_callbacks_ << " callback(s)";
       return;
+    }
 
     std::string method_name;
     int32_t delay_id = -1;
@@ -741,15 +765,27 @@ class PowerManagerClientImpl : public PowerManagerClient {
       delay_id = suspend_delay_id_;
     }
 
-    if (render_process_manager_delegate_ && !suspending_from_dark_resume_)
+    // TODO(derat): Remove VLOG(1)s after http://crbug.com/648580 is fixed.
+    VLOG(1) << "RenderProcessManagerDelegate is "
+            << render_process_manager_delegate_.get() << "; "
+            << (suspending_from_dark_resume_ ? "" : "not ")
+            << "suspending from dark resume";
+    if (render_process_manager_delegate_ && !suspending_from_dark_resume_) {
+      VLOG(1) << "Calling RenderProcessManagerDelegate::SuspendImminent()";
+      VLOG(1) << "vtable is "
+              << *(reinterpret_cast<uintptr_t*>(
+                     render_process_manager_delegate_.get()));
       render_process_manager_delegate_->SuspendImminent();
+    }
 
     dbus::MethodCall method_call(
         power_manager::kPowerManagerInterface, method_name);
     dbus::MessageWriter writer(&method_call);
 
-    POWER_LOG(EVENT) << "Announcing readiness of suspend delay " << delay_id
-                     << " for suspend attempt " << pending_suspend_id_;
+    // TODO(derat): Switch back to POWER_LOG(EVENT) after
+    // http://crbug.com/648580 is fixed.
+    VLOG(1) << "Announcing readiness of suspend delay " << delay_id
+            << " for suspend attempt " << pending_suspend_id_;
     power_manager::SuspendReadinessInfo protobuf_request;
     protobuf_request.set_delay_id(delay_id);
     protobuf_request.set_suspend_id(pending_suspend_id_);