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

chromeos/dbus/power_manager_client.cc

 // Copyright (c) 2012 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 "chromeos/dbus/power_manager_client.h"
 
 #include <stdint.h>
 
 #include <algorithm>
 #include <memory>
@@ skipping 70 matching lines @@
   void RemoveObserver(Observer* observer) override {
     observers_.RemoveObserver(observer);
   }
 
   bool HasObserver(const Observer* observer) const override {
     return observers_.HasObserver(observer);
   }
 
   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;
   }
 
   void DecreaseScreenBrightness(bool allow_off) override {
     dbus::MethodCall method_call(
         power_manager::kPowerManagerInterface,
         power_manager::kDecreaseScreenBrightnessMethod);
     dbus::MessageWriter writer(&method_call);
@@ skipping 416 matching lines @@
     }
 
     dbus::MessageReader reader(signal);
     power_manager::SuspendImminent proto;
     if (!reader.PopArrayOfBytesAsProto(&proto)) {
       POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
                        << signal_name << " signal";
       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
     // wonky.
     if (suspend_is_pending_ && suspending_from_dark_resume_ == in_dark_resume) {
       POWER_LOG(ERROR) << "Got " << signal_name
                        << " signal about pending suspend attempt "
                        << proto.suspend_id()
                        << " while still waiting on attempt "
                        << pending_suspend_id_;
@@ skipping 16 matching lines @@
     dbus::MessageReader reader(signal);
     power_manager::SuspendDone proto;
     if (!reader.PopArrayOfBytesAsProto(&proto)) {
       POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
                        << power_manager::kSuspendDoneSignal << " signal";
       return;
     }
 
     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
     // readiness for any in-progress suspend attempts.
     pending_suspend_id_ = -1;
     suspend_is_pending_ = false;
     suspending_from_dark_resume_ = false;
     num_pending_suspend_readiness_callbacks_ = 0;
 
     FOR_EACH_OBSERVER(
@@ skipping 119 matching lines @@
                    weak_ptr_factory_.GetWeakPtr(), true,
                    power_manager::kRegisterDarkSuspendDelayMethod));
   }
 
   // Records the fact that an observer has finished doing asynchronous work
   // that was blocking a pending suspend attempt and possibly reports
   // suspend readiness to powerd.  Called by callbacks returned via
   // 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;
 
     num_pending_suspend_readiness_callbacks_--;
     MaybeReportSuspendReadiness();
   }
 
   // Reports suspend readiness to powerd if no observers are still holding
   // suspend readiness callbacks.
   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;
     if (suspending_from_dark_resume_) {
       method_name = power_manager::kHandleDarkSuspendReadinessMethod;
       delay_id = dark_suspend_delay_id_;
     } else {
       method_name = power_manager::kHandleSuspendReadinessMethod;
       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_);
 
     pending_suspend_id_ = -1;
     suspend_is_pending_ = false;
 
     if (!writer.AppendProtoAsArrayOfBytes(protobuf_request)) {
       POWER_LOG(ERROR) << "Error constructing message for " << method_name;
       return;
@@ skipping 57 matching lines @@
 // static
 PowerManagerClient* PowerManagerClient::Create(
     DBusClientImplementationType type) {
   if (type == REAL_DBUS_CLIENT_IMPLEMENTATION)
     return new PowerManagerClientImpl();
   DCHECK_EQ(FAKE_DBUS_CLIENT_IMPLEMENTATION, type);
   return new FakePowerManagerClient();
 }
 
 }  // namespace chromeos