diff --git a/services/core/java/com/android/server/location/gnss/ExponentialBackOff.java b/services/core/java/com/android/server/location/gnss/ExponentialBackOff.java index 05a534fa36e9f..aab52ce52a0db 100644 --- a/services/core/java/com/android/server/location/gnss/ExponentialBackOff.java +++ b/services/core/java/com/android/server/location/gnss/ExponentialBackOff.java @@ -44,5 +44,14 @@ class ExponentialBackOff { void reset() { mCurrentIntervalMillis = mInitIntervalMillis / MULTIPLIER; } + + @Override + public String toString() { + return "ExponentialBackOff{" + + "mInitIntervalMillis=" + mInitIntervalMillis + + ", mMaxIntervalMillis=" + mMaxIntervalMillis + + ", mCurrentIntervalMillis=" + mCurrentIntervalMillis + + '}'; + } } diff --git a/services/core/java/com/android/server/location/gnss/GnssLocationProvider.java b/services/core/java/com/android/server/location/gnss/GnssLocationProvider.java index 262013ec8d961..e48412ab40292 100644 --- a/services/core/java/com/android/server/location/gnss/GnssLocationProvider.java +++ b/services/core/java/com/android/server/location/gnss/GnssLocationProvider.java @@ -1695,6 +1695,7 @@ public class GnssLocationProvider extends AbstractLocationProvider implements pw.println("mFixInterval=" + mFixInterval); pw.print(mGnssMetrics.dumpGnssMetricsAsText()); if (dumpAll) { + mNetworkTimeHelper.dump(pw); pw.println("mSupportsPsds=" + mSupportsPsds); pw.println( "PsdsServerConfigured=" + mGnssConfiguration.isLongTermPsdsServerConfigured()); diff --git a/services/core/java/com/android/server/location/gnss/NetworkTimeHelper.java b/services/core/java/com/android/server/location/gnss/NetworkTimeHelper.java index 72d6f70145153..3a2514604600f 100644 --- a/services/core/java/com/android/server/location/gnss/NetworkTimeHelper.java +++ b/services/core/java/com/android/server/location/gnss/NetworkTimeHelper.java @@ -15,9 +15,14 @@ */ package com.android.server.location.gnss; +import android.annotation.CurrentTimeMillisLong; +import android.annotation.ElapsedRealtimeLong; +import android.annotation.NonNull; import android.content.Context; import android.os.Looper; +import java.io.PrintWriter; + /** * An abstraction for use by {@link GnssLocationProvider}. This class allows switching between * implementations with a compile-time constant change, which is less risky than rolling back a @@ -32,15 +37,16 @@ abstract class NetworkTimeHelper { * the looper passed to {@link #create(Context, Looper, InjectTimeCallback)}. */ interface InjectTimeCallback { - void injectTime(long unixEpochTimeMillis, long elapsedRealtimeMillis, - int uncertaintyMillis); + void injectTime(@CurrentTimeMillisLong long unixEpochTimeMillis, + @ElapsedRealtimeLong long elapsedRealtimeMillis, int uncertaintyMillis); } /** * Creates the {@link NetworkTimeHelper} instance for use by {@link GnssLocationProvider}. */ static NetworkTimeHelper create( - Context context, Looper looper, InjectTimeCallback injectTimeCallback) { + @NonNull Context context, @NonNull Looper looper, + @NonNull InjectTimeCallback injectTimeCallback) { return new NtpNetworkTimeHelper(context, looper, injectTimeCallback); } @@ -72,4 +78,8 @@ abstract class NetworkTimeHelper { */ abstract void onNetworkAvailable(); + /** + * Dumps internal state during bugreports useful for debugging. + */ + abstract void dump(@NonNull PrintWriter pw); } diff --git a/services/core/java/com/android/server/location/gnss/NtpNetworkTimeHelper.java b/services/core/java/com/android/server/location/gnss/NtpNetworkTimeHelper.java index 479dbdab8bd58..d682164c988d1 100644 --- a/services/core/java/com/android/server/location/gnss/NtpNetworkTimeHelper.java +++ b/services/core/java/com/android/server/location/gnss/NtpNetworkTimeHelper.java @@ -23,12 +23,17 @@ import android.os.Handler; import android.os.Looper; import android.os.PowerManager; import android.os.PowerManager.WakeLock; +import android.os.SystemClock; +import android.util.IndentingPrintWriter; +import android.util.LocalLog; import android.util.Log; import android.util.NtpTrustedTime; import com.android.internal.annotations.GuardedBy; import com.android.internal.annotations.VisibleForTesting; +import java.io.PrintWriter; + /** * Handles injecting network time to GNSS by explicitly making NTP requests when needed. */ @@ -60,6 +65,9 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { private static final long WAKELOCK_TIMEOUT_MILLIS = 60 * 1000; private static final String WAKELOCK_KEY = "NtpTimeHelper"; + private final LocalLog mDumpLog = new LocalLog(10, /*useLocalTimestamps=*/false); + + @GuardedBy("this") private final ExponentialBackOff mNtpBackOff = new ExponentialBackOff(RETRY_INTERVAL, MAX_RETRY_INTERVAL); @@ -103,16 +111,39 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { @Override void demandUtcTimeInjection() { - retrieveAndInjectNtpTime(); + retrieveAndInjectNtpTime("demandUtcTimeInjection"); } @Override synchronized void onNetworkAvailable() { if (mInjectNtpTimeState == STATE_PENDING_NETWORK) { - retrieveAndInjectNtpTime(); + retrieveAndInjectNtpTime("onNetworkAvailable"); } } + @Override + void dump(PrintWriter pw) { + pw.println("NtpNetworkTimeHelper:"); + + IndentingPrintWriter ipw = new IndentingPrintWriter(pw, " "); + ipw.increaseIndent(); + synchronized (this) { + ipw.println("mInjectNtpTimeState=" + mInjectNtpTimeState); + ipw.println("mPeriodicTimeInjection=" + mPeriodicTimeInjection); + ipw.println("mNtpBackOff=" + mNtpBackOff); + } + + ipw.println("Debug log:"); + ipw.increaseIndent(); + mDumpLog.dump(ipw); + ipw.decreaseIndent(); + + ipw.println("NtpTrustedTime:"); + ipw.increaseIndent(); + mNtpTime.dump(ipw); + ipw.decreaseIndent(); + } + /** * @return {@code true} if there is a network available for outgoing connections, * {@code false} otherwise. @@ -122,14 +153,14 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { return activeNetworkInfo != null && activeNetworkInfo.isConnected(); } - private synchronized void retrieveAndInjectNtpTime() { + private synchronized void retrieveAndInjectNtpTime(String reason) { if (mInjectNtpTimeState == STATE_RETRIEVING_AND_INJECTING) { // already downloading data return; } if (!isNetworkConnected()) { // try to inject the cached NTP time - injectCachedNtpTime(); + maybeInjectCachedNtpTime(reason + "[Network not connected]"); // try again when network is up mInjectNtpTimeState = STATE_PENDING_NETWORK; return; @@ -143,7 +174,8 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { /** {@link NtpTrustedTime#forceRefresh} is a blocking network operation. */ private void blockingGetNtpTimeAndInject() { - long delay; + long debugId = SystemClock.elapsedRealtime(); + long delayMillis; // force refresh NTP cache when outdated boolean refreshSuccess = true; @@ -158,26 +190,30 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { // only update when NTP time is fresh // If refreshSuccess is false, cacheAge does not drop down. - if (injectCachedNtpTime()) { - delay = NTP_INTERVAL; + String injectReason = "blockingGetNtpTimeAndInject:" + + ", debugId=" + debugId + + ", refreshSuccess=" + refreshSuccess; + if (maybeInjectCachedNtpTime(injectReason)) { + delayMillis = NTP_INTERVAL; mNtpBackOff.reset(); } else { - Log.e(TAG, "requestTime failed"); - delay = mNtpBackOff.nextBackoffMillis(); + logWarn("maybeInjectCachedNtpTime() returned false"); + delayMillis = mNtpBackOff.nextBackoffMillis(); } - if (DEBUG) { - Log.d(TAG, String.format( - "mPeriodicTimeInjection=%s, refreshSuccess=%s, delay=%s", - mPeriodicTimeInjection, - refreshSuccess, - delay)); - } if (mPeriodicTimeInjection || !refreshSuccess) { + String debugMsg = "blockingGetNtpTimeAndInject: Scheduling later NTP retrieval" + + ", debugId=" + debugId + + ", mPeriodicTimeInjection=" + mPeriodicTimeInjection + + ", refreshSuccess=" + refreshSuccess + + ", delayMillis=" + delayMillis; + logDebug(debugMsg); + // Schedule next NTP injection. // Since this is delayed, the wake lock is released right away, and will be held // again when the delayed task runs. - mHandler.postDelayed(this::retrieveAndInjectNtpTime, delay); + String reason = "scheduled: debugId=" + debugId; + mHandler.postDelayed(() -> retrieveAndInjectNtpTime(reason), delayMillis); } } // release wake lock held by task @@ -185,24 +221,41 @@ class NtpNetworkTimeHelper extends NetworkTimeHelper { } /** Returns true if successfully inject cached NTP time. */ - private synchronized boolean injectCachedNtpTime() { + private synchronized boolean maybeInjectCachedNtpTime(String reason) { NtpTrustedTime.TimeResult ntpResult = mNtpTime.getCachedTimeResult(); if (ntpResult == null || ntpResult.getAgeMillis() >= NTP_INTERVAL) { + String debugMsg = "maybeInjectCachedNtpTime: Not injecting latest NTP time" + + ", reason=" + reason + + ", ntpResult=" + ntpResult; + logDebug(debugMsg); + return false; } long unixEpochTimeMillis = ntpResult.getTimeMillis(); + long currentTimeMillis = System.currentTimeMillis(); + String debugMsg = "maybeInjectCachedNtpTime: Injecting latest NTP time" + + ", reason=" + reason + + ", ntpResult=" + ntpResult + + ", System time offset millis=" + (unixEpochTimeMillis - currentTimeMillis); + logDebug(debugMsg); + long timeReferenceMillis = ntpResult.getElapsedRealtimeMillis(); int uncertaintyMillis = ntpResult.getUncertaintyMillis(); - if (DEBUG) { - long currentTimeMillis = System.currentTimeMillis(); - Log.d(TAG, "NTP server returned: " + unixEpochTimeMillis - + " ntpResult: " + ntpResult - + " system time offset: " + (unixEpochTimeMillis - currentTimeMillis)); - } - mHandler.post(() -> mCallback.injectTime(unixEpochTimeMillis, timeReferenceMillis, uncertaintyMillis)); return true; } + + private void logWarn(String logMsg) { + mDumpLog.log(logMsg); + Log.e(TAG, logMsg); + } + + private void logDebug(String debugMsg) { + mDumpLog.log(debugMsg); + if (DEBUG) { + Log.d(TAG, debugMsg); + } + } }