From b99b582f490139187ef1d1acde4dcec611c3b8d9 Mon Sep 17 00:00:00 2001 From: Kweku Adams Date: Tue, 28 Apr 2020 12:53:38 -0700 Subject: [PATCH] Fix QC alarm spamming. Apps could reach their job count limit during an active session. When this happened, QC would correctly identify that the app was out of quota, but it wasn't correctly calculating the in quota time, so it was trying to set a time at 0 (or whatever the last in quota time had been). This caused a loop where AlarmManager would fire the alarm, QC would see the app was still out of quota, and set a new alarm for the same old time. This cycle was more common for apps in the RESTRICTED bucket that had a much lower job limit. Now we correctly calculate the in quota time and avoid the spammy loop. Bug: 154444435 Bug: 155245660 Test: atest CountQuotaTrackerTest Test: atest CtsJobSchedulerTestCases Test: atest QuotaControllerTest Change-Id: If07a6133b3ccf8201ac2fd86622bd8e1686f1b0a --- .../job/controllers/QuotaController.java | 36 +++++++--- .../server/utils/quota/CountQuotaTracker.java | 7 +- .../job/controllers/QuotaControllerTest.java | 71 +++++++++++++++++++ 3 files changed, 105 insertions(+), 9 deletions(-) diff --git a/apex/jobscheduler/service/java/com/android/server/job/controllers/QuotaController.java b/apex/jobscheduler/service/java/com/android/server/job/controllers/QuotaController.java index 8c55b50957da8..d108f0b698f77 100644 --- a/apex/jobscheduler/service/java/com/android/server/job/controllers/QuotaController.java +++ b/apex/jobscheduler/service/java/com/android/server/job/controllers/QuotaController.java @@ -241,10 +241,11 @@ public final class QuotaController extends StateController { + "bgJobCountInMaxPeriod=" + bgJobCountInMaxPeriod + ", " + "sessionCountInWindow=" + sessionCountInWindow + ", " + "inQuotaTime=" + inQuotaTimeElapsed + ", " - + "jobCountExpirationTime=" + jobRateLimitExpirationTimeElapsed + ", " - + "jobCountInRateLimitingWindow=" + jobCountInRateLimitingWindow + ", " - + "sessionCountExpirationTime=" + sessionRateLimitExpirationTimeElapsed + ", " - + "sessionCountInRateLimitingWindow=" + sessionCountInRateLimitingWindow; + + "rateLimitJobCountExpirationTime=" + jobRateLimitExpirationTimeElapsed + ", " + + "rateLimitJobCountWindow=" + jobCountInRateLimitingWindow + ", " + + "rateLimitSessionCountExpirationTime=" + + sessionRateLimitExpirationTimeElapsed + ", " + + "rateLimitSessionCountWindow=" + sessionCountInRateLimitingWindow; } @Override @@ -863,12 +864,19 @@ public final class QuotaController extends StateController { stats.executionTimeInMaxPeriodMs = 0; stats.bgJobCountInMaxPeriod = 0; stats.sessionCountInWindow = 0; - stats.inQuotaTimeElapsed = 0; + if (stats.jobCountLimit == 0 || stats.sessionCountLimit == 0) { + // App won't be in quota until configuration changes. + stats.inQuotaTimeElapsed = Long.MAX_VALUE; + } else { + stats.inQuotaTimeElapsed = 0; + } Timer timer = mPkgTimers.get(userId, packageName); final long nowElapsed = sElapsedRealtimeClock.millis(); stats.expirationTimeElapsed = nowElapsed + MAX_PERIOD_MS; if (timer != null && timer.isActive()) { + // Exclude active sessions from the session count so that new jobs aren't prevented + // from starting due to an app hitting the session limit. stats.executionTimeInWindowMs = stats.executionTimeInMaxPeriodMs = timer.getCurrentDuration(nowElapsed); stats.bgJobCountInWindow = stats.bgJobCountInMaxPeriod = timer.getBgJobCount(); @@ -883,6 +891,10 @@ public final class QuotaController extends StateController { stats.inQuotaTimeElapsed = Math.max(stats.inQuotaTimeElapsed, nowElapsed - mMaxExecutionTimeIntoQuotaMs + MAX_PERIOD_MS); } + if (stats.bgJobCountInWindow >= stats.jobCountLimit) { + stats.inQuotaTimeElapsed = Math.max(stats.inQuotaTimeElapsed, + nowElapsed + stats.windowSizeMs); + } } List sessions = mTimingSessions.get(userId, packageName); @@ -1303,6 +1315,13 @@ public final class QuotaController extends StateController { inQuotaTimeElapsed = Math.max(inQuotaTimeElapsed, stats.sessionRateLimitExpirationTimeElapsed); } + if (inQuotaTimeElapsed <= sElapsedRealtimeClock.millis()) { + final long nowElapsed = sElapsedRealtimeClock.millis(); + Slog.wtf(TAG, + "In quota time is " + (nowElapsed - inQuotaTimeElapsed) + "ms old. Now=" + + nowElapsed + ", inQuotaTime=" + inQuotaTimeElapsed + ": " + stats); + inQuotaTimeElapsed = nowElapsed + 5 * MINUTE_IN_MILLIS; + } mInQuotaAlarmListener.addAlarmLocked(userId, packageName, inQuotaTimeElapsed); } @@ -1916,8 +1935,8 @@ public final class QuotaController extends StateController { @GuardedBy("mLock") private void setNextAlarmLocked(long earliestTriggerElapsed) { if (mAlarmQueue.size() > 0) { - final long nextTriggerTimeElapsed = Math.max(earliestTriggerElapsed, - mAlarmQueue.peek().second); + final Pair alarm = mAlarmQueue.peek(); + final long nextTriggerTimeElapsed = Math.max(earliestTriggerElapsed, alarm.second); // Only schedule the alarm if one of the following is true: // 1. There isn't one currently scheduled // 2. The new alarm is significantly earlier than the previous alarm. If it's @@ -1928,7 +1947,8 @@ public final class QuotaController extends StateController { || nextTriggerTimeElapsed < mTriggerTimeElapsed - 3 * MINUTE_IN_MILLIS || mTriggerTimeElapsed < nextTriggerTimeElapsed) { if (DEBUG) { - Slog.d(TAG, "Scheduling start alarm at " + nextTriggerTimeElapsed); + Slog.d(TAG, "Scheduling start alarm at " + nextTriggerTimeElapsed + + " for app " + alarm.first); } mAlarmManager.set(AlarmManager.ELAPSED_REALTIME, nextTriggerTimeElapsed, ALARM_TAG_QUOTA_CHECK, this, mHandler); diff --git a/services/core/java/com/android/server/utils/quota/CountQuotaTracker.java b/services/core/java/com/android/server/utils/quota/CountQuotaTracker.java index 7fe4bf8494439..b77df2d188596 100644 --- a/services/core/java/com/android/server/utils/quota/CountQuotaTracker.java +++ b/services/core/java/com/android/server/utils/quota/CountQuotaTracker.java @@ -408,7 +408,12 @@ public class CountQuotaTracker extends QuotaTracker { void updateExecutionStatsLocked(final int userId, @NonNull final String packageName, @Nullable final String tag, @NonNull ExecutionStats stats) { stats.countInWindow = 0; - stats.inQuotaTimeElapsed = 0; + if (stats.countLimit == 0) { + // UPTC won't be in quota until configuration changes. + stats.inQuotaTimeElapsed = Long.MAX_VALUE; + } else { + stats.inQuotaTimeElapsed = 0; + } // This can be used to determine when an app will have enough quota to transition from // out-of-quota to in-quota. diff --git a/services/tests/mockingservicestests/src/com/android/server/job/controllers/QuotaControllerTest.java b/services/tests/mockingservicestests/src/com/android/server/job/controllers/QuotaControllerTest.java index bc0b184cd359b..c8ec7b5503d18 100644 --- a/services/tests/mockingservicestests/src/com/android/server/job/controllers/QuotaControllerTest.java +++ b/services/tests/mockingservicestests/src/com/android/server/job/controllers/QuotaControllerTest.java @@ -620,6 +620,77 @@ public class QuotaControllerTest { assertEquals(expectedStats, inputStats); } + @Test + public void testUpdateExecutionStatsLocked_WithTimer() { + final long now = sElapsedRealtimeClock.millis(); + setProcessState(ActivityManager.PROCESS_STATE_SERVICE); + + ExecutionStats expectedStats = new ExecutionStats(); + ExecutionStats inputStats = new ExecutionStats(); + inputStats.windowSizeMs = expectedStats.windowSizeMs = 24 * HOUR_IN_MILLIS; + inputStats.jobCountLimit = expectedStats.jobCountLimit = mQcConstants.MAX_JOB_COUNT_RARE; + inputStats.sessionCountLimit = expectedStats.sessionCountLimit = + mQcConstants.MAX_SESSION_COUNT_RARE; + // Active timer isn't counted as session yet. + expectedStats.sessionCountInWindow = 0; + // Timer only, under quota. + for (int i = 1; i < mQcConstants.MAX_JOB_COUNT_RARE; ++i) { + JobStatus jobStatus = createJobStatus("testUpdateExecutionStatsLocked_WithTimer", i); + setStandbyBucket(RARE_INDEX, jobStatus); // 24 hour window + mQuotaController.maybeStartTrackingJobLocked(jobStatus, null); + mQuotaController.prepareForExecutionLocked(jobStatus); + advanceElapsedClock(7000); + + expectedStats.expirationTimeElapsed = sElapsedRealtimeClock.millis(); + expectedStats.executionTimeInWindowMs = expectedStats.executionTimeInMaxPeriodMs = + 7000 * i; + expectedStats.bgJobCountInWindow = expectedStats.bgJobCountInMaxPeriod = i; + mQuotaController.updateExecutionStatsLocked(SOURCE_USER_ID, SOURCE_PACKAGE, inputStats); + assertEquals(expectedStats, inputStats); + assertTrue(mQuotaController.isWithinQuotaLocked(SOURCE_USER_ID, SOURCE_PACKAGE, + RARE_INDEX)); + } + + // Add old session. Make sure values are combined correctly. + mQuotaController.saveTimingSession(SOURCE_USER_ID, SOURCE_PACKAGE, + createTimingSession(sElapsedRealtimeClock.millis() - (6 * HOUR_IN_MILLIS), + 10 * MINUTE_IN_MILLIS, 5)); + expectedStats.sessionCountInWindow = 1; + + expectedStats.expirationTimeElapsed = sElapsedRealtimeClock.millis() + 18 * HOUR_IN_MILLIS; + expectedStats.executionTimeInWindowMs += 10 * MINUTE_IN_MILLIS; + expectedStats.executionTimeInMaxPeriodMs += 10 * MINUTE_IN_MILLIS; + expectedStats.bgJobCountInWindow += 5; + expectedStats.bgJobCountInMaxPeriod += 5; + // Active timer is under quota, so out of quota due to old session. + expectedStats.inQuotaTimeElapsed = + sElapsedRealtimeClock.millis() + 18 * HOUR_IN_MILLIS + 10 * MINUTE_IN_MILLIS; + mQuotaController.updateExecutionStatsLocked(SOURCE_USER_ID, SOURCE_PACKAGE, inputStats); + assertEquals(expectedStats, inputStats); + assertFalse( + mQuotaController.isWithinQuotaLocked(SOURCE_USER_ID, SOURCE_PACKAGE, RARE_INDEX)); + + // Quota should be exceeded due to activity in active timer. + JobStatus jobStatus = createJobStatus("testUpdateExecutionStatsLocked_WithTimer", 0); + setStandbyBucket(RARE_INDEX, jobStatus); // 24 hour window + mQuotaController.maybeStartTrackingJobLocked(jobStatus, null); + mQuotaController.prepareForExecutionLocked(jobStatus); + advanceElapsedClock(10000); + + expectedStats.executionTimeInWindowMs += 10000; + expectedStats.executionTimeInMaxPeriodMs += 10000; + expectedStats.bgJobCountInWindow++; + expectedStats.bgJobCountInMaxPeriod++; + // Out of quota due to activity in active timer, so in quota time should be when enough + // time has passed since active timer. + expectedStats.inQuotaTimeElapsed = + sElapsedRealtimeClock.millis() + expectedStats.windowSizeMs; + mQuotaController.updateExecutionStatsLocked(SOURCE_USER_ID, SOURCE_PACKAGE, inputStats); + assertEquals(expectedStats, inputStats); + assertFalse( + mQuotaController.isWithinQuotaLocked(SOURCE_USER_ID, SOURCE_PACKAGE, RARE_INDEX)); + } + /** * Tests that getExecutionStatsLocked returns the correct stats. */