Merge "Logging and readability improvements" (d0161eee) · Commits · e / os / android_frameworks_base

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

+109 −43

Original line number	Original line	Diff line number	Diff line
	@@ -358,9 +358,30 @@ public class NetworkTimeUpdateService extends Binder {
	@NonNull		@NonNull
	private final LocalLog mLocalDebugLog = new LocalLog(30, false /* useLocalTimestamps */);		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;		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;		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 int mTryAgainTimesMax;

	private final NtpTrustedTime mNtpTrustedTime;		private final NtpTrustedTime mNtpTrustedTime;

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

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

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

			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) {		synchronized (this) {
	long nextPollDelayMillis;		// Manage mTryAgainCounter.
	NtpTrustedTime.TimeResult latestTimeResult = mNtpTrustedTime.getCachedTimeResult();		if (shouldAttemptRefresh) {
	if (calculateTimeResultAgeMillis(latestTimeResult, currentElapsedRealtimeMillis)		if (refreshSuccessful) {
	< maxNetworkTimeAgeMillis) {		// Reset failure tracking.
	// Obtained fresh fix; schedule next normal update		mTryAgainCounter = 0;
	nextPollDelayMillis = mNormalPollingIntervalMillis
	- latestTimeResult.getAgeMillis(currentElapsedRealtimeMillis);

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

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

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

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

services/tests/servicestests/src/com/android/server/timedetector/NetworkTimeUpdateServiceTest.java

+195 −39

File changed.

Preview size limit exceeded, changes collapsed.