Logging and readability improvements (469925d2) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/timedetector/NetworkTimeUpdateService.java

+109 −43

Original line number	Diff line number	Diff line
		@@ -358,9 +358,30 @@ public class NetworkTimeUpdateService extends Binder {
		@NonNull
		private final LocalLog mLocalDebugLog = new LocalLog(30, false /* useLocalTimestamps */);

		/**
		* The usual interval between refresh attempts. Always used after a successful request.
		*
		* <p>The value also determines whether a network time result is considered fresh.
		* Refreshes only take place from this class when the latest time result is considered too
		* old.
		*/
		private final int mNormalPollingIntervalMillis;

		/**
		* A shortened interval between refresh attempts used after a failure to refresh.
		* Always shorter than {@link #mNormalPollingIntervalMillis} and only used when {@link
		* #mTryAgainTimesMax} != 0.
		*/
		private final int mShortPollingIntervalMillis;

		/**
		* The number of times {@link #mShortPollingIntervalMillis} can be used after successive
		* failures before switching back to using {@link #mNormalPollingIntervalMillis} once before
		* repeating. When this value is negative, the refresh algorithm will continue to use {@link
		* #mShortPollingIntervalMillis} until a successful refresh.
		*/
		private final int mTryAgainTimesMax;

		private final NtpTrustedTime mNtpTrustedTime;

		/**
		@@ -378,6 +399,11 @@ public class NetworkTimeUpdateService extends Binder {
		int normalPollingIntervalMillis, int shortPollingIntervalMillis,
		int tryAgainTimesMax, @NonNull NtpTrustedTime ntpTrustedTime) {
		mElapsedRealtimeMillisSupplier = Objects.requireNonNull(elapsedRealtimeMillisSupplier);
		if (shortPollingIntervalMillis > normalPollingIntervalMillis) {
		throw new IllegalArgumentException(String.format(
		"shortPollingIntervalMillis (%s) > normalPollingIntervalMillis (%s)",
		shortPollingIntervalMillis, normalPollingIntervalMillis));
		}
		mNormalPollingIntervalMillis = normalPollingIntervalMillis;
		mShortPollingIntervalMillis = shortPollingIntervalMillis;
		mTryAgainTimesMax = tryAgainTimesMax;
		@@ -387,81 +413,121 @@ public class NetworkTimeUpdateService extends Binder {
		@Override
		public boolean forceRefreshForTests(
		@NonNull Network network, @NonNull RefreshCallbacks refreshCallbacks) {
		boolean success = mNtpTrustedTime.forceRefresh(network);
		logToDebugAndDumpsys("forceRefreshForTests: success=" + success);
		boolean refreshSuccessful = mNtpTrustedTime.forceRefresh(network);
		logToDebugAndDumpsys("forceRefreshForTests: refreshSuccessful=" + refreshSuccessful);

		if (success) {
		if (refreshSuccessful) {
		makeNetworkTimeSuggestion(mNtpTrustedTime.getCachedTimeResult(),
		"EngineImpl.forceRefreshForTests()", refreshCallbacks);
		}
		return success;
		return refreshSuccessful;
		}

		@Override
		public void refreshIfRequiredAndReschedule(
		@NonNull Network network, @NonNull String reason,
		@NonNull RefreshCallbacks refreshCallbacks) {
		long currentElapsedRealtimeMillis = mElapsedRealtimeMillisSupplier.get();

		final int maxNetworkTimeAgeMillis = mNormalPollingIntervalMillis;
		// Force an NTP fix when outdated
		// Attempt to refresh the network time if there is no latest time result, or if the
		// latest time result is considered too old.
		NtpTrustedTime.TimeResult initialTimeResult = mNtpTrustedTime.getCachedTimeResult();
		if (calculateTimeResultAgeMillis(initialTimeResult, currentElapsedRealtimeMillis)
		>= maxNetworkTimeAgeMillis) {
		if (DBG) Log.d(TAG, "Stale NTP fix; forcing refresh using network=" + network);
		boolean successful = mNtpTrustedTime.forceRefresh(network);
		if (successful) {
		boolean shouldAttemptRefresh;
		synchronized (this) {
		mTryAgainCounter = 0;
		}
		} else {
		String logMsg = "forceRefresh() returned false:"
		+ " initialTimeResult=" + initialTimeResult
		+ ", currentElapsedRealtimeMillis=" + currentElapsedRealtimeMillis;
		logToDebugAndDumpsys(logMsg);
		long currentElapsedRealtimeMillis = mElapsedRealtimeMillisSupplier.get();

		// calculateTimeResultAgeMillis() safely handles a null initialTimeResult.
		long timeResultAgeMillis = calculateTimeResultAgeMillis(
		initialTimeResult, currentElapsedRealtimeMillis);
		shouldAttemptRefresh = timeResultAgeMillis >= mNormalPollingIntervalMillis;
		}

		boolean refreshSuccessful = false;
		if (shouldAttemptRefresh) {
		// This is a blocking call. Deliberately invoked without holding the "this" monitor
		// to avoid blocking logic that wants to use the "this" monitor.
		refreshSuccessful = mNtpTrustedTime.forceRefresh(network);
		}

		synchronized (this) {
		long nextPollDelayMillis;
		NtpTrustedTime.TimeResult latestTimeResult = mNtpTrustedTime.getCachedTimeResult();
		if (calculateTimeResultAgeMillis(latestTimeResult, currentElapsedRealtimeMillis)
		< maxNetworkTimeAgeMillis) {
		// Obtained fresh fix; schedule next normal update
		nextPollDelayMillis = mNormalPollingIntervalMillis
		- latestTimeResult.getAgeMillis(currentElapsedRealtimeMillis);

		makeNetworkTimeSuggestion(latestTimeResult, reason, refreshCallbacks);
		// Manage mTryAgainCounter.
		if (shouldAttemptRefresh) {
		if (refreshSuccessful) {
		// Reset failure tracking.
		mTryAgainCounter = 0;
		} else {
		// No fresh fix; schedule retry
		mTryAgainCounter++;
		if (mTryAgainTimesMax < 0 \|\| mTryAgainCounter <= mTryAgainTimesMax) {
		nextPollDelayMillis = mShortPollingIntervalMillis;
		if (mTryAgainTimesMax < 0) {
		// When mTryAgainTimesMax is negative there's no enforced maximum and
		// short intervals should be used until a successful refresh. Setting
		// mTryAgainCounter to 1 is sufficient for the interval calculations
		// below. There's no need to increment.
		mTryAgainCounter = 1;
		} else {
		// Try much later
		mTryAgainCounter++;
		if (mTryAgainCounter > mTryAgainTimesMax) {
		mTryAgainCounter = 0;
		}
		}
		}
		}

		// currentElapsedRealtimeMillis is used to evaluate ages and refresh scheduling
		// below. Capturing this after a possible successful refresh ensures that latest
		// time result ages will be >= 0.
		long currentElapsedRealtimeMillis = mElapsedRealtimeMillisSupplier.get();

		nextPollDelayMillis = mNormalPollingIntervalMillis;
		// This section of code deliberately doesn't assume it is the only component using
		// mNtpTrustedTime to obtain NTP times: another component in the same process could
		// be gathering NTP signals (which then won't have been suggested to the time
		// detector).
		// TODO(b/222295093): Make this class the sole owner of mNtpTrustedTime and
		// simplify / reduce duplicate suggestions.
		NtpTrustedTime.TimeResult latestTimeResult = mNtpTrustedTime.getCachedTimeResult();
		long latestTimeResultAgeMillis = calculateTimeResultAgeMillis(
		latestTimeResult, currentElapsedRealtimeMillis);

		// Suggest the latest time result to the time detector if it is fresh regardless of
		// whether refresh happened above.
		if (latestTimeResultAgeMillis < mNormalPollingIntervalMillis) {
		// We assume the time detector service will detect duplicate suggestions and not
		// do more work than it has to, so no need to avoid making duplicate
		// suggestions.
		makeNetworkTimeSuggestion(latestTimeResult, reason, refreshCallbacks);
		}

		// (Re)schedule the next refresh based on the latest state.
		// Determine which refresh delay to use by using the current value of
		// mTryAgainCounter.
		long refreshDelayMillis = mTryAgainCounter > 0
		? mShortPollingIntervalMillis : mNormalPollingIntervalMillis;
		// Adjust the next refresh time for the age of the latest time result.
		if (latestTimeResultAgeMillis < refreshDelayMillis) {
		refreshDelayMillis -= latestTimeResultAgeMillis;
		}

		long nextRefreshElapsedRealtimeMillis =
		currentElapsedRealtimeMillis + nextPollDelayMillis;
		currentElapsedRealtimeMillis + refreshDelayMillis;
		refreshCallbacks.scheduleNextRefresh(nextRefreshElapsedRealtimeMillis);

		logToDebugAndDumpsys("refreshIfRequiredAndReschedule:"
		+ " network=" + network
		+ ", reason=" + reason
		+ ", currentElapsedRealtimeMillis=" + currentElapsedRealtimeMillis
		+ ", initialTimeResult=" + initialTimeResult
		+ ", shouldAttemptRefresh=" + shouldAttemptRefresh
		+ ", refreshSuccessful=" + refreshSuccessful
		+ ", currentElapsedRealtimeMillis="
		+ formatElapsedRealtimeMillis(currentElapsedRealtimeMillis)
		+ ", latestTimeResult=" + latestTimeResult
		+ ", mTryAgainCounter=" + mTryAgainCounter
		+ ", nextPollDelayMillis=" + nextPollDelayMillis
		+ ", refreshDelayMillis=" + refreshDelayMillis
		+ ", nextRefreshElapsedRealtimeMillis="
		+ Duration.ofMillis(nextRefreshElapsedRealtimeMillis)
		+ " (" + nextRefreshElapsedRealtimeMillis + ")");
		+ formatElapsedRealtimeMillis(nextRefreshElapsedRealtimeMillis));
		}
		}

		private static String formatElapsedRealtimeMillis(
		@ElapsedRealtimeLong long elapsedRealtimeMillis) {
		return Duration.ofMillis(elapsedRealtimeMillis) + " (" + elapsedRealtimeMillis + ")";
		}

		private static long calculateTimeResultAgeMillis(
		@Nullable TimeResult timeResult,
		@ElapsedRealtimeLong long currentElapsedRealtimeMillis) {