Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge "Record resource access times"

Browse Source
This commit is contained in:
Lee Shombert
2022-09-20 19:08:32 +00:00
committed by Android (Google) Code Review
parent 9f7005c5e9 3e4d9f2007
commit d112853729
8 changed files with 1160 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

289
core/java/android/content/res/ResourceTimer.java Normal file
View File

@@ -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);
}

1
core/jni/Android.bp
View File

@@ -209,6 +209,7 @@ cc_library_shared {
"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",

2
core/jni/AndroidRuntime.cpp
View File

@@ -117,6 +117,7 @@ extern int register_android_util_MemoryIntArray(JNIEnv* env);
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 @@ static const RegJNIRec gRegJNI[] = {
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),

129
core/jni/android_content_res_ResourceTimer.cpp Normal file
View File

@@ -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

2
libs/androidfw/Android.bp
View File

@@ -71,6 +71,7 @@ cc_library {
"misc.cpp",
"ObbFile.cpp",
"PosixUtils.cpp",
"ResourceTimer.cpp",
"ResourceTypes.cpp",
"ResourceUtils.cpp",
"StreamingZipInflater.cpp",
@@ -173,6 +174,7 @@ cc_test {
"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",

271
libs/androidfw/ResourceTimer.cpp Normal file
View File

@@ -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

221
libs/androidfw/include/androidfw/ResourceTimer.h Normal file
View File

@@ -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_ */

245
libs/androidfw/tests/ResourceTimer_test.cpp Normal file
View File

@@ -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