From 7234fc6fef781e33842bc598a6e9e04bbff4f898 Mon Sep 17 00:00:00 2001
From: Christopher Tate <ctate@google.com>
Date: Mon, 3 Apr 2017 17:36:07 -0700
Subject: [PATCH] Track pending job latency

Timestamp jobs being marked 'pending' and 'active,' so we can then report their
pending latency in dumpsys.

Bug 35385393
Test: N/A

Change-Id: I3d981fbc7fbe6abdf30da3f86d88d3733b797f51
---
 .../com/android/server/job/JobPackageTracker.java  |  2 ++
 .../android/server/job/JobSchedulerService.java    | 14 +++++++++++---
 .../server/job/controllers/IdleController.java     |  8 ++++++--
 .../android/server/job/controllers/JobStatus.java  |  4 ++++
 4 files changed, 23 insertions(+), 5 deletions(-)

diff --git a/services/core/java/com/android/server/job/JobPackageTracker.java b/services/core/java/com/android/server/job/JobPackageTracker.java
index 0a6d8a4e24745..8ad1beace6432 100644
--- a/services/core/java/com/android/server/job/JobPackageTracker.java
+++ b/services/core/java/com/android/server/job/JobPackageTracker.java
@@ -345,6 +345,7 @@ public final class JobPackageTracker {
 
     public void notePending(JobStatus job) {
         final long now = SystemClock.uptimeMillis();
+        job.madePending = now;
         rebatchIfNeeded(now);
         mCurDataSet.incPending(job.getSourceUid(), job.getSourcePackageName(), now);
     }
@@ -357,6 +358,7 @@ public final class JobPackageTracker {
 
     public void noteActive(JobStatus job) {
         final long now = SystemClock.uptimeMillis();
+        job.madeActive = now;
         rebatchIfNeeded(now);
         if (job.lastEvaluatedPriority >= JobInfo.PRIORITY_TOP_APP) {
             mCurDataSet.incActiveTop(job.getSourceUid(), job.getSourcePackageName(), now);
diff --git a/services/core/java/com/android/server/job/JobSchedulerService.java b/services/core/java/com/android/server/job/JobSchedulerService.java
index 7c231ff45434b..cd3ba4c8b1f34 100644
--- a/services/core/java/com/android/server/job/JobSchedulerService.java
+++ b/services/core/java/com/android/server/job/JobSchedulerService.java
@@ -2035,27 +2035,35 @@ public final class JobSchedulerService extends com.android.server.SystemService
                     pw.print("    Evaluated priority: "); pw.println(priority);
                 }
                 pw.print("    Tag: "); pw.println(job.getTag());
+                pw.print("    Enq: ");
+                TimeUtils.formatDuration(now - job.madePending, pw);
+                pw.println(" ago");
             }
             pw.println();
             pw.println("Active jobs:");
             for (int i=0; i<mActiveServices.size(); i++) {
                 JobServiceContext jsc = mActiveServices.get(i);
                 pw.print("  Slot #"); pw.print(i); pw.print(": ");
-                if (jsc.getRunningJob() == null) {
+                final JobStatus job = jsc.getRunningJob();
+                if (job == null) {
                     pw.println("inactive");
                     continue;
                 } else {
-                    pw.println(jsc.getRunningJob().toShortString());
+                    pw.println(job.toShortString());
                     pw.print("    Running for: ");
                     TimeUtils.formatDuration(now - jsc.getExecutionStartTimeElapsed(), pw);
                     pw.print(", timeout at: ");
                     TimeUtils.formatDuration(jsc.getTimeoutElapsed() - now, pw);
                     pw.println();
-                    jsc.getRunningJob().dump(pw, "    ", false);
+                    job.dump(pw, "    ", false);
                     int priority = evaluateJobPriorityLocked(jsc.getRunningJob());
                     if (priority != JobInfo.PRIORITY_DEFAULT) {
                         pw.print("    Evaluated priority: "); pw.println(priority);
                     }
+                    pw.print("    Active at "); pw.println(job.madeActive);
+                    pw.print("    Pending for ");
+                    TimeUtils.formatDuration(job.madeActive - job.madePending, pw);
+                    pw.println();
                 }
             }
             if (filterUid == -1) {
diff --git a/services/core/java/com/android/server/job/controllers/IdleController.java b/services/core/java/com/android/server/job/controllers/IdleController.java
index f41e1876e721a..0e04d2441bf8c 100644
--- a/services/core/java/com/android/server/job/controllers/IdleController.java
+++ b/services/core/java/com/android/server/job/controllers/IdleController.java
@@ -147,7 +147,6 @@ public class IdleController extends StateController {
         @Override
         public void onReceive(Context context, Intent intent) {
             final String action = intent.getAction();
-
             if (action.equals(Intent.ACTION_SCREEN_ON)
                     || action.equals(Intent.ACTION_DREAMING_STOPPED)) {
                 if (DEBUG) {
@@ -183,6 +182,11 @@ public class IdleController extends StateController {
                     }
                     mIdle = true;
                     reportNewIdleState(mIdle);
+                } else {
+                    if (DEBUG) {
+                        Slog.v(TAG, "TRIGGER_IDLE received but not changing state; idle="
+                                + mIdle + " screen=" + mScreenOn);
+                    }
                 }
             }
         }
@@ -191,7 +195,7 @@ public class IdleController extends StateController {
     @Override
     public void dumpControllerStateLocked(PrintWriter pw, int filterUid) {
         pw.print("Idle: ");
-        pw.println(mIdleTracker.isIdle() ? "true" : "false");
+        pw.println(mIdleTracker.isIdle());
         pw.print("Tracking ");
         pw.print(mTrackedTasks.size());
         pw.println(":");
diff --git a/services/core/java/com/android/server/job/controllers/JobStatus.java b/services/core/java/com/android/server/job/controllers/JobStatus.java
index 47630d0d734b5..d27d0e582cc5f 100644
--- a/services/core/java/com/android/server/job/controllers/JobStatus.java
+++ b/services/core/java/com/android/server/job/controllers/JobStatus.java
@@ -129,6 +129,10 @@ public final class JobStatus {
     // Used by shell commands
     public int overrideState = 0;
 
+    // Metrics about queue latency
+    public long madePending;
+    public long madeActive;
+
     /**
      * For use only by ContentObserverController: state it is maintaining about content URIs
      * being observed.