diff --git a/services/credentials/java/com/android/server/credentials/MetricUtilities.java b/services/credentials/java/com/android/server/credentials/MetricUtilities.java index f75a9b685d10f..e7b0a2d9f7312 100644 --- a/services/credentials/java/com/android/server/credentials/MetricUtilities.java +++ b/services/credentials/java/com/android/server/credentials/MetricUtilities.java @@ -43,8 +43,8 @@ public class MetricUtilities { private static final String TAG = "MetricUtilities"; - private static final int DEFAULT_INT_32 = -1; - private static final int[] DEFAULT_REPEATED_INT_32 = new int[0]; + public static final int DEFAULT_INT_32 = -1; + public static final int[] DEFAULT_REPEATED_INT_32 = new int[0]; // Metrics constants TODO(b/269290341) migrate to enums eventually to improve protected static final int METRICS_PROVIDER_STATUS_FINAL_FAILURE = @@ -79,6 +79,21 @@ public class MetricUtilities { return sessUid; } + /** + * Given any two timestamps in nanoseconds, this gets the difference and converts to + * milliseconds. Assumes the difference is not larger than the maximum int size. + * + * @param t2 the final timestamp + * @param t1 the initial timestamp + * @return the timestamp difference converted to microseconds + */ + protected static int getMetricTimestampDifferenceMicroseconds(long t2, long t1) { + if (t2 - t1 > Integer.MAX_VALUE) { + throw new ArithmeticException("Input timestamps are too far apart and unsupported"); + } + return (int) ((t2 - t1) / 1000); + } + /** * The most common logging helper, handles the overall status of the API request with the * provider status and latencies. Other versions of this method may be more useful depending @@ -102,7 +117,7 @@ public class MetricUtilities { for (var session : providerSessions) { CandidateProviderMetric metric = session.mCandidateProviderMetric; candidateUidList[index] = metric.getCandidateUid(); - candidateQueryRoundTripTimeList[index] = metric.getQueryLatencyMs(); + candidateQueryRoundTripTimeList[index] = metric.getQueryLatencyMicroseconds(); candidateStatusList[index] = metric.getProviderQueryStatus(); index++; } @@ -116,9 +131,11 @@ public class MetricUtilities { /* repeated_candidate_provider_status */ candidateStatusList, /* chosen_provider_uid */ chosenProviderMetric.getChosenUid(), /* chosen_provider_round_trip_time_overall_microseconds */ - chosenProviderMetric.getEntireProviderLatencyMs(), - /* chosen_provider_final_phase_microseconds */ - chosenProviderMetric.getFinalPhaseLatencyMs(), + chosenProviderMetric.getEntireProviderLatencyMicroseconds(), + /* chosen_provider_final_phase_microseconds (backwards compat only) */ + getMetricTimestampDifferenceMicroseconds(chosenProviderMetric + .getFinalFinishTimeNanoseconds(), + chosenProviderMetric.getUiCallEndTimeNanoseconds()), /* chosen_provider_status */ chosenProviderMetric.getChosenProviderStatus()); } diff --git a/services/credentials/java/com/android/server/credentials/ProviderClearSession.java b/services/credentials/java/com/android/server/credentials/ProviderClearSession.java index ce9fca753a060..941d9ad26dcaf 100644 --- a/services/credentials/java/com/android/server/credentials/ProviderClearSession.java +++ b/services/credentials/java/com/android/server/credentials/ProviderClearSession.java @@ -119,8 +119,8 @@ public final class ProviderClearSession extends ProviderSession implements CredentialManagerUi.CredentialMan //TODO improve design to allow grouped metrics per request protected final String mHybridService; - @NonNull protected RequestSessionStatus mRequestSessionStatus = + @NonNull + protected RequestSessionStatus mRequestSessionStatus = RequestSessionStatus.IN_PROGRESS; /** The status in which a given request session is. */ @@ -213,6 +214,7 @@ abstract class RequestSession implements CredentialManagerUi.CredentialMan /** * Called by RequestSession's upon chosen metric determination. + * * @param componentName the componentName to associate with a provider */ protected void setChosenMetric(ComponentName componentName) { @@ -220,8 +222,8 @@ abstract class RequestSession implements CredentialManagerUi.CredentialMan .mCandidateProviderMetric; mChosenProviderMetric.setChosenUid(metric.getCandidateUid()); mChosenProviderMetric.setFinalFinishTimeNanoseconds(System.nanoTime()); - mChosenProviderMetric.setQueryFinishTimeNanoseconds( - metric.getQueryFinishTimeNanoseconds()); - mChosenProviderMetric.setStartTimeNanoseconds(metric.getStartTimeNanoseconds()); + mChosenProviderMetric.setQueryPhaseLatencyMicroseconds( + metric.getQueryLatencyMicroseconds()); + mChosenProviderMetric.setQueryStartTimeNanoseconds(metric.getStartQueryTimeNanoseconds()); } } diff --git a/services/credentials/java/com/android/server/credentials/metrics/CandidateProviderMetric.java b/services/credentials/java/com/android/server/credentials/metrics/CandidateProviderMetric.java index acfb4a4e3e392..f49995d041aad 100644 --- a/services/credentials/java/com/android/server/credentials/metrics/CandidateProviderMetric.java +++ b/services/credentials/java/com/android/server/credentials/metrics/CandidateProviderMetric.java @@ -18,63 +18,69 @@ package com.android.server.credentials.metrics; /** * The central candidate provider metric object that mimics our defined metric setup. + * TODO(b/270403549) - iterate on this in V3+ */ public class CandidateProviderMetric { + private static final String TAG = "CandidateProviderMetric"; private int mCandidateUid = -1; - private long mStartTimeNanoseconds = -1; + + // Raw timestamp in nanoseconds, will be converted to microseconds for logging + + private long mStartQueryTimeNanoseconds = -1; private long mQueryFinishTimeNanoseconds = -1; private int mProviderQueryStatus = -1; - public CandidateProviderMetric(long startTime, long queryFinishTime, int providerQueryStatus, - int candidateUid) { - this.mStartTimeNanoseconds = startTime; - this.mQueryFinishTimeNanoseconds = queryFinishTime; - this.mProviderQueryStatus = providerQueryStatus; - this.mCandidateUid = candidateUid; + public CandidateProviderMetric() { } - public CandidateProviderMetric(){} + /* ---------- Latencies ---------- */ - public void setStartTimeNanoseconds(long startTimeNanoseconds) { - this.mStartTimeNanoseconds = startTimeNanoseconds; + public void setStartQueryTimeNanoseconds(long startQueryTimeNanoseconds) { + this.mStartQueryTimeNanoseconds = startQueryTimeNanoseconds; } public void setQueryFinishTimeNanoseconds(long queryFinishTimeNanoseconds) { this.mQueryFinishTimeNanoseconds = queryFinishTimeNanoseconds; } - public void setProviderQueryStatus(int providerQueryStatus) { - this.mProviderQueryStatus = providerQueryStatus; - } - - public void setCandidateUid(int candidateUid) { - this.mCandidateUid = candidateUid; - } - - public long getStartTimeNanoseconds() { - return this.mStartTimeNanoseconds; + public long getStartQueryTimeNanoseconds() { + return this.mStartQueryTimeNanoseconds; } public long getQueryFinishTimeNanoseconds() { return this.mQueryFinishTimeNanoseconds; } + /** + * Returns the latency in microseconds for the query phase. + */ + public int getQueryLatencyMicroseconds() { + return (int) ((this.getQueryFinishTimeNanoseconds() + - this.getStartQueryTimeNanoseconds()) / 1000); + } + + // TODO (in direct next dependent CL, so this is transient) - add reference timestamp in micro + // seconds for this too. + + /* ------------- Provider Query Status ------------ */ + + public void setProviderQueryStatus(int providerQueryStatus) { + this.mProviderQueryStatus = providerQueryStatus; + } + public int getProviderQueryStatus() { return this.mProviderQueryStatus; } + /* -------------- Candidate Uid ---------------- */ + + public void setCandidateUid(int candidateUid) { + this.mCandidateUid = candidateUid; + } + public int getCandidateUid() { return this.mCandidateUid; } - - /** - * Returns the latency in microseconds for the query phase. - */ - public int getQueryLatencyMs() { - return (int) ((this.getQueryFinishTimeNanoseconds() - - this.getStartTimeNanoseconds()) / 1000); - } - } diff --git a/services/credentials/java/com/android/server/credentials/metrics/ChosenProviderMetric.java b/services/credentials/java/com/android/server/credentials/metrics/ChosenProviderMetric.java index c4d0b3c7254de..75fdc567013cf 100644 --- a/services/credentials/java/com/android/server/credentials/metrics/ChosenProviderMetric.java +++ b/services/credentials/java/com/android/server/credentials/metrics/ChosenProviderMetric.java @@ -16,18 +16,39 @@ package com.android.server.credentials.metrics; +import android.util.Log; + +import com.android.server.credentials.MetricUtilities; + /** * The central chosen provider metric object that mimics our defined metric setup. + * TODO(b/270403549) - iterate on this in V3+ */ public class ChosenProviderMetric { + // TODO(b/270403549) - applies elsewhere, likely removed or replaced with a count-index (1,2,3) + private static final String TAG = "ChosenProviderMetric"; private int mChosenUid = -1; - private long mStartTimeNanoseconds = -1; - private long mQueryFinishTimeNanoseconds = -1; + + // Latency figures typically fed in from prior CandidateProviderMetric + + private int mPreQueryPhaseLatencyMicroseconds = -1; + private int mQueryPhaseLatencyMicroseconds = -1; + + // Timestamps kept in raw nanoseconds. Expected to be converted to microseconds from using + // reference 'mServiceBeganTimeNanoseconds' during metric log point. + + private long mServiceBeganTimeNanoseconds = -1; + private long mQueryStartTimeNanoseconds = -1; + private long mUiCallStartTimeNanoseconds = -1; + private long mUiCallEndTimeNanoseconds = -1; private long mFinalFinishTimeNanoseconds = -1; private int mChosenProviderStatus = -1; - public ChosenProviderMetric() {} + public ChosenProviderMetric() { + } + + /* ------------------- UID ------------------- */ public int getChosenUid() { return mChosenUid; @@ -37,30 +58,140 @@ public class ChosenProviderMetric { mChosenUid = chosenUid; } - public long getStartTimeNanoseconds() { - return mStartTimeNanoseconds; + /* ---------------- Latencies ------------------ */ + + + /* ----- Direct Latencies ------- */ + + /** + * In order for a chosen provider to be selected, the call must have successfully begun. + * Thus, the {@link PreCandidateMetric} can directly pass this initial latency figure into + * this chosen provider metric. + * + * @param preQueryPhaseLatencyMicroseconds the millisecond latency for the service start, + * typically passed in through the + * {@link PreCandidateMetric} + */ + public void setPreQueryPhaseLatencyMicroseconds(int preQueryPhaseLatencyMicroseconds) { + mPreQueryPhaseLatencyMicroseconds = preQueryPhaseLatencyMicroseconds; } - public void setStartTimeNanoseconds(long startTimeNanoseconds) { - mStartTimeNanoseconds = startTimeNanoseconds; + /** + * In order for a chosen provider to be selected, a candidate provider must exist. The + * candidate provider can directly pass the final latency figure into this chosen provider + * metric. + * + * @param queryPhaseLatencyMicroseconds the millisecond latency for the query phase, typically + * passed in through the {@link CandidateProviderMetric} + */ + public void setQueryPhaseLatencyMicroseconds(int queryPhaseLatencyMicroseconds) { + mQueryPhaseLatencyMicroseconds = queryPhaseLatencyMicroseconds; } - public long getQueryFinishTimeNanoseconds() { - return mQueryFinishTimeNanoseconds; + public int getPreQueryPhaseLatencyMicroseconds() { + return mPreQueryPhaseLatencyMicroseconds; } - public void setQueryFinishTimeNanoseconds(long queryFinishTimeNanoseconds) { - mQueryFinishTimeNanoseconds = queryFinishTimeNanoseconds; + public int getQueryPhaseLatencyMicroseconds() { + return mQueryPhaseLatencyMicroseconds; + } + + public int getUiPhaseLatencyMicroseconds() { + return (int) ((this.mUiCallEndTimeNanoseconds + - this.mUiCallStartTimeNanoseconds) / 1000); + } + + /** + * Returns the full provider (invocation to response) latency in microseconds. Expects the + * start time to be provided, such as from {@link CandidateProviderMetric}. + */ + public int getEntireProviderLatencyMicroseconds() { + return (int) ((this.mFinalFinishTimeNanoseconds + - this.mQueryStartTimeNanoseconds) / 1000); + } + + /** + * Returns the full (platform invoked to response) latency in microseconds. Expects the + * start time to be provided, such as from {@link PreCandidateMetric}. + */ + public int getEntireLatencyMicroseconds() { + return (int) ((this.mFinalFinishTimeNanoseconds + - this.mServiceBeganTimeNanoseconds) / 1000); + } + + /* ----- Timestamps for Latency ----- */ + + /** + * In order for a chosen provider to be selected, the call must have successfully begun. + * Thus, the {@link PreCandidateMetric} can directly pass this initial timestamp into this + * chosen provider metric. + * + * @param serviceBeganTimeNanoseconds the timestamp moment when the platform was called, + * typically passed in through the {@link PreCandidateMetric} + */ + public void setServiceBeganTimeNanoseconds(long serviceBeganTimeNanoseconds) { + mServiceBeganTimeNanoseconds = serviceBeganTimeNanoseconds; + } + + public void setQueryStartTimeNanoseconds(long queryStartTimeNanoseconds) { + mQueryStartTimeNanoseconds = queryStartTimeNanoseconds; + } + + public void setUiCallStartTimeNanoseconds(long uiCallStartTimeNanoseconds) { + this.mUiCallStartTimeNanoseconds = uiCallStartTimeNanoseconds; + } + + public void setUiCallEndTimeNanoseconds(long uiCallEndTimeNanoseconds) { + this.mUiCallEndTimeNanoseconds = uiCallEndTimeNanoseconds; + } + + public void setFinalFinishTimeNanoseconds(long finalFinishTimeNanoseconds) { + mFinalFinishTimeNanoseconds = finalFinishTimeNanoseconds; + } + + public long getServiceBeganTimeNanoseconds() { + return mServiceBeganTimeNanoseconds; + } + + public long getQueryStartTimeNanoseconds() { + return mQueryStartTimeNanoseconds; + } + + public long getUiCallStartTimeNanoseconds() { + return mUiCallStartTimeNanoseconds; + } + + public long getUiCallEndTimeNanoseconds() { + return mUiCallEndTimeNanoseconds; } public long getFinalFinishTimeNanoseconds() { return mFinalFinishTimeNanoseconds; } - public void setFinalFinishTimeNanoseconds(long finalFinishTimeNanoseconds) { - mFinalFinishTimeNanoseconds = finalFinishTimeNanoseconds; + /* --- Time Stamp Conversion to Microseconds --- */ + + /** + * We collect raw timestamps in nanoseconds for ease of collection. However, given the scope + * of our logging timeframe, and size considerations of the metric, we require these to give us + * the microsecond timestamps from the start reference point. + * + * @param specificTimestamp the timestamp to consider, must be greater than the reference + * @return the microsecond integer timestamp from service start to query began + */ + public int getTimestampFromReferenceStartMicroseconds(long specificTimestamp) { + if (specificTimestamp < this.mServiceBeganTimeNanoseconds) { + Log.i(TAG, "The timestamp is before service started, falling back to default int"); + return MetricUtilities.DEFAULT_INT_32; + } + return (int) ((specificTimestamp + - this.mServiceBeganTimeNanoseconds) / 1000); } + + + /* ----------- Provider Status -------------- */ + public int getChosenProviderStatus() { return mChosenProviderStatus; } @@ -68,23 +199,4 @@ public class ChosenProviderMetric { public void setChosenProviderStatus(int chosenProviderStatus) { mChosenProviderStatus = chosenProviderStatus; } - - /** - * Returns the full provider (invocation to response) latency in microseconds. - */ - public int getEntireProviderLatencyMs() { - return (int) ((this.getFinalFinishTimeNanoseconds() - - this.getStartTimeNanoseconds()) / 1000); - } - - // TODO get post click final phase and re-add the query phase time to metric - - /** - * Returns the end of query to response phase latency in microseconds. - */ - public int getFinalPhaseLatencyMs() { - return (int) ((this.getFinalFinishTimeNanoseconds() - - this.getQueryFinishTimeNanoseconds()) / 1000); - } - } diff --git a/services/credentials/java/com/android/server/credentials/metrics/PreCandidateMetric.java b/services/credentials/java/com/android/server/credentials/metrics/PreCandidateMetric.java new file mode 100644 index 0000000000000..952328f6ba3ae --- /dev/null +++ b/services/credentials/java/com/android/server/credentials/metrics/PreCandidateMetric.java @@ -0,0 +1,65 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.credentials.metrics; + +/** + * This handles metrics collected prior to any remote calls to providers. + * TODO(b/270403549) - iterate on this in V3+ + */ +public class PreCandidateMetric { + + private static final String TAG = "PreCandidateMetric"; + + // Raw timestamps in nanoseconds, *the only* one logged as such (i.e. 64 bits) since it is a + // reference point. + + private long mCredentialServiceStartedTimeNanoseconds = -1; + private long mCredentialServiceBeginQueryTimeNanoseconds = -1; + + public PreCandidateMetric() { + } + + /* ---------- Latencies ---------- */ + + /* -- Direct Latencies -- */ + + public int getServiceStartToQueryLatencyMicroseconds() { + return (int) ((this.mCredentialServiceStartedTimeNanoseconds + - this.mCredentialServiceBeginQueryTimeNanoseconds) / 1000); + } + + /* -- Timestamps -- */ + + public void setCredentialServiceStartedTimeNanoseconds( + long credentialServiceStartedTimeNanoseconds + ) { + this.mCredentialServiceStartedTimeNanoseconds = credentialServiceStartedTimeNanoseconds; + } + + public void setCredentialServiceBeginQueryTimeNanoseconds( + long credentialServiceBeginQueryTimeNanoseconds) { + mCredentialServiceBeginQueryTimeNanoseconds = credentialServiceBeginQueryTimeNanoseconds; + } + + public long getCredentialServiceStartedTimeNanoseconds() { + return mCredentialServiceStartedTimeNanoseconds; + } + + public long getCredentialServiceBeginQueryTimeNanoseconds() { + return mCredentialServiceBeginQueryTimeNanoseconds; + } +}