From 373ea9056d3838a8d3becc2adfeb372f83c3db6a Mon Sep 17 00:00:00 2001
From: Christopher Tate <ctate@google.com>
Date: Thu, 4 Jan 2018 16:10:26 -0800
Subject: [PATCH] EventLog when an executed job had been deferred by standby

This gives us a way to review the impact of the deferral on jobs'
nominal timeliness.

Bug: 70297451
Test: manual
Change-Id: I0b5caab6ac7157aab1524f7b014e521f34400e1d
---
 .../java/com/android/server/EventLogTags.logtags  |  4 ++++
 .../com/android/server/job/JobServiceContext.java | 15 ++++++++++-----
 2 files changed, 14 insertions(+), 5 deletions(-)

diff --git a/services/core/java/com/android/server/EventLogTags.logtags b/services/core/java/com/android/server/EventLogTags.logtags
index 6174aece39371..8361132f24bcf 100644
--- a/services/core/java/com/android/server/EventLogTags.logtags
+++ b/services/core/java/com/android/server/EventLogTags.logtags
@@ -261,6 +261,10 @@ option java_package com.android.server
 2756 fstrim_finish (time|2|3)
 
 # ---------------------------
+# Job scheduler
+# ---------------------------
+8000 job_deferred_execution (time|2|3)
+
 # AudioService.java
 # ---------------------------
 40000 volume_changed (stream|1), (prev_level|1), (level|1), (max_level|1), (caller|3)
diff --git a/services/core/java/com/android/server/job/JobServiceContext.java b/services/core/java/com/android/server/job/JobServiceContext.java
index 6a3fd04a4e263..709deeb81ac94 100644
--- a/services/core/java/com/android/server/job/JobServiceContext.java
+++ b/services/core/java/com/android/server/job/JobServiceContext.java
@@ -38,12 +38,14 @@ import android.os.PowerManager;
 import android.os.RemoteException;
 import android.os.UserHandle;
 import android.os.WorkSource;
+import android.util.EventLog;
 import android.util.Slog;
 import android.util.TimeUtils;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.annotations.VisibleForTesting;
 import com.android.internal.app.IBatteryStats;
+import com.android.server.EventLogTags;
 import com.android.server.job.controllers.JobStatus;
 
 /**
@@ -222,17 +224,20 @@ public final class JobServiceContext implements ServiceConnection {
                     isDeadlineExpired, triggeredUris, triggeredAuthorities, job.network);
             mExecutionStartTimeElapsed = sElapsedRealtimeClock.millis();
 
-            if (DEBUG_STANDBY) {
-                final long whenDeferred = job.getWhenStandbyDeferred();
-                if (whenDeferred > 0) {
+            final long whenDeferred = job.getWhenStandbyDeferred();
+            if (whenDeferred > 0) {
+                final long deferral = mExecutionStartTimeElapsed - whenDeferred;
+                EventLog.writeEvent(EventLogTags.JOB_DEFERRED_EXECUTION, deferral);
+                if (DEBUG_STANDBY) {
                     StringBuilder sb = new StringBuilder(128);
                     sb.append("Starting job deferred for standby by ");
-                    TimeUtils.formatDuration(mExecutionStartTimeElapsed - whenDeferred, sb);
-                    sb.append(" : ");
+                    TimeUtils.formatDuration(deferral, sb);
+                    sb.append(" ms : ");
                     sb.append(job.toShortString());
                     Slog.v(TAG, sb.toString());
                 }
             }
+
             // Once we'e begun executing a job, we by definition no longer care whether
             // it was inflated from disk with not-yet-coherent delay/deadline bounds.
             job.clearPersistedUtcTimes();