From eea7870783d25503930e2020634ab14829f52a32 Mon Sep 17 00:00:00 2001 From: Neil Fuller Date: Wed, 14 Dec 2022 15:50:00 +0000 Subject: [PATCH] Improve debug logging for NetworkTimeHelper Adds dumpsys logging support to NetworkTimeHelper and implement it for NtpNetworkTimeHelper. This enables better tracking of whether it currently does what is expected and help comparison with its proposed replacement. Bug: 222295093 Test: treehugger / manual build / boot Change-Id: Idb74ad2842dcc7f521800cdd4f026db1b47dbebc --- .../location/gnss/ExponentialBackOff.java | 9 ++ .../location/gnss/GnssLocationProvider.java | 1 + .../location/gnss/NetworkTimeHelper.java | 16 ++- .../location/gnss/NtpNetworkTimeHelper.java | 103 +++++++++++++----- 4 files changed, 101 insertions(+), 28 deletions(-) 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); + } + } }