Merge "Record resource access times"
diff --git a/core/java/android/content/res/ResourceTimer.java b/core/java/android/content/res/ResourceTimer.java
new file mode 100644
index 0000000..13f0b72
--- /dev/null
+++ b/core/java/android/content/res/ResourceTimer.java
@@ -0,0 +1,289 @@
+/*
+ * Copyright (C) 2022 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 android.content.res;
+
+import android.annotation.NonNull;
+import android.annotation.Nullable;
+
+import android.os.Handler;
+import android.os.Looper;
+import android.os.Message;
+import android.os.ParcelFileDescriptor;
+import android.os.Process;
+import android.os.SystemClock;
+import android.text.TextUtils;
+import android.util.Log;
+
+import com.android.internal.annotations.GuardedBy;
+import com.android.internal.util.FastPrintWriter;
+
+import java.io.FileOutputStream;
+import java.io.PrintWriter;
+import java.util.Arrays;
+
+/**
+ * Provides access to the resource timers without intruding on other classes.
+ * @hide
+ */
+public final class ResourceTimer {
+ private static final String TAG = "ResourceTimer";
+
+ // Enable metrics in this process. The flag may be set false in some processes. The flag is
+ // never set true at runtime, so setting it false here disables the feature entirely.
+ private static boolean sEnabled = true;
+
+ // Set true for incremental metrics (the counters are reset after every fetch). Set false for
+ // cumulative metrics (the counters are never reset and accumulate values for the lifetime of
+ // the process).
+ private static boolean sIncrementalMetrics = true;
+
+ // Set true to enable some debug behavior.
+ private static boolean ENABLE_DEBUG = false;
+
+ // The global lock.
+ private static final Object sLock = new Object();
+
+ // The singleton cache manager
+ private static ResourceTimer sManager;
+
+ // The handler for the timeouts.
+ private static Handler mHandler;
+
+ // The time at which the process started.
+ private final static long sProcessStart = SystemClock.uptimeMillis();
+
+ // Metrics are published at offsets from the process start. Processes publish at five minutes
+ // and one hour. Thereafter, metrics are published every 12 hours. The values in this array
+ // are in units of minutes.
+ private static final long[] sPublicationPoints = new long[]{ 5, 60, 60 * 12 };
+
+ // The index of the latest publication point.
+ private static int sCurrentPoint;
+
+ /**
+ * The runtime timer configuration.
+ */
+ private static class Config {
+ // The number of timers in the runtime
+ int maxTimer;
+ // The number of histogram buckets per timer.
+ int maxBuckets;
+ // The number of "largest" values per timer.
+ int maxLargest;
+ // A string label for each timer. This array has maxTimer elements.
+ String[] timers;
+ }
+
+ /**
+ * The timer information that is pulled from the native runtime. All times have units of ns.
+ */
+ private static class Timer {
+ int count;
+ long total;
+ int mintime;
+ int maxtime;
+ int[] largest;
+ int[] percentile;
+ @Override
+ public String toString() {
+ return TextUtils.formatSimple("%d:%d:%d:%d", count, total, mintime, maxtime);
+ }
+ }
+
+ /**
+ * A singleton Config. This is initialized when the timers are started.
+ */
+ @GuardedBy("sLock")
+ private static Config sConfig;
+
+ /**
+ * 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
+ * smaller of the length of the array or the actual number of timers in the runtime. The
+ * actual number of timers in the run time is returned by the function.
+ */
+ @GuardedBy("sLock")
+ private static Timer[] sTimers;
+
+ /**
+ * The time at which the local timer array was last updated. This has the same units as
+ * sProcessStart; the difference is the process run time.
+ */
+ @GuardedBy("sLock")
+ private static long sLastUpdated = 0;
+
+ // The constructor is private. Use the factory to get a hold of the manager.
+ private ResourceTimer() {
+ throw new RuntimeException("ResourceTimer constructor");
+ }
+
+ /**
+ * Start the manager. This runs a periodic job that collects and publishes timer values.
+ * This is not part of the constructor only because the looper failicities might not be
+ * available at the beginning of time.
+ */
+ public static void start() {
+ synchronized (sLock) {
+ if (!sEnabled) {
+ return;
+ }
+ if (mHandler != null) {
+ // Nothing to be done. The job has already been started.
+ return;
+ }
+ if (Looper.getMainLooper() == null) {
+ throw new RuntimeException("ResourceTimer started too early");
+ }
+ mHandler = new Handler(Looper.getMainLooper()) {
+ @Override
+ public void handleMessage(Message msg) {
+ ResourceTimer.handleMessage(msg);
+ }
+ };
+
+ // Initialize the container that holds information from the native runtime. The
+ // container is built according to the dimensions returned by the native layer.
+ sConfig = new Config();
+ nativeEnableTimers(sConfig);
+ sTimers = new Timer[sConfig.maxTimer];
+ for (int i = 0; i < sTimers.length; i++) {
+ sTimers[i] = new Timer();
+ sTimers[i].percentile = new int[sConfig.maxBuckets];
+ sTimers[i].largest = new int[sConfig.maxLargest];
+ }
+
+ sCurrentPoint = 0;
+ startTimer();
+ }
+ }
+
+ /**
+ * Handle a refresh message. Publish the metrics and start a timer for the next publication.
+ * The message parameter is unused.
+ */
+ private static void handleMessage(Message msg) {
+ synchronized (sLock) {
+ publish();
+ startTimer();
+ }
+ }
+
+ /**
+ * Start a timer to the next publication point. Publication points are referenced from
+ * process start.
+ */
+ @GuardedBy("sLock")
+ private static void startTimer() {
+ // The delay is in minutes.
+ long delay;
+ if (sCurrentPoint < sPublicationPoints.length) {
+ delay = sPublicationPoints[sCurrentPoint];
+ } else {
+ // Repeat with the final publication point.
+ delay = sCurrentPoint * sPublicationPoints[sPublicationPoints.length - 1];
+ }
+ // Convert minutes to milliseconds.
+ delay *= 60 * 1000;
+ // If debug is enabled, convert hours down to minutes.
+ if (ENABLE_DEBUG) {
+ delay /= 60;
+ }
+ mHandler.sendEmptyMessageAtTime(0, sProcessStart + delay);
+ }
+
+ /**
+ * Update the local copy of the timers. The current time is saved as well.
+ */
+ @GuardedBy("sLock")
+ private static void update(boolean reset) {
+ nativeGetTimers(sTimers, reset);
+ sLastUpdated = SystemClock.uptimeMillis();
+ }
+
+ /**
+ * Retrieve the accumulated timer information, reset the native counters, and advance the
+ * publication point.
+ */
+ @GuardedBy("sLock")
+ private static void publish() {
+ 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) {
+ Log.i(TAG, TextUtils.formatSimple("%s count=%d pvalues=%s",
+ sConfig.timers[i], sTimers[i].count,
+ packedString(sTimers[i].percentile)));
+ }
+ }
+ sCurrentPoint++;
+ }
+
+ /**
+ * Given an int[], return a string that is formatted as "a,b,c" with no spaces.
+ */
+ private static String packedString(int[] a) {
+ return Arrays.toString(a).replaceAll("[\\]\\[ ]", "");
+ }
+
+ /**
+ * Update the metrics information and dump it.
+ * @hide
+ */
+ public static void dumpTimers(@NonNull ParcelFileDescriptor pfd, @Nullable String[] args) {
+ FileOutputStream fout = new FileOutputStream(pfd.getFileDescriptor());
+ PrintWriter pw = new FastPrintWriter(fout);
+ synchronized (sLock) {
+ if (!sEnabled || (sConfig == null)) {
+ pw.println(" Timers are not enabled in this process");
+ pw.flush();
+ return;
+ }
+ }
+
+ // Look for the --refresh switch. If the switch is present, then sTimers is updated.
+ // Otherwise, the current value of sTimers is displayed.
+ boolean refresh = Arrays.asList(args).contains("-refresh");
+
+ synchronized (sLock) {
+ update(refresh);
+ long runtime = sLastUpdated - sProcessStart;
+ pw.format(" config runtime=%d proc=%s\n", runtime, Process.myProcessName());
+ for (int i = 0; i < sTimers.length; i++) {
+ Timer t = sTimers[i];
+ if (t.count != 0) {
+ String name = sConfig.timers[i];
+ pw.format(" stats timer=%s cnt=%d avg=%d min=%d max=%d pval=%s "
+ + "largest=%s\n",
+ name, t.count, t.total / t.count, t.mintime, t.maxtime,
+ packedString(t.percentile),
+ packedString(t.largest));
+ }
+ }
+ }
+ pw.flush();
+ }
+
+ // Enable (or disabled) the runtime timers. Note that timers are disabled by default. This
+ // retrieves the runtime timer configuration that are taking effect
+ private static native int nativeEnableTimers(@NonNull Config config);
+
+ // Retrieve the timers from the native layer. If reset is true, the timers are reset after
+ // being fetched. The method returns the number of timers that are defined in the runtime
+ // layer. The stats array is filled out to the smaller of its actual size and the number of
+ // runtime timers; it never overflows.
+ private static native int nativeGetTimers(@NonNull Timer[] stats, boolean reset);
+}
diff --git a/core/jni/Android.bp b/core/jni/Android.bp
index 26d0be1..d59a51a 100644
--- a/core/jni/Android.bp
+++ b/core/jni/Android.bp
@@ -209,6 +209,7 @@
"android_content_res_ApkAssets.cpp",
"android_content_res_ObbScanner.cpp",
"android_content_res_Configuration.cpp",
+ "android_content_res_ResourceTimer.cpp",
"android_security_Scrypt.cpp",
"com_android_internal_content_om_OverlayConfig.cpp",
"com_android_internal_net_NetworkUtilsInternal.cpp",
diff --git a/core/jni/AndroidRuntime.cpp b/core/jni/AndroidRuntime.cpp
index 11cb64c..68db603 100644
--- a/core/jni/AndroidRuntime.cpp
+++ b/core/jni/AndroidRuntime.cpp
@@ -117,6 +117,7 @@
extern int register_android_content_StringBlock(JNIEnv* env);
extern int register_android_content_XmlBlock(JNIEnv* env);
extern int register_android_content_res_ApkAssets(JNIEnv* env);
+extern int register_android_content_res_ResourceTimer(JNIEnv* env);
extern int register_android_graphics_BLASTBufferQueue(JNIEnv* env);
extern int register_android_graphics_SurfaceTexture(JNIEnv* env);
extern int register_android_view_DisplayEventReceiver(JNIEnv* env);
@@ -1506,6 +1507,7 @@
REG_JNI(register_android_content_StringBlock),
REG_JNI(register_android_content_XmlBlock),
REG_JNI(register_android_content_res_ApkAssets),
+ REG_JNI(register_android_content_res_ResourceTimer),
REG_JNI(register_android_text_AndroidCharacter),
REG_JNI(register_android_text_Hyphenator),
REG_JNI(register_android_view_InputDevice),
diff --git a/core/jni/android_content_res_ResourceTimer.cpp b/core/jni/android_content_res_ResourceTimer.cpp
new file mode 100644
index 0000000..91e3c921
--- /dev/null
+++ b/core/jni/android_content_res_ResourceTimer.cpp
@@ -0,0 +1,129 @@
+/*
+ * Copyright 2022, 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.
+ */
+
+#include <jni.h>
+#include <core_jni_helpers.h>
+#include <utils/misc.h>
+#include <androidfw/ResourceTimer.h>
+
+namespace android {
+
+// ----------------------------------------------------------------------------
+
+static struct {
+ jfieldID maxTimer;
+ jfieldID maxBuckets;
+ jfieldID maxLargest;
+ jfieldID timers;
+} gConfigOffsets;
+
+static struct {
+ jfieldID count;
+ jfieldID total;
+ jfieldID mintime;
+ jfieldID maxtime;
+ jfieldID largest;
+ jfieldID percentile;
+} gTimerOffsets;
+
+// ----------------------------------------------------------------------------
+
+
+static int NativeGetTimers(JNIEnv* env, jobject /*clazz*/, jobjectArray timer, jboolean reset) {
+ size_t size = ResourceTimer::counterSize;
+ if (jsize st = env->GetArrayLength(timer); st < size) {
+ // Shrink the size to the minimum of the available counters and the available space.
+ size = st;
+ }
+ for (size_t i = 0; i < size; i++) {
+ ResourceTimer::Timer src;
+ ResourceTimer::copy(i, src, reset);
+ jobject dst = env->GetObjectArrayElement(timer, i);
+ env->SetIntField(dst, gTimerOffsets.count, src.count);
+ if (src.count == 0) {
+ continue;
+ }
+
+ src.compute();
+ env->SetIntField(dst, gTimerOffsets.count, src.count);
+ env->SetLongField(dst, gTimerOffsets.total, src.total);
+ env->SetIntField(dst, gTimerOffsets.mintime, src.mintime);
+ env->SetIntField(dst, gTimerOffsets.maxtime, src.maxtime);
+ jintArray percentile =
+ reinterpret_cast<jintArray>(env->GetObjectField(dst, gTimerOffsets.percentile));
+ env->SetIntArrayRegion(percentile, 0, 1, &src.pvalues.p50.nominal);
+ env->SetIntArrayRegion(percentile, 1, 1, &src.pvalues.p90.nominal);
+ env->SetIntArrayRegion(percentile, 2, 1, &src.pvalues.p95.nominal);
+ env->SetIntArrayRegion(percentile, 3, 1, &src.pvalues.p99.nominal);
+ jintArray largest =
+ reinterpret_cast<jintArray>(env->GetObjectField(dst, gTimerOffsets.largest));
+ env->SetIntArrayRegion(largest, 0, ResourceTimer::Timer::MaxLargest, src.largest);
+ }
+ return size;
+}
+
+static jstring counterName(JNIEnv *env, int counter) {
+ char const *s = ResourceTimer::toString(static_cast<ResourceTimer::Counter>(counter));
+ return env->NewStringUTF(s);
+}
+
+static int NativeEnableTimers(JNIEnv* env, jobject /*clazz*/, jobject config) {
+ ResourceTimer::enable();
+
+ env->SetIntField(config, gConfigOffsets.maxTimer, ResourceTimer::counterSize);
+ env->SetIntField(config, gConfigOffsets.maxBuckets, 4); // Number of ints in PValues
+ env->SetIntField(config, gConfigOffsets.maxLargest, ResourceTimer::Timer::MaxLargest);
+
+ jclass str = env->FindClass("java/lang/String");
+ jstring empty = counterName(env, 0);
+ jobjectArray timers = env->NewObjectArray(ResourceTimer::counterSize, str, empty);
+ for (int i = 0; i < ResourceTimer::counterSize; i++) {
+ env->SetObjectArrayElement(timers, i, counterName(env, i));
+ }
+ env->SetObjectField(config, gConfigOffsets.timers, timers);
+ return 0;
+}
+
+// ----------------------------------------------------------------------------
+
+// JNI registration.
+static const JNINativeMethod gResourceTimerMethods[] = {
+ {"nativeEnableTimers", "(Landroid/content/res/ResourceTimer$Config;)I",
+ (void *) NativeEnableTimers},
+ {"nativeGetTimers", "([Landroid/content/res/ResourceTimer$Timer;Z)I",
+ (void *) NativeGetTimers},
+};
+
+int register_android_content_res_ResourceTimer(JNIEnv* env) {
+ jclass config = FindClassOrDie(env, "android/content/res/ResourceTimer$Config");
+ gConfigOffsets.maxTimer = GetFieldIDOrDie(env, config, "maxTimer", "I");
+ gConfigOffsets.maxBuckets = GetFieldIDOrDie(env, config, "maxBuckets", "I");
+ gConfigOffsets.maxLargest = GetFieldIDOrDie(env, config, "maxLargest", "I");
+ gConfigOffsets.timers = GetFieldIDOrDie(env, config, "timers", "[Ljava/lang/String;");
+
+ jclass timers = FindClassOrDie(env, "android/content/res/ResourceTimer$Timer");
+ gTimerOffsets.count = GetFieldIDOrDie(env, timers, "count", "I");
+ gTimerOffsets.total = GetFieldIDOrDie(env, timers, "total", "J");
+ gTimerOffsets.mintime = GetFieldIDOrDie(env, timers, "mintime", "I");
+ gTimerOffsets.maxtime = GetFieldIDOrDie(env, timers, "maxtime", "I");
+ gTimerOffsets.largest = GetFieldIDOrDie(env, timers, "largest", "[I");
+ gTimerOffsets.percentile = GetFieldIDOrDie(env, timers, "percentile", "[I");
+
+ return RegisterMethodsOrDie(env, "android/content/res/ResourceTimer", gResourceTimerMethods,
+ NELEM(gResourceTimerMethods));
+}
+
+}; // namespace android
diff --git a/libs/androidfw/Android.bp b/libs/androidfw/Android.bp
index 779c4b7..eb8d26a 100644
--- a/libs/androidfw/Android.bp
+++ b/libs/androidfw/Android.bp
@@ -71,6 +71,7 @@
"misc.cpp",
"ObbFile.cpp",
"PosixUtils.cpp",
+ "ResourceTimer.cpp",
"ResourceTypes.cpp",
"ResourceUtils.cpp",
"StreamingZipInflater.cpp",
@@ -173,6 +174,7 @@
"tests/Idmap_test.cpp",
"tests/LoadedArsc_test.cpp",
"tests/Locale_test.cpp",
+ "tests/ResourceTimer_test.cpp",
"tests/ResourceUtils_test.cpp",
"tests/ResTable_test.cpp",
"tests/Split_test.cpp",
diff --git a/libs/androidfw/ResourceTimer.cpp b/libs/androidfw/ResourceTimer.cpp
new file mode 100644
index 0000000..44128d9
--- /dev/null
+++ b/libs/androidfw/ResourceTimer.cpp
@@ -0,0 +1,271 @@
+/*
+ * Copyright (C) 2022 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.
+ */
+
+#include <unistd.h>
+#include <string.h>
+
+#include <map>
+#include <atomic>
+
+#include <utils/Log.h>
+#include <androidfw/ResourceTimer.h>
+
+// The following block allows compilation on windows, which does not have getuid().
+#ifdef _WIN32
+#ifdef ERROR
+#undef ERROR
+#endif
+#define getuid() (getUidWindows_)
+#endif
+
+namespace android {
+
+namespace {
+
+#ifdef _WIN32
+// A temporary to confuse lint into thinking that getuid() on windows might return something other
+// than zero.
+int getUidWindows_ = 0;
+#endif
+
+// The number of nanoseconds in a microsecond.
+static const unsigned int US = 1000;
+// The number of nanoseconds in a second.
+static const unsigned int S = 1000 * 1000 * 1000;
+
+// Return the difference between two timespec values. The difference is in nanoseconds. If the
+// return value would exceed 2s (2^31 nanoseconds) then UINT_MAX is returned.
+unsigned int diffInNs(timespec const &a, timespec const &b) {
+ timespec r = { 0, 0 };
+ r.tv_nsec = a.tv_nsec - b.tv_nsec;
+ if (r.tv_nsec < 0) {
+ r.tv_sec = -1;
+ r.tv_nsec += S;
+ }
+ r.tv_sec = r.tv_sec + (a.tv_sec - b.tv_sec);
+ if (r.tv_sec > 2) return UINT_MAX;
+ unsigned int result = (r.tv_sec * S) + r.tv_nsec;
+ if (result > 2 * S) return UINT_MAX;
+ return result;
+}
+
+}
+
+ResourceTimer::ResourceTimer(Counter api)
+ : active_(enabled_.load()),
+ api_(api) {
+ if (active_) {
+ clock_gettime(CLOCK_MONOTONIC, &start_);
+ }
+}
+
+ResourceTimer::~ResourceTimer() {
+ record();
+}
+
+void ResourceTimer::enable() {
+ if (!enabled_.load()) counter_ = new GuardedTimer[ResourceTimer::counterSize];
+ enabled_.store(true);
+}
+
+void ResourceTimer::cancel() {
+ active_ = false;
+}
+
+void ResourceTimer::record() {
+ if (!active_) return;
+
+ struct timespec end;
+ clock_gettime(CLOCK_MONOTONIC, &end);
+ // Get the difference in microseconds.
+ const unsigned int ticks = diffInNs(end, start_);
+ ScopedTimer t(counter_[toIndex(api_)]);
+ t->record(ticks);
+ active_ = false;
+}
+
+bool ResourceTimer::copy(int counter, Timer &dst, bool reset) {
+ ScopedTimer t(counter_[counter]);
+ if (t->count == 0) {
+ dst.reset();
+ if (reset) t->reset();
+ return false;
+ }
+ Timer::copy(dst, *t, reset);
+ return true;
+}
+
+void ResourceTimer::reset() {
+ for (int i = 0; i < counterSize; i++) {
+ ScopedTimer t(counter_[i]);
+ t->reset();
+ }
+}
+
+ResourceTimer::Timer::Timer() {
+ // Ensure newly-created objects are zeroed.
+ memset(buckets, 0, sizeof(buckets));
+ reset();
+}
+
+ResourceTimer::Timer::~Timer() {
+ for (int d = 0; d < MaxDimension; d++) {
+ delete[] buckets[d];
+ }
+}
+
+void ResourceTimer::Timer::freeBuckets() {
+ for (int d = 0; d < MaxDimension; d++) {
+ delete[] buckets[d];
+ buckets[d] = 0;
+ }
+}
+
+void ResourceTimer::Timer::reset() {
+ count = total = mintime = maxtime = 0;
+ memset(largest, 0, sizeof(largest));
+ memset(&pvalues, 0, sizeof(pvalues));
+ // Zero the histogram, keeping any allocated dimensions.
+ for (int d = 0; d < MaxDimension; d++) {
+ if (buckets[d] != 0) memset(buckets[d], 0, sizeof(int) * MaxBuckets);
+ }
+}
+
+void ResourceTimer::Timer::copy(Timer &dst, Timer &src, bool reset) {
+ dst.freeBuckets();
+ dst = src;
+ // Clean up the histograms.
+ if (reset) {
+ // Do NOT free the src buckets because they being used by dst.
+ memset(src.buckets, 0, sizeof(src.buckets));
+ src.reset();
+ } else {
+ for (int d = 0; d < MaxDimension; d++) {
+ if (src.buckets[d] != nullptr) {
+ dst.buckets[d] = new int[MaxBuckets];
+ memcpy(dst.buckets[d], src.buckets[d], sizeof(int) * MaxBuckets);
+ }
+ }
+ }
+}
+
+void ResourceTimer::Timer::record(int ticks) {
+ // Record that the event happened.
+ count++;
+
+ total += ticks;
+ if (mintime == 0 || ticks < mintime) mintime = ticks;
+ if (ticks > maxtime) maxtime = ticks;
+
+ // Do not add oversized events to the histogram.
+ if (ticks != UINT_MAX) {
+ for (int d = 0; d < MaxDimension; d++) {
+ if (ticks < range[d]) {
+ if (buckets[d] == 0) {
+ buckets[d] = new int[MaxBuckets];
+ memset(buckets[d], 0, sizeof(int) * MaxBuckets);
+ }
+ if (ticks < width[d]) {
+ // Special case: never write to bucket 0 because it complicates the percentile logic.
+ // However, this is always the smallest possible value to it is very unlikely to ever
+ // affect any of the percentile results.
+ buckets[d][1]++;
+ } else {
+ buckets[d][ticks / width[d]]++;
+ }
+ break;
+ }
+ }
+ }
+
+ // The list of largest times is sorted with the biggest value at index 0 and the smallest at
+ // index MaxLargest-1. The incoming tick count should be added to the array only if it is
+ // larger than the current value at MaxLargest-1.
+ if (ticks > largest[Timer::MaxLargest-1]) {
+ for (size_t i = 0; i < Timer::MaxLargest; i++) {
+ if (ticks > largest[i]) {
+ if (i < Timer::MaxLargest-1) {
+ for (size_t j = Timer::MaxLargest - 1; j > i; j--) {
+ largest[j] = largest[j-1];
+ }
+ }
+ largest[i] = ticks;
+ break;
+ }
+ }
+ }
+}
+
+void ResourceTimer::Timer::Percentile::compute(
+ int cumulative, int current, int count, int width, int time) {
+ nominal = time;
+ nominal_actual = (cumulative * 100) / count;
+ floor = nominal - width;
+ floor_actual = ((cumulative - current) * 100) / count;
+}
+
+void ResourceTimer::Timer::compute() {
+ memset(&pvalues, 0, sizeof(pvalues));
+
+ float l50 = count / 2.0;
+ float l90 = (count * 9.0) / 10.0;
+ float l95 = (count * 95.0) / 100.0;
+ float l99 = (count * 99.0) / 100.0;
+
+ int sum = 0;
+ for (int d = 0; d < MaxDimension; d++) {
+ if (buckets[d] == 0) continue;
+ for (int j = 0; j < MaxBuckets && sum < count; j++) {
+ // Empty buckets don't contribute to the answers. Skip them.
+ if (buckets[d][j] == 0) continue;
+ sum += buckets[d][j];
+ // A word on indexing. j is never zero in the following lines. buckets[0][0] corresponds
+ // to a delay of 0us, which cannot happen. buckets[n][0], for n > 0 overlaps a value in
+ // buckets[n-1], and the code would have stopped there.
+ if (sum >= l50 && pvalues.p50.nominal == 0) {
+ pvalues.p50.compute(sum, buckets[d][j], count, width[d], j * width[d]);
+ }
+ if (sum >= l90 && pvalues.p90.nominal == 0) {
+ pvalues.p90.compute(sum, buckets[d][j], count, width[d], j * width[d]);
+ }
+ if (sum >= l95 && pvalues.p95.nominal == 0) {
+ pvalues.p95.compute(sum, buckets[d][j], count, width[d], j * width[d]);
+ }
+ if (sum >= l99 && pvalues.p99.nominal == 0) {
+ pvalues.p99.compute(sum, buckets[d][j], count, width[d], j * width[d]);
+ }
+ }
+ }
+}
+
+char const *ResourceTimer::toString(ResourceTimer::Counter counter) {
+ switch (counter) {
+ case Counter::GetResourceValue:
+ return "GetResourceValue";
+ case Counter::RetrieveAttributes:
+ return "RetrieveAttributes";
+ };
+ return "Unknown";
+}
+
+std::atomic<bool> ResourceTimer::enabled_(false);
+std::atomic<ResourceTimer::GuardedTimer *> ResourceTimer::counter_(nullptr);
+
+const int ResourceTimer::Timer::range[] = { 100 * US, 1000 * US, 10*1000 * US, 100*1000 * US };
+const int ResourceTimer::Timer::width[] = { 1 * US, 10 * US, 100 * US, 1000 * US };
+
+
+} // namespace android
diff --git a/libs/androidfw/include/androidfw/ResourceTimer.h b/libs/androidfw/include/androidfw/ResourceTimer.h
new file mode 100644
index 0000000..7461351
--- /dev/null
+++ b/libs/androidfw/include/androidfw/ResourceTimer.h
@@ -0,0 +1,221 @@
+/*
+ * Copyright (C) 2022 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.
+ */
+
+#ifndef ANDROIDFW_RESOURCETIMER_H_
+#define ANDROIDFW_RESOURCETIMER_H_
+
+#include <time.h>
+#include <atomic>
+#include <vector>
+
+#include <utils/Mutex.h>
+#include <android-base/macros.h>
+#include <androidfw/Util.h>
+
+namespace android {
+
+// ResourceTimer captures the duration of short functions. Durations are accumulated in registers
+// and statistics are pulled back to the Java layer as needed.
+// To monitor an API, first add it to the Counter enumeration. Then, inside the API, create an
+// instance of ResourceTimer with the appropriate enumeral. The corresponding counter will be
+// updated when the ResourceTimer destructor is called, normally at the end of the enclosing block.
+class ResourceTimer {
+ public:
+ enum class Counter {
+ GetResourceValue,
+ RetrieveAttributes,
+
+ LastCounter = RetrieveAttributes,
+ };
+ static const int counterSize = static_cast<int>(Counter::LastCounter) + 1;
+ static char const *toString(Counter);
+
+ // Start a timer for the specified counter.
+ ResourceTimer(Counter);
+ // The block is exiting. If the timer is active, record it.
+ ~ResourceTimer();
+ // This records the elapsed time and disables further recording. Use this if the containing
+ // block includes extra processing that should not be included in the timer. The method is
+ // destructive in that the timer is no longer valid and further calls to record() will be
+ // ignored.
+ void record();
+ // This cancels a timer. Elapsed time will neither be computed nor recorded.
+ void cancel();
+
+ // A single timer contains the count of events and the cumulative time spent handling the
+ // events. It also includes the smallest value seen and 10 largest values seen. Finally, it
+ // includes a histogram of values that approximates a semi-log.
+
+ // The timer can compute percentiles of recorded events. For example, the p50 value is a time
+ // such that 50% of the readings are below the value and 50% are above the value. The
+ // granularity in the readings means that a percentile cannot always be computed. In this case,
+ // the percentile is reported as zero. (The simplest example is when there is a single
+ // reading.) Even if the value can be computed, it will not be exact. Therefore, a percentile
+ // is actually reported as two values: the lowest time at which it might be valid and the
+ // highest time at which it might be valid.
+ struct Timer {
+ static const size_t MaxLargest = 5;
+
+ // The construct zeros all the fields. The destructor releases memory allocated to the
+ // buckets.
+ Timer();
+ ~Timer();
+
+ // The following summary values are set to zero on a reset. All times are in ns.
+
+ // The total number of events recorded.
+ int count;
+ // The total duration of events.
+ int64_t total;
+ // The smallest event duration seen. This is guaranteed to be non-zero if count is greater
+ // than 0.
+ int mintime;
+ // The largest event duration seen.
+ int maxtime;
+
+ // The largest values seen. Element 0 is the largest value seen (and is the same as maxtime,
+ // above). Element 1 is the next largest, and so on. If count is less than MaxLargest,
+ // unused elements will be zero.
+ int largest[MaxLargest];
+
+ // The p50 value is a time such that 50% of the readings are below that time and 50% of the
+ // readings.
+
+ // A single percentile is defined by the lowest value supported by the readings and the
+ // highest value supported by the readings.
+ struct Percentile {
+ // The nominal time (in ns) of the percentile. The true percentile is guaranteed to be less
+ // than or equal to this time.
+ int nominal;
+ // The actual percentile of the nominal time.
+ int nominal_actual;
+ // The time of the next lower bin. The true percentile is guaranteed to be greater than
+ // this time.
+ int floor;
+ // The actual percentile of the floor time.
+ int floor_actual;
+
+ // Fill in a percentile given the cumulative to the bin, the count in the current bin, the
+ // total count, the width of the bin, and the time of the bin.
+ void compute(int cumulative, int current, int count, int width, int time);
+ };
+
+ // The structure that holds the percentiles.
+ struct {
+ Percentile p50;
+ Percentile p90;
+ Percentile p95;
+ Percentile p99;
+ } pvalues;
+
+ // Set all counters to zero.
+ void reset();
+ // Record an event. The input time is in ns.
+ void record(int);
+ // Compute the percentiles. Percentiles are computed on demand, as the computation is too
+ // expensive to be done inline.
+ void compute();
+
+ // Copy one timer to another. If reset is true then the src is reset immediately after the
+ // copy. The reset flag is exploited to make the copy faster. Any data in dst is lost.
+ static void copy(Timer &dst, Timer &src, bool reset);
+
+ private:
+ // Free any buckets.
+ void freeBuckets();
+
+ // Readings are placed in bins, which are orgzanized into decades. The decade 0 covers
+ // [0,100) in steps of 1us. Decade 1 covers [0,1000) in steps of 10us. Decade 2 covers
+ // [0,10000) in steps of 100us. And so on.
+
+ // An event is placed in the first bin that can hold it. This means that events in the range
+ // of [0,100) are placed in the first decade, events in the range of [0,1000) are placed in
+ // the second decade, and so on. This also means that the first 10% of the bins are unused
+ // in each decade after the first.
+
+ // The design provides at least two significant digits across the range of [0,10000).
+
+ static const size_t MaxDimension = 4;
+ static const size_t MaxBuckets = 100;
+
+ // The range of each dimension. The lower value is always zero.
+ static const int range[MaxDimension];
+ // The width of each bin, by dimension
+ static const int width[MaxDimension];
+
+ // A histogram of the values seen. Centuries are allocated as needed, to minimize the memory
+ // impact.
+ int *buckets[MaxDimension];
+ };
+
+ // Fetch one Timer. The function has a short-circuit behavior: if the count is zero then
+ // destination count is set to zero and the function returns false. Otherwise, the destination
+ // is a copy of the source and the function returns true. This behavior lowers the cost of
+ // handling unused timers.
+ static bool copy(int src, Timer &dst, bool reset);
+
+ // Enable the timers. Timers are initially disabled. Enabling timers allocates memory for the
+ // counters. Timers cannot be disabled.
+ static void enable();
+
+ private:
+ // An internal reset method. This does not take a lock.
+ static void reset();
+
+ // Helper method to convert a counter into an enum. Presumably, this will be inlined into zero
+ // actual cpu instructions.
+ static inline std::vector<unsigned int>::size_type toIndex(Counter c) {
+ return static_cast<std::vector<unsigned int>::size_type>(c);
+ }
+
+ // Every counter has an associated lock. The lock has been factored into a separate class to
+ // keep the Timer class a POD.
+ struct GuardedTimer {
+ Mutex lock_;
+ Timer timer_;
+ };
+
+ // Scoped timer
+ struct ScopedTimer {
+ AutoMutex _l;
+ Timer &t;
+ ScopedTimer(GuardedTimer &g) :
+ _l(g.lock_), t(g.timer_) {
+ }
+ Timer *operator->() {
+ return &t;
+ }
+ Timer& operator*() {
+ return t;
+ }
+ };
+
+ // An individual timer is active (or not), is tracking a specific API, and has a start time.
+ // The api and the start time are undefined if the timer is not active.
+ bool active_;
+ Counter api_;
+ struct timespec start_;
+
+ // The global enable flag. This is initially false and may be set true by the java runtime.
+ static std::atomic<bool> enabled_;
+
+ // The global timers. The memory for the timers is not allocated until the timers are enabled.
+ static std::atomic<GuardedTimer *> counter_;
+};
+
+} // namespace android
+
+#endif /* ANDROIDFW_RESOURCETIMER_H_ */
diff --git a/libs/androidfw/tests/ResourceTimer_test.cpp b/libs/androidfw/tests/ResourceTimer_test.cpp
new file mode 100644
index 0000000..4a1e973
--- /dev/null
+++ b/libs/androidfw/tests/ResourceTimer_test.cpp
@@ -0,0 +1,245 @@
+/*
+ * Copyright (C) 2022 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.
+ */
+
+
+#include <android-base/file.h>
+#include <android-base/test_utils.h>
+#include <androidfw/Util.h>
+
+#include "TestHelpers.h"
+
+#include <androidfw/ResourceTimer.h>
+
+namespace android {
+
+namespace {
+
+// Create a reading in us. This is a convenience function to avoid multiplying by 1000
+// everywhere.
+unsigned int US(int us) {
+ return us * 1000;
+}
+
+}
+
+TEST(ResourceTimerTest, TimerBasic) {
+ ResourceTimer::Timer timer;
+ ASSERT_THAT(timer.count, 0);
+ ASSERT_THAT(timer.total, 0);
+
+ for (int i = 1; i <= 100; i++) {
+ timer.record(US(i));
+ }
+ ASSERT_THAT(timer.count, 100);
+ ASSERT_THAT(timer.total, US((101 * 100)/2));
+ ASSERT_THAT(timer.mintime, US(1));
+ ASSERT_THAT(timer.maxtime, US(100));
+ ASSERT_THAT(timer.pvalues.p50.floor, 0);
+ ASSERT_THAT(timer.pvalues.p50.nominal, 0);
+ ASSERT_THAT(timer.largest[0], US(100));
+ ASSERT_THAT(timer.largest[1], US(99));
+ ASSERT_THAT(timer.largest[2], US(98));
+ ASSERT_THAT(timer.largest[3], US(97));
+ ASSERT_THAT(timer.largest[4], US(96));
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(49));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(50));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(89));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(90));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(94));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(95));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(98));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(99));
+
+ // Test reset functionality. All values should be zero after the reset. Computing pvalues
+ // after the result should also yield zeros.
+ timer.reset();
+ ASSERT_THAT(timer.count, 0);
+ ASSERT_THAT(timer.total, 0);
+ ASSERT_THAT(timer.mintime, US(0));
+ ASSERT_THAT(timer.maxtime, US(0));
+ ASSERT_THAT(timer.pvalues.p50.floor, US(0));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(0));
+ ASSERT_THAT(timer.largest[0], US(0));
+ ASSERT_THAT(timer.largest[1], US(0));
+ ASSERT_THAT(timer.largest[2], US(0));
+ ASSERT_THAT(timer.largest[3], US(0));
+ ASSERT_THAT(timer.largest[4], US(0));
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(0));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(0));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(0));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(0));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(0));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(0));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(0));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(0));
+
+ // Test again, adding elements in reverse.
+ for (int i = 100; i >= 1; i--) {
+ timer.record(US(i));
+ }
+ ASSERT_THAT(timer.count, 100);
+ ASSERT_THAT(timer.total, US((101 * 100)/2));
+ ASSERT_THAT(timer.mintime, US(1));
+ ASSERT_THAT(timer.maxtime, US(100));
+ ASSERT_THAT(timer.pvalues.p50.floor, 0);
+ ASSERT_THAT(timer.pvalues.p50.nominal, 0);
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(49));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(50));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(89));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(90));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(94));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(95));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(98));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(99));
+ ASSERT_THAT(timer.largest[0], US(100));
+ ASSERT_THAT(timer.largest[1], US(99));
+ ASSERT_THAT(timer.largest[2], US(98));
+ ASSERT_THAT(timer.largest[3], US(97));
+ ASSERT_THAT(timer.largest[4], US(96));
+}
+
+TEST(ResourceTimerTest, TimerLimit) {
+ ResourceTimer::Timer timer;
+
+ // Event truncation means that a time of 1050us will be stored in the 1000us
+ // bucket. Since there is a single event, all p-values lie in the same range.
+ timer.record(US(1050));
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(900));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(1000));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(900));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(1000));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(900));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(1000));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(900));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(1000));
+}
+
+TEST(ResourceTimerTest, TimerCopy) {
+ ResourceTimer::Timer source;
+ for (int i = 1; i <= 100; i++) {
+ source.record(US(i));
+ }
+ ResourceTimer::Timer timer;
+ ResourceTimer::Timer::copy(timer, source, true);
+ ASSERT_THAT(source.count, 0);
+ ASSERT_THAT(source.total, 0);
+ // compute() is not normally be called on a reset timer, but it should work and it should return
+ // all zeros.
+ source.compute();
+ ASSERT_THAT(source.pvalues.p50.floor, US(0));
+ ASSERT_THAT(source.pvalues.p50.nominal, US(0));
+ ASSERT_THAT(source.pvalues.p90.floor, US(0));
+ ASSERT_THAT(source.pvalues.p90.nominal, US(0));
+ ASSERT_THAT(source.pvalues.p95.floor, US(0));
+ ASSERT_THAT(source.pvalues.p95.nominal, US(0));
+ ASSERT_THAT(source.pvalues.p99.floor, US(0));
+ ASSERT_THAT(source.pvalues.p99.nominal, US(0));
+ ASSERT_THAT(source.largest[0], US(0));
+ ASSERT_THAT(source.largest[1], US(0));
+ ASSERT_THAT(source.largest[2], US(0));
+ ASSERT_THAT(source.largest[3], US(0));
+ ASSERT_THAT(source.largest[4], US(0));
+
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(49));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(50));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(89));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(90));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(94));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(95));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(98));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(99));
+ ASSERT_THAT(timer.largest[0], US(100));
+ ASSERT_THAT(timer.largest[1], US(99));
+ ASSERT_THAT(timer.largest[2], US(98));
+ ASSERT_THAT(timer.largest[3], US(97));
+ ASSERT_THAT(timer.largest[4], US(96));
+
+ // Call compute a second time. The values must be the same.
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(49));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(50));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(89));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(90));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(94));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(95));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(98));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(99));
+ ASSERT_THAT(timer.largest[0], US(100));
+ ASSERT_THAT(timer.largest[1], US(99));
+ ASSERT_THAT(timer.largest[2], US(98));
+ ASSERT_THAT(timer.largest[3], US(97));
+ ASSERT_THAT(timer.largest[4], US(96));
+
+ // Modify the source. If timer and source share histogram arrays, this will introduce an
+ // error.
+ for (int i = 1; i <= 100; i++) {
+ source.record(US(i));
+ }
+ // Call compute a third time. The values must be the same.
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(49));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(50));
+ ASSERT_THAT(timer.pvalues.p90.floor, US(89));
+ ASSERT_THAT(timer.pvalues.p90.nominal, US(90));
+ ASSERT_THAT(timer.pvalues.p95.floor, US(94));
+ ASSERT_THAT(timer.pvalues.p95.nominal, US(95));
+ ASSERT_THAT(timer.pvalues.p99.floor, US(98));
+ ASSERT_THAT(timer.pvalues.p99.nominal, US(99));
+ ASSERT_THAT(timer.largest[0], US(100));
+ ASSERT_THAT(timer.largest[1], US(99));
+ ASSERT_THAT(timer.largest[2], US(98));
+ ASSERT_THAT(timer.largest[3], US(97));
+ ASSERT_THAT(timer.largest[4], US(96));
+}
+
+// Verify that if too many oversize entries are reported, the percentile values cannot be computed
+// and are set to zero.
+TEST(ResourceTimerTest, TimerOversize) {
+ static const int oversize = US(2 * 1000 * 1000);
+
+ ResourceTimer::Timer timer;
+ for (int i = 1; i <= 100; i++) {
+ timer.record(US(i));
+ }
+
+ // Insert enough oversize values to invalidate the p90, p95, and p99 percentiles. The p50 is
+ // still computable.
+ for (int i = 1; i <= 50; i++) {
+ timer.record(oversize);
+ }
+ ASSERT_THAT(timer.largest[0], oversize);
+ ASSERT_THAT(timer.largest[1], oversize);
+ ASSERT_THAT(timer.largest[2], oversize);
+ ASSERT_THAT(timer.largest[3], oversize);
+ ASSERT_THAT(timer.largest[4], oversize);
+ timer.compute();
+ ASSERT_THAT(timer.pvalues.p50.floor, US(74));
+ ASSERT_THAT(timer.pvalues.p50.nominal, US(75));
+ ASSERT_THAT(timer.pvalues.p90.floor, 0);
+ ASSERT_THAT(timer.pvalues.p90.nominal, 0);
+ ASSERT_THAT(timer.pvalues.p95.floor, 0);
+ ASSERT_THAT(timer.pvalues.p95.nominal, 0);
+ ASSERT_THAT(timer.pvalues.p99.floor, 0);
+ ASSERT_THAT(timer.pvalues.p99.nominal, 0);
+}
+
+
+} // namespace android