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

1 files changed, 20 insertions, 3 deletions

diff --git a/core/java/com/android/internal/app/procstats/ProcessStats.java b/core/java/com/android/internal/app/procstats/ProcessStats.java
index e7ac5664c3ee..19d8a836fc4c 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());
                 }