From b349b59f7a8c82ff6dca25efa8146c3094e5e48e Mon Sep 17 00:00:00 2001 From: Arpan Kaphle Date: Wed, 1 Mar 2023 23:33:57 +0000 Subject: [PATCH] Further V2 Modifications, Prep for V3 This adds to our Metric Objects the ability to handle new V2 changes, and prepares for V3. There will be significant changes to come, but this is a first step that addresses our immediate TODOs, particularily to properly split up the latencies of the Metric objects on top of the previously checked in isEnabled additions and the cancellation changes. Bug: 270403549 Bug: 269290341 Test: Will be chained in the future Change-Id: Ia77ef7fe854a2b41ef2bc85a07f3852df1984bbf --- .../server/credentials/MetricUtilities.java | 29 ++- .../credentials/ProviderClearSession.java | 2 +- .../credentials/ProviderCreateSession.java | 2 +- .../credentials/ProviderGetSession.java | 2 +- .../server/credentials/RequestSession.java | 10 +- .../metrics/CandidateProviderMetric.java | 64 ++++--- .../metrics/ChosenProviderMetric.java | 176 ++++++++++++++---- .../metrics/PreCandidateMetric.java | 65 +++++++ 8 files changed, 276 insertions(+), 74 deletions(-) create mode 100644 services/credentials/java/com/android/server/credentials/metrics/PreCandidateMetric.java 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; + } +}