Loading services/core/java/com/android/server/utils/AnrTimer.java +50 −5 Original line number Diff line number Diff line Loading @@ -193,6 +193,9 @@ public class AnrTimer<V> implements AutoCloseable { new TreeSet<>(comparingInt(SplitPoint::percent) .thenComparingInt(SplitPoint::token)); /** Make this AnrTimer use test-mode clocking. This is only useful in tests. */ private boolean mTestMode = false; // This is only used for testing, so it is limited to package visibility. Args injector(@NonNull Injector injector) { mInjector = injector; Loading @@ -209,6 +212,11 @@ public class AnrTimer<V> implements AutoCloseable { return this; } public Args testMode(boolean flag) { mTestMode = flag; return this; } /** * Enables or disables long method tracing. * When enabled, the timer will trigger long method tracing if it reaches 50% Loading Loading @@ -427,14 +435,14 @@ public class AnrTimer<V> implements AutoCloseable { mWhat = what; mLabel = label; mArgs = args; boolean enabled = args.mEnable && nativeTimersSupported(); mFeature = createFeatureSwitch(enabled); mFeature = createFeatureSwitch(); } // Return the correct feature. FeatureEnabled is returned if and only if the feature is // flag-enabled and if the native shadow was successfully created. Otherwise, FeatureDisabled // is returned. private FeatureSwitch createFeatureSwitch(boolean enabled) { private FeatureSwitch createFeatureSwitch() { final boolean enabled = mArgs.mEnable && nativeTimersSupported(); if (!enabled) { return new FeatureDisabled(); } else { Loading Loading @@ -505,6 +513,8 @@ public class AnrTimer<V> implements AutoCloseable { abstract void dump(IndentingPrintWriter pw, boolean verbose); abstract void close(); abstract void setTime(long now); } /** Loading Loading @@ -560,6 +570,12 @@ public class AnrTimer<V> implements AutoCloseable { @Override void close() { } /** The disabled timer does not support this operation. */ @Override void setTime(long now) { throw new UnsupportedOperationException("setTime unavailable in disabled mode"); } } /** Loading Loading @@ -589,7 +605,7 @@ public class AnrTimer<V> implements AutoCloseable { /** Create the native AnrTimerService that will host all timers from this instance. */ FeatureEnabled() { mNative = nativeAnrTimerCreate(mLabel, mArgs.mExtend, mArgs.getSplitPercentArray(), mArgs.getSplitTokenArray()); mArgs.getSplitTokenArray(), mArgs.mTestMode); if (mNative == 0) throw new IllegalArgumentException("unable to create native timer"); synchronized (sAnrTimerList) { sAnrTimerList.put(mNative, new WeakReference(AnrTimer.this)); Loading Loading @@ -742,6 +758,16 @@ public class AnrTimer<V> implements AutoCloseable { } return r; } /** This is always safe to call; it does nothing if the timer is not in test mode. */ @Override void setTime(long now) { if (!mArgs.mTestMode) { throw new UnsupportedOperationException("setTime called outside test mode"); } else if (!nativeAnrTimerSetTime(mNative, now)) { throw new RuntimeException("setTime failure"); } } } /** Loading Loading @@ -883,6 +909,15 @@ public class AnrTimer<V> implements AutoCloseable { mFeature.close(); } /** * Set the current time as seen by this AnrTimer. This is only effective for native timers * that were created with testMode enabled. */ @VisibleForTesting public void setTime(long now) { mFeature.setTime(now); } /** * Ensure any native resources are freed when the object is GC'ed. Best practice is to close * the object explicitly, but overriding finalize() avoids accidental leaks. Loading Loading @@ -1037,9 +1072,12 @@ public class AnrTimer<V> implements AutoCloseable { * Create a new native timer with the given name and flags. The name is only for logging. * Unlike the other methods, this is an instance method: the "this" parameter is passed into * the native layer. * * When testMode is true, the native timer is disconnected from any real clock. Use * nativeAnrTimerSetTime() to change the time seen by a testMode timer. */ private native long nativeAnrTimerCreate(String name, boolean extend, int[] splitPercent, int[] splitToken); int[] splitPercent, int[] splitToken, boolean testMode); /** Release the native resources. No further operations are premitted. */ private static native int nativeAnrTimerClose(long service); Loading Loading @@ -1073,4 +1111,11 @@ public class AnrTimer<V> implements AutoCloseable { /** Retrieve runtime dump information from the native layer. */ private static native String[] nativeAnrTimerDump(long service); /** * Set the clock for a native time service. If the time service was created in test mode, * this changes the service's view of "now" and returns true. Otherwise it has no effect and * returns false. */ private static native boolean nativeAnrTimerSetTime(long service, long now); } services/core/jni/com_android_server_utils_AnrTimer.cpp +133 −6 Original line number Diff line number Diff line Loading @@ -26,6 +26,7 @@ #include <list> #include <map> #include <memory> #include <semaphore> #include <set> #include <string> #include <vector> Loading Loading @@ -159,6 +160,12 @@ public: // Get the current time, in nanoseconds, as understood by this instance. virtual nsecs_t getCurrentTime() = 0; // Set the current time. Return true if it worked (test mode) and false otherwise. virtual bool setCurrentTime(nsecs_t) = 0; // True on debug. Useful for test development and debugging. virtual bool isDebug() const = 0; private: Clock(const Clock&) = delete; }; Loading Loading @@ -221,6 +228,14 @@ public: return systemTime(SYSTEM_TIME_MONOTONIC); } bool setCurrentTime(nsecs_t) { return false; } bool isDebug() const { return false; } private: bool running() const { return timerFd_ >= 0; Loading @@ -229,6 +244,90 @@ private: int timerFd_; }; /** * A clock whose time is manually advanced. This is used only for testing. */ class ClockTest : public Clock { public: ClockTest() : now_(0), alarm_(0), lock_(0), running_(true) {} virtual ~ClockTest() { stop(); } // Set a timer to expire at the given relative time. int setTimer(nsecs_t delay) { if (delay <= 0) { errno = EINVAL; return -1; } alarm_ = now_ + delay; maybeRelease(); return 0; } // Clear the timer. void clearTimer() { alarm_ = 0; } // Wait for the timer to fire. Returns true if the timer is running. bool waitForTimer() { if (running_ && !ready()) { lock_.acquire(); } return running_; } // Stop the timer and release any waiters. void stop() { running_ = false; lock_.release(); } // Get the current time. This uses the same timebase as the timer. nsecs_t getCurrentTime() { return now_; } // Set the current time. This does nothing unless in the test variant. bool setCurrentTime(nsecs_t now) { now_ = now; maybeRelease(); return true; } bool isDebug() const { return true; } private: // Return true if there is an expired alarm time. bool ready() const { return (alarm_ > 0 && alarm_ <= now_); } // Maybe release any waiters. void maybeRelease() { if (ready()) { lock_.release(); } } // The current time. nsecs_t now_; // The current timeout. nsecs_t alarm_; // A semaphore: it is taken inside waitForTimer() and it is released in setCurrentTime() // when the new time is greater than or equal to the alarm. std::binary_semaphore lock_; // Set false to indicate that the clock is about to exit. bool running_; }; /** * Actions that can be taken when a timer reaches a split point. * - Trace: Log the event for debugging Loading Loading @@ -637,6 +736,10 @@ class AnrTimerService { return notifierObject_; } // Set the time in the current Clock. This has no effect if the instance is not in test // mode. bool setCurrentTime(nsecs_t); // Return the per-instance statistics. std::vector<std::string> getDump() const; Loading Loading @@ -1086,6 +1189,12 @@ class AnrTimerService::Ticker { return maxRunning_; } // Set the current time of this ticker's clock. Returns true on success (this ticker is // using a test clock) and false otherwise. bool setCurrentTime(nsecs_t now) { return clock_->setCurrentTime(now); } private: // Return the head of the running list. The lock must be held by the caller. Loading Loading @@ -1346,6 +1455,10 @@ nsecs_t AnrTimerService::now() const { return ticker_->now(); } bool AnrTimerService::setCurrentTime(nsecs_t now) { return ticker_->setCurrentTime(now); } std::vector<std::string> AnrTimerService::getDump() const { std::vector<std::string> r; AutoMutex _l(lock_); Loading Loading @@ -1421,15 +1534,21 @@ jboolean anrTimerSupported(JNIEnv* env, jclass) { } jlong anrTimerCreate(JNIEnv* env, jobject jtimer, jstring jname, jboolean extend, jintArray jperc, jintArray jtok) { jintArray jtok, jboolean testMode) { if (!nativeSupportEnabled) return 0; AutoMutex _l(gAnrLock); // Create a Posix ticker lazily. This is a singleton that is shared by all non-test // timers. However, every test timer gets its own ticker. std::shared_ptr<AnrTimerService::Ticker> ticker; if (testMode) { ticker.reset(new AnrTimerService::Ticker(std::unique_ptr<Clock>(new ClockTest()))); } else { if (gAnrArgs.ticker.get() == nullptr) { gAnrArgs.ticker.reset( new AnrTimerService::Ticker(std::unique_ptr<Clock>(new ClockPosix()))); } ticker = gAnrArgs.ticker; } std::vector<SplitPoint> splits; if (jperc && jtok) { Loading Loading @@ -1515,9 +1634,16 @@ jobjectArray anrTimerDump(JNIEnv *env, jclass, jlong ptr) { return r; } jboolean anrTimerSetTime(JNIEnv* env, jclass, jlong ptr, jlong now) { if (!nativeSupportEnabled) return false; // On the Java side, timeouts are expressed in milliseconds and must be converted to // nanoseconds before being passed to the library code. return toService(ptr)->setCurrentTime(milliseconds_to_nanoseconds(now)); } static const JNINativeMethod methods[] = { {"nativeAnrTimerSupported", "()Z", (void*)anrTimerSupported}, {"nativeAnrTimerCreate", "(Ljava/lang/String;Z[I[I)J", (void*)anrTimerCreate}, {"nativeAnrTimerCreate", "(Ljava/lang/String;Z[I[IZ)J", (void*)anrTimerCreate}, {"nativeAnrTimerClose", "(J)I", (void*)anrTimerClose}, {"nativeAnrTimerStart", "(JIIJ)I", (void*)anrTimerStart}, {"nativeAnrTimerCancel", "(JI)Z", (void*)anrTimerCancel}, Loading @@ -1525,6 +1651,7 @@ static const JNINativeMethod methods[] = { {"nativeAnrTimerDiscard", "(JI)Z", (void*)anrTimerDiscard}, {"nativeAnrTimerTrace", "([Ljava/lang/String;)Ljava/lang/String;", (void*)anrTimerTrace}, {"nativeAnrTimerDump", "(J)[Ljava/lang/String;", (void*)anrTimerDump}, {"nativeAnrTimerSetTime", "(JJ)Z", (void*)anrTimerSetTime}, }; } // anonymous namespace Loading services/tests/servicestests/src/com/android/server/utils/AnrTimerTest.java +148 −87 Original line number Diff line number Diff line Loading @@ -18,33 +18,32 @@ package com.android.server.utils; import static com.google.common.truth.Truth.assertThat; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertNotEquals; import static org.junit.Assert.assertTrue; import static org.junit.Assume.assumeTrue; import android.os.Handler; import android.os.Looper; import android.os.Message; import android.platform.test.annotations.Presubmit; import android.util.Log; import android.platform.test.annotations.Presubmit; import androidx.test.filters.SmallTest; import com.android.internal.annotations.GuardedBy; import org.junit.Ignore; import org.junit.Test; import org.junit.runner.RunWith; import org.junit.runners.Parameterized; import org.junit.runners.Parameterized.Parameters; import java.io.PrintWriter; import java.io.StringWriter; import java.util.ArrayList; import java.util.Arrays; import java.util.Collection; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; @SmallTest @Presubmit @RunWith(Parameterized.class) public class AnrTimerTest { // A log tag. Loading @@ -66,6 +65,11 @@ public class AnrTimerTest { this.uid = uid; this.what = 0; } @Override public String toString() { return String.format("pid=%d uid=%d what=%d", pid, uid, what); } } /** The test helper is a self-contained object for a single test. */ Loading @@ -75,11 +79,12 @@ public class AnrTimerTest { final Handler mHandler; final CountDownLatch mLatch; @GuardedBy("mLock") final ArrayList<TestArg> mMessages; final ArrayList<TestArg> mMessages = new ArrayList<>(); @GuardedBy("mLock") final ArrayList<Thread> mThreads = new ArrayList<>(); Helper(int expect) { mHandler = new Handler(Looper.getMainLooper(), this::expirationHandler); mMessages = new ArrayList<>(); mLatch = new CountDownLatch(expect); } Loading @@ -92,6 +97,7 @@ public class AnrTimerTest { TestArg arg = (TestArg) msg.obj; arg.what = msg.what; mMessages.add(arg); mThreads.add(Thread.currentThread()); mLatch.countDown(); return false; } Loading @@ -102,6 +108,15 @@ public class AnrTimerTest { return mLatch.await(timeout, TimeUnit.MILLISECONDS); } /** * Return the number of messages so far. */ int size() { synchronized (mLock) { return mMessages.size(); } } /** * Fetch the received messages. Fail if the count of received messages is other than the * expected count. Loading @@ -112,18 +127,30 @@ public class AnrTimerTest { return mMessages.toArray(new TestArg[expected]); } } /** * Fetch the threads that delivered the messages. */ Thread[] threads() { synchronized (mLock) { return mThreads.toArray(new Thread[mThreads.size()]); } } } /** * An instrumented AnrTimer. */ private class TestAnrTimer extends AnrTimer<TestArg> { private TestAnrTimer(Handler h, int key, String tag) { super(h, key, tag, new AnrTimer.Args().enable(mEnabled)); private TestAnrTimer(Handler h, int key, String tag, boolean enable, boolean testMode) { super(h, key, tag, new AnrTimer.Args().enable(enable).testMode(testMode)); } TestAnrTimer(Helper helper, boolean enable, boolean testMode) { this(helper.mHandler, MSG_TIMEOUT, caller(), enable, testMode); } TestAnrTimer(Helper helper) { this(helper.mHandler, MSG_TIMEOUT, caller()); TestAnrTimer(Helper helper, boolean enable) { this(helper, enable, false); } @Override Loading Loading @@ -152,91 +179,110 @@ public class AnrTimerTest { assertThat(actual.what).isEqualTo(MSG_TIMEOUT); } @Parameters(name = "featureEnabled={0}") public static Collection<Object[]> data() { return Arrays.asList(new Object[][] { {false}, {true} }); } /** True if the feature is enabled. */ private boolean mEnabled; public AnrTimerTest(boolean featureEnabled) { mEnabled = featureEnabled; } /** * Verify that a simple expiration succeeds. The timer is started for 10ms. The test * procedure waits 5s for the expiration message, but under correct operation, the test will * only take 10ms */ @Test public void testSimpleTimeout() throws Exception { private void testSimpleTimeout(boolean enable) throws Exception { Helper helper = new Helper(1); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { // One-time check that the injector is working as expected. assertThat(mEnabled).isEqualTo(timer.serviceEnabled()); assertThat(enable).isEqualTo(timer.serviceEnabled()); TestArg t = new TestArg(1, 1); timer.start(t, 10); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(1); validate(t, result[0]); } } @Test public void testSimpleTimeoutDisabled() throws Exception { testSimpleTimeout(false); } @Test public void testSimpleTimeoutEnabled() throws Exception { testSimpleTimeout(true); } /** * Verify that a restarted timer is delivered exactly once. The initial timer value is very * large, to ensure it does not expire before the timer can be restarted. */ @Test public void testTimerRestart() throws Exception { private void testTimerRestart(boolean enable) throws Exception { Helper helper = new Helper(1); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { TestArg t = new TestArg(1, 1); timer.start(t, 10000); // Briefly pause. assertThat(helper.await(10)).isFalse(); timer.start(t, 10); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(1); validate(t, result[0]); } } @Test public void testTimerRestartDisabled() throws Exception { testTimerRestart(false); } @Test public void testTimerRestartEnabled() throws Exception { testTimerRestart(true); } /** * Verify that a restarted timer is delivered exactly once. The initial timer value is very * large, to ensure it does not expire before the timer can be restarted. * Verify that a zero timeout is delivered on a different thread. Repeat with a negative * timeout. The order in which the timers are delivered is unpredictable (it is based on CPU * time during the test), so it is not checked. */ @Test public void testTimerZero() throws Exception { Helper helper = new Helper(1); try (TestAnrTimer timer = new TestAnrTimer(helper)) { TestArg t = new TestArg(1, 1); timer.start(t, 0); // Delivery is immediate but occurs on a different thread. private void testTimerZero(boolean enable) throws Exception { Helper helper = new Helper(2); try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { TestArg t1 = new TestArg(1, 1); timer.start(t1, 0); TestArg t2 = new TestArg(1, 2); timer.start(t2, -5); assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(1); validate(t, result[0]); assertEquals(2, helper.size()); Thread[] threads = helper.threads(); Thread me = Thread.currentThread(); assertNotEquals(me, threads[0]); assertNotEquals(me, threads[1]); } } @Test public void testTimerZeroDisabled() throws Exception { testTimerZero(false); } @Test public void testTimerZeroEnabled() throws Exception { testTimerZero(true); } /** * Verify that if three timers are scheduled on a single AnrTimer, they are delivered in time * order. */ @Test public void testMultipleTimers() throws Exception { private void testMultipleTimers(boolean enable) throws Exception { // Expect three messages. Helper helper = new Helper(3); TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { timer.start(t1, 50); timer.start(t2, 60); timer.start(t3, 40); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(3); validate(t3, result[0]); Loading @@ -245,51 +291,76 @@ public class AnrTimerTest { } } @Test public void testMultipleTimersDisabled() throws Exception { testMultipleTimers(false); } @Test public void testMultipleTimersEnabled() throws Exception { testMultipleTimers(true); } /** * Verify that if three timers are scheduled on three separate AnrTimers, they are delivered * in time order. * Verify that a canceled timer is not delivered. */ @Test public void testMultipleServices() throws Exception { // Expect three messages. Helper helper = new Helper(3); private void testCancelTimer(boolean enable) throws Exception { // Expect two messages. Helper helper = new Helper(2); TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer x1 = new TestAnrTimer(helper); TestAnrTimer x2 = new TestAnrTimer(helper); TestAnrTimer x3 = new TestAnrTimer(helper)) { x1.start(t1, 50); x2.start(t2, 60); x3.start(t3, 40); try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { timer.start(t1, 200); timer.start(t2, 300); timer.start(t3, 100); // Briefly pause. assertThat(helper.await(10)).isFalse(); timer.cancel(t1); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(3); TestArg[] result = helper.messages(2); validate(t3, result[0]); validate(t1, result[1]); validate(t2, result[2]); validate(t2, result[1]); } } @Test public void testCancelTimerDisabled() throws Exception { testCancelTimer(false); } @Test public void testCancelTimerEnabled() throws Exception { testCancelTimer(true); } /** * Verify that a canceled timer is not delivered. * Test the new manual-clock AnrTimer. This is only tested with the feature enabled. */ @Test public void testCancelTimer() throws Exception { public void testManualClock() throws Exception { assumeTrue(AnrTimer.nativeTimersSupported()); // Expect two messages. Helper helper = new Helper(2); TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, true, true)) { timer.start(t1, 50); timer.start(t2, 60); timer.start(t3, 40); assertEquals(0, helper.size()); // Briefly pause. assertThat(helper.await(10)).isFalse(); timer.setTime(10); assertEquals(0, helper.size()); timer.cancel(t1); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); timer.setTime(70); assertThat(helper.await(1000)).isTrue(); TestArg[] result = helper.messages(2); validate(t3, result[0]); validate(t2, result[1]); Loading @@ -312,7 +383,7 @@ public class AnrTimerTest { */ @Test public void testDumpOutput() throws Exception { if (!AnrTimer.nativeTimersSupported()) return; assumeTrue(AnrTimer.nativeTimersSupported()); // The timers in this class are named "class.method". final String timerName = "timer: com.android.server.utils.AnrTimerTest"; Loading @@ -324,18 +395,15 @@ public class AnrTimerTest { TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, true, true)) { timer.start(t1, 5000); timer.start(t2, 5000); timer.start(t3, 5000); // Do not advance the clock. String r2 = getDumpOutput(); // There are timers in the list if and only if the feature is enabled. if (mEnabled) { assertThat(r2).contains(timerName); } else { assertThat(r2).doesNotContain(timerName); } } String r3 = getDumpOutput(); Loading @@ -350,8 +418,6 @@ public class AnrTimerTest { @Ignore @Test public void testGarbageCollection() throws Exception { if (!mEnabled) return; String r1 = getDumpOutput(); assertThat(r1).doesNotContain("timer:"); Loading @@ -361,18 +427,13 @@ public class AnrTimerTest { TestArg t3 = new TestArg(1, 3); // The timer is explicitly not closed. It is, however, scoped to the next block. { TestAnrTimer timer = new TestAnrTimer(helper); TestAnrTimer timer = new TestAnrTimer(helper, true); timer.start(t1, 5000); timer.start(t2, 5000); timer.start(t3, 5000); String r2 = getDumpOutput(); // There are timers in the list if and only if the feature is enabled. if (mEnabled) { assertThat(r2).contains("timer:"); } else { assertThat(r2).doesNotContain("timer:"); } } // Try to make finalizers run. The timer object above should be a candidate. Finalizers Loading Loading
services/core/java/com/android/server/utils/AnrTimer.java +50 −5 Original line number Diff line number Diff line Loading @@ -193,6 +193,9 @@ public class AnrTimer<V> implements AutoCloseable { new TreeSet<>(comparingInt(SplitPoint::percent) .thenComparingInt(SplitPoint::token)); /** Make this AnrTimer use test-mode clocking. This is only useful in tests. */ private boolean mTestMode = false; // This is only used for testing, so it is limited to package visibility. Args injector(@NonNull Injector injector) { mInjector = injector; Loading @@ -209,6 +212,11 @@ public class AnrTimer<V> implements AutoCloseable { return this; } public Args testMode(boolean flag) { mTestMode = flag; return this; } /** * Enables or disables long method tracing. * When enabled, the timer will trigger long method tracing if it reaches 50% Loading Loading @@ -427,14 +435,14 @@ public class AnrTimer<V> implements AutoCloseable { mWhat = what; mLabel = label; mArgs = args; boolean enabled = args.mEnable && nativeTimersSupported(); mFeature = createFeatureSwitch(enabled); mFeature = createFeatureSwitch(); } // Return the correct feature. FeatureEnabled is returned if and only if the feature is // flag-enabled and if the native shadow was successfully created. Otherwise, FeatureDisabled // is returned. private FeatureSwitch createFeatureSwitch(boolean enabled) { private FeatureSwitch createFeatureSwitch() { final boolean enabled = mArgs.mEnable && nativeTimersSupported(); if (!enabled) { return new FeatureDisabled(); } else { Loading Loading @@ -505,6 +513,8 @@ public class AnrTimer<V> implements AutoCloseable { abstract void dump(IndentingPrintWriter pw, boolean verbose); abstract void close(); abstract void setTime(long now); } /** Loading Loading @@ -560,6 +570,12 @@ public class AnrTimer<V> implements AutoCloseable { @Override void close() { } /** The disabled timer does not support this operation. */ @Override void setTime(long now) { throw new UnsupportedOperationException("setTime unavailable in disabled mode"); } } /** Loading Loading @@ -589,7 +605,7 @@ public class AnrTimer<V> implements AutoCloseable { /** Create the native AnrTimerService that will host all timers from this instance. */ FeatureEnabled() { mNative = nativeAnrTimerCreate(mLabel, mArgs.mExtend, mArgs.getSplitPercentArray(), mArgs.getSplitTokenArray()); mArgs.getSplitTokenArray(), mArgs.mTestMode); if (mNative == 0) throw new IllegalArgumentException("unable to create native timer"); synchronized (sAnrTimerList) { sAnrTimerList.put(mNative, new WeakReference(AnrTimer.this)); Loading Loading @@ -742,6 +758,16 @@ public class AnrTimer<V> implements AutoCloseable { } return r; } /** This is always safe to call; it does nothing if the timer is not in test mode. */ @Override void setTime(long now) { if (!mArgs.mTestMode) { throw new UnsupportedOperationException("setTime called outside test mode"); } else if (!nativeAnrTimerSetTime(mNative, now)) { throw new RuntimeException("setTime failure"); } } } /** Loading Loading @@ -883,6 +909,15 @@ public class AnrTimer<V> implements AutoCloseable { mFeature.close(); } /** * Set the current time as seen by this AnrTimer. This is only effective for native timers * that were created with testMode enabled. */ @VisibleForTesting public void setTime(long now) { mFeature.setTime(now); } /** * Ensure any native resources are freed when the object is GC'ed. Best practice is to close * the object explicitly, but overriding finalize() avoids accidental leaks. Loading Loading @@ -1037,9 +1072,12 @@ public class AnrTimer<V> implements AutoCloseable { * Create a new native timer with the given name and flags. The name is only for logging. * Unlike the other methods, this is an instance method: the "this" parameter is passed into * the native layer. * * When testMode is true, the native timer is disconnected from any real clock. Use * nativeAnrTimerSetTime() to change the time seen by a testMode timer. */ private native long nativeAnrTimerCreate(String name, boolean extend, int[] splitPercent, int[] splitToken); int[] splitPercent, int[] splitToken, boolean testMode); /** Release the native resources. No further operations are premitted. */ private static native int nativeAnrTimerClose(long service); Loading Loading @@ -1073,4 +1111,11 @@ public class AnrTimer<V> implements AutoCloseable { /** Retrieve runtime dump information from the native layer. */ private static native String[] nativeAnrTimerDump(long service); /** * Set the clock for a native time service. If the time service was created in test mode, * this changes the service's view of "now" and returns true. Otherwise it has no effect and * returns false. */ private static native boolean nativeAnrTimerSetTime(long service, long now); }
services/core/jni/com_android_server_utils_AnrTimer.cpp +133 −6 Original line number Diff line number Diff line Loading @@ -26,6 +26,7 @@ #include <list> #include <map> #include <memory> #include <semaphore> #include <set> #include <string> #include <vector> Loading Loading @@ -159,6 +160,12 @@ public: // Get the current time, in nanoseconds, as understood by this instance. virtual nsecs_t getCurrentTime() = 0; // Set the current time. Return true if it worked (test mode) and false otherwise. virtual bool setCurrentTime(nsecs_t) = 0; // True on debug. Useful for test development and debugging. virtual bool isDebug() const = 0; private: Clock(const Clock&) = delete; }; Loading Loading @@ -221,6 +228,14 @@ public: return systemTime(SYSTEM_TIME_MONOTONIC); } bool setCurrentTime(nsecs_t) { return false; } bool isDebug() const { return false; } private: bool running() const { return timerFd_ >= 0; Loading @@ -229,6 +244,90 @@ private: int timerFd_; }; /** * A clock whose time is manually advanced. This is used only for testing. */ class ClockTest : public Clock { public: ClockTest() : now_(0), alarm_(0), lock_(0), running_(true) {} virtual ~ClockTest() { stop(); } // Set a timer to expire at the given relative time. int setTimer(nsecs_t delay) { if (delay <= 0) { errno = EINVAL; return -1; } alarm_ = now_ + delay; maybeRelease(); return 0; } // Clear the timer. void clearTimer() { alarm_ = 0; } // Wait for the timer to fire. Returns true if the timer is running. bool waitForTimer() { if (running_ && !ready()) { lock_.acquire(); } return running_; } // Stop the timer and release any waiters. void stop() { running_ = false; lock_.release(); } // Get the current time. This uses the same timebase as the timer. nsecs_t getCurrentTime() { return now_; } // Set the current time. This does nothing unless in the test variant. bool setCurrentTime(nsecs_t now) { now_ = now; maybeRelease(); return true; } bool isDebug() const { return true; } private: // Return true if there is an expired alarm time. bool ready() const { return (alarm_ > 0 && alarm_ <= now_); } // Maybe release any waiters. void maybeRelease() { if (ready()) { lock_.release(); } } // The current time. nsecs_t now_; // The current timeout. nsecs_t alarm_; // A semaphore: it is taken inside waitForTimer() and it is released in setCurrentTime() // when the new time is greater than or equal to the alarm. std::binary_semaphore lock_; // Set false to indicate that the clock is about to exit. bool running_; }; /** * Actions that can be taken when a timer reaches a split point. * - Trace: Log the event for debugging Loading Loading @@ -637,6 +736,10 @@ class AnrTimerService { return notifierObject_; } // Set the time in the current Clock. This has no effect if the instance is not in test // mode. bool setCurrentTime(nsecs_t); // Return the per-instance statistics. std::vector<std::string> getDump() const; Loading Loading @@ -1086,6 +1189,12 @@ class AnrTimerService::Ticker { return maxRunning_; } // Set the current time of this ticker's clock. Returns true on success (this ticker is // using a test clock) and false otherwise. bool setCurrentTime(nsecs_t now) { return clock_->setCurrentTime(now); } private: // Return the head of the running list. The lock must be held by the caller. Loading Loading @@ -1346,6 +1455,10 @@ nsecs_t AnrTimerService::now() const { return ticker_->now(); } bool AnrTimerService::setCurrentTime(nsecs_t now) { return ticker_->setCurrentTime(now); } std::vector<std::string> AnrTimerService::getDump() const { std::vector<std::string> r; AutoMutex _l(lock_); Loading Loading @@ -1421,15 +1534,21 @@ jboolean anrTimerSupported(JNIEnv* env, jclass) { } jlong anrTimerCreate(JNIEnv* env, jobject jtimer, jstring jname, jboolean extend, jintArray jperc, jintArray jtok) { jintArray jtok, jboolean testMode) { if (!nativeSupportEnabled) return 0; AutoMutex _l(gAnrLock); // Create a Posix ticker lazily. This is a singleton that is shared by all non-test // timers. However, every test timer gets its own ticker. std::shared_ptr<AnrTimerService::Ticker> ticker; if (testMode) { ticker.reset(new AnrTimerService::Ticker(std::unique_ptr<Clock>(new ClockTest()))); } else { if (gAnrArgs.ticker.get() == nullptr) { gAnrArgs.ticker.reset( new AnrTimerService::Ticker(std::unique_ptr<Clock>(new ClockPosix()))); } ticker = gAnrArgs.ticker; } std::vector<SplitPoint> splits; if (jperc && jtok) { Loading Loading @@ -1515,9 +1634,16 @@ jobjectArray anrTimerDump(JNIEnv *env, jclass, jlong ptr) { return r; } jboolean anrTimerSetTime(JNIEnv* env, jclass, jlong ptr, jlong now) { if (!nativeSupportEnabled) return false; // On the Java side, timeouts are expressed in milliseconds and must be converted to // nanoseconds before being passed to the library code. return toService(ptr)->setCurrentTime(milliseconds_to_nanoseconds(now)); } static const JNINativeMethod methods[] = { {"nativeAnrTimerSupported", "()Z", (void*)anrTimerSupported}, {"nativeAnrTimerCreate", "(Ljava/lang/String;Z[I[I)J", (void*)anrTimerCreate}, {"nativeAnrTimerCreate", "(Ljava/lang/String;Z[I[IZ)J", (void*)anrTimerCreate}, {"nativeAnrTimerClose", "(J)I", (void*)anrTimerClose}, {"nativeAnrTimerStart", "(JIIJ)I", (void*)anrTimerStart}, {"nativeAnrTimerCancel", "(JI)Z", (void*)anrTimerCancel}, Loading @@ -1525,6 +1651,7 @@ static const JNINativeMethod methods[] = { {"nativeAnrTimerDiscard", "(JI)Z", (void*)anrTimerDiscard}, {"nativeAnrTimerTrace", "([Ljava/lang/String;)Ljava/lang/String;", (void*)anrTimerTrace}, {"nativeAnrTimerDump", "(J)[Ljava/lang/String;", (void*)anrTimerDump}, {"nativeAnrTimerSetTime", "(JJ)Z", (void*)anrTimerSetTime}, }; } // anonymous namespace Loading
services/tests/servicestests/src/com/android/server/utils/AnrTimerTest.java +148 −87 Original line number Diff line number Diff line Loading @@ -18,33 +18,32 @@ package com.android.server.utils; import static com.google.common.truth.Truth.assertThat; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertNotEquals; import static org.junit.Assert.assertTrue; import static org.junit.Assume.assumeTrue; import android.os.Handler; import android.os.Looper; import android.os.Message; import android.platform.test.annotations.Presubmit; import android.util.Log; import android.platform.test.annotations.Presubmit; import androidx.test.filters.SmallTest; import com.android.internal.annotations.GuardedBy; import org.junit.Ignore; import org.junit.Test; import org.junit.runner.RunWith; import org.junit.runners.Parameterized; import org.junit.runners.Parameterized.Parameters; import java.io.PrintWriter; import java.io.StringWriter; import java.util.ArrayList; import java.util.Arrays; import java.util.Collection; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; @SmallTest @Presubmit @RunWith(Parameterized.class) public class AnrTimerTest { // A log tag. Loading @@ -66,6 +65,11 @@ public class AnrTimerTest { this.uid = uid; this.what = 0; } @Override public String toString() { return String.format("pid=%d uid=%d what=%d", pid, uid, what); } } /** The test helper is a self-contained object for a single test. */ Loading @@ -75,11 +79,12 @@ public class AnrTimerTest { final Handler mHandler; final CountDownLatch mLatch; @GuardedBy("mLock") final ArrayList<TestArg> mMessages; final ArrayList<TestArg> mMessages = new ArrayList<>(); @GuardedBy("mLock") final ArrayList<Thread> mThreads = new ArrayList<>(); Helper(int expect) { mHandler = new Handler(Looper.getMainLooper(), this::expirationHandler); mMessages = new ArrayList<>(); mLatch = new CountDownLatch(expect); } Loading @@ -92,6 +97,7 @@ public class AnrTimerTest { TestArg arg = (TestArg) msg.obj; arg.what = msg.what; mMessages.add(arg); mThreads.add(Thread.currentThread()); mLatch.countDown(); return false; } Loading @@ -102,6 +108,15 @@ public class AnrTimerTest { return mLatch.await(timeout, TimeUnit.MILLISECONDS); } /** * Return the number of messages so far. */ int size() { synchronized (mLock) { return mMessages.size(); } } /** * Fetch the received messages. Fail if the count of received messages is other than the * expected count. Loading @@ -112,18 +127,30 @@ public class AnrTimerTest { return mMessages.toArray(new TestArg[expected]); } } /** * Fetch the threads that delivered the messages. */ Thread[] threads() { synchronized (mLock) { return mThreads.toArray(new Thread[mThreads.size()]); } } } /** * An instrumented AnrTimer. */ private class TestAnrTimer extends AnrTimer<TestArg> { private TestAnrTimer(Handler h, int key, String tag) { super(h, key, tag, new AnrTimer.Args().enable(mEnabled)); private TestAnrTimer(Handler h, int key, String tag, boolean enable, boolean testMode) { super(h, key, tag, new AnrTimer.Args().enable(enable).testMode(testMode)); } TestAnrTimer(Helper helper, boolean enable, boolean testMode) { this(helper.mHandler, MSG_TIMEOUT, caller(), enable, testMode); } TestAnrTimer(Helper helper) { this(helper.mHandler, MSG_TIMEOUT, caller()); TestAnrTimer(Helper helper, boolean enable) { this(helper, enable, false); } @Override Loading Loading @@ -152,91 +179,110 @@ public class AnrTimerTest { assertThat(actual.what).isEqualTo(MSG_TIMEOUT); } @Parameters(name = "featureEnabled={0}") public static Collection<Object[]> data() { return Arrays.asList(new Object[][] { {false}, {true} }); } /** True if the feature is enabled. */ private boolean mEnabled; public AnrTimerTest(boolean featureEnabled) { mEnabled = featureEnabled; } /** * Verify that a simple expiration succeeds. The timer is started for 10ms. The test * procedure waits 5s for the expiration message, but under correct operation, the test will * only take 10ms */ @Test public void testSimpleTimeout() throws Exception { private void testSimpleTimeout(boolean enable) throws Exception { Helper helper = new Helper(1); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { // One-time check that the injector is working as expected. assertThat(mEnabled).isEqualTo(timer.serviceEnabled()); assertThat(enable).isEqualTo(timer.serviceEnabled()); TestArg t = new TestArg(1, 1); timer.start(t, 10); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(1); validate(t, result[0]); } } @Test public void testSimpleTimeoutDisabled() throws Exception { testSimpleTimeout(false); } @Test public void testSimpleTimeoutEnabled() throws Exception { testSimpleTimeout(true); } /** * Verify that a restarted timer is delivered exactly once. The initial timer value is very * large, to ensure it does not expire before the timer can be restarted. */ @Test public void testTimerRestart() throws Exception { private void testTimerRestart(boolean enable) throws Exception { Helper helper = new Helper(1); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { TestArg t = new TestArg(1, 1); timer.start(t, 10000); // Briefly pause. assertThat(helper.await(10)).isFalse(); timer.start(t, 10); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(1); validate(t, result[0]); } } @Test public void testTimerRestartDisabled() throws Exception { testTimerRestart(false); } @Test public void testTimerRestartEnabled() throws Exception { testTimerRestart(true); } /** * Verify that a restarted timer is delivered exactly once. The initial timer value is very * large, to ensure it does not expire before the timer can be restarted. * Verify that a zero timeout is delivered on a different thread. Repeat with a negative * timeout. The order in which the timers are delivered is unpredictable (it is based on CPU * time during the test), so it is not checked. */ @Test public void testTimerZero() throws Exception { Helper helper = new Helper(1); try (TestAnrTimer timer = new TestAnrTimer(helper)) { TestArg t = new TestArg(1, 1); timer.start(t, 0); // Delivery is immediate but occurs on a different thread. private void testTimerZero(boolean enable) throws Exception { Helper helper = new Helper(2); try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { TestArg t1 = new TestArg(1, 1); timer.start(t1, 0); TestArg t2 = new TestArg(1, 2); timer.start(t2, -5); assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(1); validate(t, result[0]); assertEquals(2, helper.size()); Thread[] threads = helper.threads(); Thread me = Thread.currentThread(); assertNotEquals(me, threads[0]); assertNotEquals(me, threads[1]); } } @Test public void testTimerZeroDisabled() throws Exception { testTimerZero(false); } @Test public void testTimerZeroEnabled() throws Exception { testTimerZero(true); } /** * Verify that if three timers are scheduled on a single AnrTimer, they are delivered in time * order. */ @Test public void testMultipleTimers() throws Exception { private void testMultipleTimers(boolean enable) throws Exception { // Expect three messages. Helper helper = new Helper(3); TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { timer.start(t1, 50); timer.start(t2, 60); timer.start(t3, 40); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(3); validate(t3, result[0]); Loading @@ -245,51 +291,76 @@ public class AnrTimerTest { } } @Test public void testMultipleTimersDisabled() throws Exception { testMultipleTimers(false); } @Test public void testMultipleTimersEnabled() throws Exception { testMultipleTimers(true); } /** * Verify that if three timers are scheduled on three separate AnrTimers, they are delivered * in time order. * Verify that a canceled timer is not delivered. */ @Test public void testMultipleServices() throws Exception { // Expect three messages. Helper helper = new Helper(3); private void testCancelTimer(boolean enable) throws Exception { // Expect two messages. Helper helper = new Helper(2); TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer x1 = new TestAnrTimer(helper); TestAnrTimer x2 = new TestAnrTimer(helper); TestAnrTimer x3 = new TestAnrTimer(helper)) { x1.start(t1, 50); x2.start(t2, 60); x3.start(t3, 40); try (TestAnrTimer timer = new TestAnrTimer(helper, enable)) { timer.start(t1, 200); timer.start(t2, 300); timer.start(t3, 100); // Briefly pause. assertThat(helper.await(10)).isFalse(); timer.cancel(t1); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); TestArg[] result = helper.messages(3); TestArg[] result = helper.messages(2); validate(t3, result[0]); validate(t1, result[1]); validate(t2, result[2]); validate(t2, result[1]); } } @Test public void testCancelTimerDisabled() throws Exception { testCancelTimer(false); } @Test public void testCancelTimerEnabled() throws Exception { testCancelTimer(true); } /** * Verify that a canceled timer is not delivered. * Test the new manual-clock AnrTimer. This is only tested with the feature enabled. */ @Test public void testCancelTimer() throws Exception { public void testManualClock() throws Exception { assumeTrue(AnrTimer.nativeTimersSupported()); // Expect two messages. Helper helper = new Helper(2); TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, true, true)) { timer.start(t1, 50); timer.start(t2, 60); timer.start(t3, 40); assertEquals(0, helper.size()); // Briefly pause. assertThat(helper.await(10)).isFalse(); timer.setTime(10); assertEquals(0, helper.size()); timer.cancel(t1); // Delivery is immediate but occurs on a different thread. assertThat(helper.await(5000)).isTrue(); timer.setTime(70); assertThat(helper.await(1000)).isTrue(); TestArg[] result = helper.messages(2); validate(t3, result[0]); validate(t2, result[1]); Loading @@ -312,7 +383,7 @@ public class AnrTimerTest { */ @Test public void testDumpOutput() throws Exception { if (!AnrTimer.nativeTimersSupported()) return; assumeTrue(AnrTimer.nativeTimersSupported()); // The timers in this class are named "class.method". final String timerName = "timer: com.android.server.utils.AnrTimerTest"; Loading @@ -324,18 +395,15 @@ public class AnrTimerTest { TestArg t1 = new TestArg(1, 1); TestArg t2 = new TestArg(1, 2); TestArg t3 = new TestArg(1, 3); try (TestAnrTimer timer = new TestAnrTimer(helper)) { try (TestAnrTimer timer = new TestAnrTimer(helper, true, true)) { timer.start(t1, 5000); timer.start(t2, 5000); timer.start(t3, 5000); // Do not advance the clock. String r2 = getDumpOutput(); // There are timers in the list if and only if the feature is enabled. if (mEnabled) { assertThat(r2).contains(timerName); } else { assertThat(r2).doesNotContain(timerName); } } String r3 = getDumpOutput(); Loading @@ -350,8 +418,6 @@ public class AnrTimerTest { @Ignore @Test public void testGarbageCollection() throws Exception { if (!mEnabled) return; String r1 = getDumpOutput(); assertThat(r1).doesNotContain("timer:"); Loading @@ -361,18 +427,13 @@ public class AnrTimerTest { TestArg t3 = new TestArg(1, 3); // The timer is explicitly not closed. It is, however, scoped to the next block. { TestAnrTimer timer = new TestAnrTimer(helper); TestAnrTimer timer = new TestAnrTimer(helper, true); timer.start(t1, 5000); timer.start(t2, 5000); timer.start(t3, 5000); String r2 = getDumpOutput(); // There are timers in the list if and only if the feature is enabled. if (mEnabled) { assertThat(r2).contains("timer:"); } else { assertThat(r2).doesNotContain("timer:"); } } // Try to make finalizers run. The timer object above should be a candidate. Finalizers Loading