From 3a8e5c50bc133cc035b5f63fbde4a712ae7ada6f Mon Sep 17 00:00:00 2001
From: Makoto Onuki <omakoto@google.com>
Date: Mon, 5 Nov 2018 15:53:53 -0800
Subject: [PATCH] Fix "Tracking association..." logspam.

In the previous code, updateTrackingAssociationsLocked() was called too early.
There's still code that changes procstates, so let's move
updateTrackingAssociationsLocked() to the end of updateOomAdjLocked().

Also change Slog.w() to Slog.wtf() so we can monitor it on APR.

Also rate limit the WTF to at most one in ten seconds.

Bug: 118826162
Test: Boot with and without the fix and make sure the number of the warnings
reduces.
(We still have a couple WTFs from during a boot with this CL, which requires
further investigation.)

Change-Id: Ifa1fe85de82fa1d1d8f843372c54c1248966a62a
---
 .../internal/app/procstats/ProcessStats.java  | 23 ++++++++++++++++---
 .../server/am/ActivityManagerService.java     |  5 ++--
 2 files changed, 23 insertions(+), 5 deletions(-)

diff --git a/core/java/com/android/internal/app/procstats/ProcessStats.java b/core/java/com/android/internal/app/procstats/ProcessStats.java
index e7ac5664c3ee9..19d8a836fc4c4 100644
--- a/core/java/com/android/internal/app/procstats/ProcessStats.java
+++ b/core/java/com/android/internal/app/procstats/ProcessStats.java
@@ -1396,6 +1396,11 @@ public final class ProcessStats implements Parcelable {
         return as;
     }
 
+    // See b/118826162 -- to avoid logspaming, we rate limit the WTF.
+    private static final long INVERSE_PROC_STATE_WTF_MIN_INTERVAL_MS = 10_000L;
+    private long mNextInverseProcStateWtfUptime;
+    private int mSkippedInverseProcStateWtfCount;
+
     public void updateTrackingAssociationsLocked(int curSeq, long now) {
         final int NUM = mTrackingAssociations.size();
         for (int i = NUM - 1; i >= 0; i--) {
@@ -1417,12 +1422,24 @@ public final class ProcessStats implements Parcelable {
                     } else {
                         act.stopActive(now);
                         if (act.mProcState < procState) {
-                            Slog.w(TAG, "Tracking association " + act + " whose proc state "
-                                    + act.mProcState + " is better than process " + proc
-                                    + " proc state " + procState);
+                            final long nowUptime = SystemClock.uptimeMillis();
+                            if (mNextInverseProcStateWtfUptime > nowUptime) {
+                                mSkippedInverseProcStateWtfCount++;
+                            } else {
+                                // TODO We still see it during boot related to GMS-core.
+                                // b/118826162
+                                Slog.wtf(TAG, "Tracking association " + act + " whose proc state "
+                                        + act.mProcState + " is better than process " + proc
+                                        + " proc state " + procState
+                                        + " (" +  mSkippedInverseProcStateWtfCount + " skipped)");
+                                mSkippedInverseProcStateWtfCount = 0;
+                                mNextInverseProcStateWtfUptime =
+                                        nowUptime + INVERSE_PROC_STATE_WTF_MIN_INTERVAL_MS;
+                            }
                         }
                     }
                 } else {
+                    // Don't need rate limiting on it.
                     Slog.wtf(TAG, "Tracking association without process: " + act
                             + " in " + act.getAssociationState());
                 }
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index 4d6fa2927127a..ce8fdbbe17c24 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -17343,8 +17343,6 @@ public class ActivityManagerService extends IActivityManager.Stub
             }
         }
 
-        mProcessStats.updateTrackingAssociationsLocked(mAdjSeq, now);
-
         incrementProcStateSeqAndNotifyAppsLocked();
 
         mNumServiceProcs = mNewNumServiceProcs;
@@ -17606,6 +17604,9 @@ public class ActivityManagerService extends IActivityManager.Stub
             mHandler.post(new ProcStatsRunnable(ActivityManagerService.this, mProcessStats));
         }
 
+        // Run this after making sure all procstates are updated.
+        mProcessStats.updateTrackingAssociationsLocked(mAdjSeq, now);
+
         if (DEBUG_OOM_ADJ) {
             final long duration = SystemClock.uptimeMillis() - now;
             if (false) {