Add wall clock time to GPU watchdog V2 for debugging purpose

base::Time represents an absolute point in coordinated universal time (UTC).
base::TimeTicks which tracks the amount of time a task runs.
Watchdog V2 uses TimeTicks to check timeout. Adding clock time and analyzing
the difference between these two might help debugging V2.

Bug: 949839
Change-Id: I21e9250e67a02f4190d12d28d33c5c7a52a2168c
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1742440
Commit-Queue: Maggie Chen <magchen@chromium.org>
Reviewed-by: Zhenyao Mo <zmo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#685365}

gpu/ipc/service/gpu_watchdog_thread_v2.cc

@@ -95,7 +95,9 @@ void GpuWatchdogThreadImplV2::Init() {
       FROM_HERE,
       base::BindOnce(&GpuWatchdogThreadImplV2::OnWatchdogTimeout, weak_ptr_),
       watchdog_timeout_ * kInitFactor);
-  watchdog_start_time_ = base::TimeTicks::Now();
+  watchdog_start_timeticks_ = base::TimeTicks::Now();
+  last_on_watchdog_timeout_timeticks_ = watchdog_start_timeticks_;
+  last_on_watchdog_timeout_time_ = base::Time::Now();
   GpuWatchdogHistogram(GpuWatchdogThreadEvent::kGpuWatchdogStart);
 }
 
@@ -121,13 +123,13 @@ void GpuWatchdogThreadImplV2::OnSuspend() {
   in_power_suspension_ = true;
   // Revoke any pending watchdog timeout task
   weak_factory_.InvalidateWeakPtrs();
-  suspend_time_ = base::TimeTicks::Now();
+  suspend_timeticks_ = base::TimeTicks::Now();
 }
 
 void GpuWatchdogThreadImplV2::OnResume() {
   in_power_suspension_ = false;
   RestartWatchdogTimeoutTask();
-  resume_time_ = base::TimeTicks::Now();
+  resume_timeticks_ = base::TimeTicks::Now();
 }
 
 // Running on the watchdog thread.
@@ -141,14 +143,14 @@ void GpuWatchdogThreadImplV2::OnWatchdogBackgrounded() {
   is_backgrounded_ = true;
   // Revoke any pending watchdog timeout task
   weak_factory_.InvalidateWeakPtrs();
-  backgrounded_time_ = base::TimeTicks::Now();
+  backgrounded_timeticks_ = base::TimeTicks::Now();
 }
 
 // Running on the watchdog thread.
 void GpuWatchdogThreadImplV2::OnWatchdogForegrounded() {
   is_backgrounded_ = false;
   RestartWatchdogTimeoutTask();
-  foregrounded_time_ = base::TimeTicks::Now();
+  foregrounded_timeticks_ = base::TimeTicks::Now();
 }
 
 void GpuWatchdogThreadImplV2::RestartWatchdogTimeoutTask() {
@@ -198,6 +200,8 @@ void GpuWatchdogThreadImplV2::OnWatchdogTimeout() {
 
   // No gpu hang is detected. Continue with another OnWatchdogTimeout
   if (disarmed || gpu_makes_progress) {
+    last_on_watchdog_timeout_timeticks_ = base::TimeTicks::Now();
+    last_on_watchdog_timeout_time_ = base::Time::Now();
     task_runner()->PostDelayedTask(
         FROM_HERE,
         base::BindOnce(&GpuWatchdogThreadImplV2::OnWatchdogTimeout, weak_ptr_),
@@ -223,17 +227,29 @@ void GpuWatchdogThreadImplV2::DeliberatelyTerminateToRecoverFromHang() {
 
   // Store variables so they're available in crash dumps to help determine the
   // cause of any hang.
-  base::TimeTicks current_time = base::TimeTicks::Now();
+  base::TimeTicks current_timeticks = base::TimeTicks::Now();
-  base::debug::Alias(&current_time);
+  base::debug::Alias(&current_timeticks);
-  base::debug::Alias(&watchdog_start_time_);
+  base::debug::Alias(&watchdog_start_timeticks_);
-  base::debug::Alias(&suspend_time_);
+  base::debug::Alias(&suspend_timeticks_);
-  base::debug::Alias(&resume_time_);
+  base::debug::Alias(&resume_timeticks_);
-  base::debug::Alias(&backgrounded_time_);
+  base::debug::Alias(&backgrounded_timeticks_);
-  base::debug::Alias(&foregrounded_time_);
+  base::debug::Alias(&foregrounded_timeticks_);
   base::debug::Alias(&in_power_suspension_);
   base::debug::Alias(&is_backgrounded_);
   base::debug::Alias(&is_add_power_observer_called_);
   base::debug::Alias(&is_power_observer_added_);
+  base::debug::Alias(&last_on_watchdog_timeout_timeticks_);
+  base::TimeDelta timeticks_elapses =
+      current_timeticks - last_on_watchdog_timeout_timeticks_;
+  base::debug::Alias(&timeticks_elapses);
+
+  // If clock_time_elapses is much longer than time_elapses, it might be a sign
+  // of a busy system.
+  base::Time current_time = base::Time::Now();
+  base::TimeDelta time_elapses = current_time - last_on_watchdog_timeout_time_;
+  base::debug::Alias(&current_time);
+  base::debug::Alias(&last_on_watchdog_timeout_time_);
+  base::debug::Alias(&time_elapses);
 
   GpuWatchdogHistogram(GpuWatchdogThreadEvent::kGpuWatchdogKill);
 

gpu/ipc/service/gpu_watchdog_thread_v2.h

@@ -70,15 +70,23 @@ class GPU_IPC_SERVICE_EXPORT GpuWatchdogThreadImplV2
   base::TimeDelta watchdog_timeout_;
 
   // The time the gpu watchdog was created
-  base::TimeTicks watchdog_start_time_;
+  base::TimeTicks watchdog_start_timeticks_;
 
   // The time the last OnSuspend and OnResume was called.
-  base::TimeTicks suspend_time_;
+  base::TimeTicks suspend_timeticks_;
-  base::TimeTicks resume_time_;
+  base::TimeTicks resume_timeticks_;
 
   // The time the last OnBackgrounded and OnForegrounded was called.
-  base::TimeTicks backgrounded_time_;
+  base::TimeTicks backgrounded_timeticks_;
-  base::TimeTicks foregrounded_time_;
+  base::TimeTicks foregrounded_timeticks_;
+
+  // Time:      Interpreting the wall-clock time provided by a remote system.
+  // TimeTicks: Tracking the amount of time a task runs. Executing delayed
+  //            tasks at the right time.
+
+  // The time the last OnWatchdogTimeout() was called.
+  base::TimeTicks last_on_watchdog_timeout_timeticks_;
+  base::Time last_on_watchdog_timeout_time_;
 
   // The system has entered the power suspension mode.
   bool in_power_suspension_ = false;