From 1452bc759a3f3fa6941a5d52bd19b01a3ba5d636 Mon Sep 17 00:00:00 2001 From: Lee Shombert Date: Mon, 26 Sep 2022 09:37:24 -0700 Subject: [PATCH] Log resource api times to statsd Bug: 246953799 Log resource api times to statsd. Two APIs are logged: getResourceValue() and retrieveAttributes(). Other APIs may be timed by the runtime layer but these are not logged. This fixes a bug in ResourceTimer.startTimer() that caused the class to skip the first repeated publication point. This change renames the two RecourceTimer instances in android_util_AssetManager.cpp to "_timer" to be more explicit and to avoid the use of the more generic "_tag". Test: manual Change-Id: I0c5e0906f79ff35db1e34593275b39fb7f2f179b --- .../android/content/res/ResourceTimer.java | 42 +++++++++++++++++-- core/jni/android_util_AssetManager.cpp | 4 +- 2 files changed, 40 insertions(+), 6 deletions(-) diff --git a/core/java/android/content/res/ResourceTimer.java b/core/java/android/content/res/ResourceTimer.java index 13f0b72b88750..d51f64ce81066 100644 --- a/core/java/android/content/res/ResourceTimer.java +++ b/core/java/android/content/res/ResourceTimer.java @@ -19,6 +19,7 @@ package android.content.res; import android.annotation.NonNull; import android.annotation.Nullable; +import android.app.AppProtoEnums; import android.os.Handler; import android.os.Looper; import android.os.Message; @@ -30,6 +31,7 @@ import android.util.Log; import com.android.internal.annotations.GuardedBy; import com.android.internal.util.FastPrintWriter; +import com.android.internal.util.FrameworkStatsLog; import java.io.FileOutputStream; import java.io.PrintWriter; @@ -110,6 +112,14 @@ public final class ResourceTimer { @GuardedBy("sLock") private static Config sConfig; + /** + * This array contains the statsd enum associated with each timer entry. A value of NONE (0) + * means that the entry should not be logged to statsd. (This would be the case for timers + * that are created for temporary debugging.) + */ + @GuardedBy("sLock") + private static int[] sApiMap; + /** * A singleton Summary object that is refilled from the native side. The length of the array * is the number of timers that can be fetched. nativeGetTimers() will fill the array to the @@ -165,6 +175,19 @@ public final class ResourceTimer { sTimers[i].percentile = new int[sConfig.maxBuckets]; sTimers[i].largest = new int[sConfig.maxLargest]; } + // Map the values returned from the runtime to statsd enumerals The runtime may + // return timers that are not meant to be logged via statsd. Such timers are mapped + // to RESOURCE_API_NONE. + sApiMap = new int[sConfig.maxTimer]; + for (int i = 0; i < sApiMap.length; i++) { + if (sConfig.timers[i].equals("GetResourceValue")) { + sApiMap[i] = AppProtoEnums.RESOURCE_API_GET_VALUE; + } else if (sConfig.timers[i].equals("RetrieveAttributes")) { + sApiMap[i] = AppProtoEnums.RESOURCE_API_RETRIEVE_ATTRIBUTES; + } else { + sApiMap[i] = AppProtoEnums.RESOURCE_API_NONE; + } + } sCurrentPoint = 0; startTimer(); @@ -194,7 +217,9 @@ public final class ResourceTimer { delay = sPublicationPoints[sCurrentPoint]; } else { // Repeat with the final publication point. - delay = sCurrentPoint * sPublicationPoints[sPublicationPoints.length - 1]; + final long repeated = sPublicationPoints[sPublicationPoints.length - 1]; + final int prelude = sPublicationPoints.length - 1; + delay = (sCurrentPoint - prelude) * repeated; } // Convert minutes to milliseconds. delay *= 60 * 1000; @@ -223,10 +248,19 @@ public final class ResourceTimer { update(true); // Log the number of records read. This happens a few times a day. for (int i = 0; i < sTimers.length; i++) { - if (sTimers[i].count > 0) { + var timer = sTimers[i]; + if (timer.count > 0) { Log.i(TAG, TextUtils.formatSimple("%s count=%d pvalues=%s", - sConfig.timers[i], sTimers[i].count, - packedString(sTimers[i].percentile))); + sConfig.timers[i], timer.count, packedString(timer.percentile))); + if (sApiMap[i] != AppProtoEnums.RESOURCE_API_NONE) { + FrameworkStatsLog.write(FrameworkStatsLog.RESOURCE_API_INFO, + sApiMap[i], + timer.count, timer.total, + timer.percentile[0], timer.percentile[1], + timer.percentile[2], timer.percentile[3], + timer.largest[0], timer.largest[1], timer.largest[2], + timer.largest[3], timer.largest[4]); + } } } sCurrentPoint++; diff --git a/core/jni/android_util_AssetManager.cpp b/core/jni/android_util_AssetManager.cpp index b5a78b0fc46b3..b60ec9f493c22 100644 --- a/core/jni/android_util_AssetManager.cpp +++ b/core/jni/android_util_AssetManager.cpp @@ -631,7 +631,7 @@ static jint NativeGetResourceValue(JNIEnv* env, jclass /*clazz*/, jlong ptr, jin jshort density, jobject typed_value, jboolean resolve_references) { ScopedLock assetmanager(AssetManagerFromLong(ptr)); - ResourceTimer _tag(ResourceTimer::Counter::GetResourceValue); + ResourceTimer _timer(ResourceTimer::Counter::GetResourceValue); auto value = assetmanager->GetResource(static_cast(resid), false /*may_be_bag*/, static_cast(density)); if (!value.has_value()) { @@ -1234,7 +1234,7 @@ static jboolean NativeRetrieveAttributes(JNIEnv* env, jclass /*clazz*/, jlong pt } ScopedLock assetmanager(AssetManagerFromLong(ptr)); - ResourceTimer _tag(ResourceTimer::Counter::RetrieveAttributes); + ResourceTimer _timer(ResourceTimer::Counter::RetrieveAttributes); ResXMLParser* xml_parser = reinterpret_cast(xml_parser_ptr); auto result = RetrieveAttributes(assetmanager.get(), xml_parser, reinterpret_cast(attrs),