Merge "Update AnrTimer statistics" into main (13aa3806) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/utils/AnrTimer.java

+46 −19

Original line number	Diff line number	Diff line
		@@ -40,6 +40,7 @@ import java.lang.ref.WeakReference;
		import java.io.PrintWriter;
		import java.util.Arrays;
		import java.util.ArrayList;
		import java.util.Comparator;
		import java.util.Objects;

		/**
		@@ -211,10 +212,6 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		@GuardedBy("mLock")
		private int mTotalStarted = 0;

		/** The total number of timers that were restarted without an explicit cancel. */
		@GuardedBy("mLock")
		private int mTotalRestarted = 0;

		/** The total number of errors detected. */
		@GuardedBy("mLock")
		private int mTotalErrors = 0;
		@@ -368,7 +365,7 @@ public abstract class AnrTimer<V> implements AutoCloseable {

		abstract boolean enabled();

		abstract void dump(PrintWriter pw, boolean verbose);
		abstract void dump(IndentingPrintWriter pw, boolean verbose);

		abstract void close();
		}
		@@ -410,9 +407,14 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		return false;
		}

		/** dump() is a no-op when the feature is disabled. */
		/** Dump the limited statistics captured when the feature is disabled. */
		@Override
		void dump(PrintWriter pw, boolean verbose) {
		void dump(IndentingPrintWriter pw, boolean verbose) {
		synchronized (mLock) {
		pw.format("started=%d maxStarted=%d running=%d expired=%d errors=%d\n",
		mTotalStarted, mMaxStarted, mTimerIdMap.size(),
		mTotalExpired, mTotalErrors);
		}
		}

		/** close() is a no-op when the feature is disabled. */
		@@ -441,6 +443,10 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		*/
		private long mNative = 0;

		/** The total number of timers that were restarted without an explicit cancel. */
		@GuardedBy("mLock")
		private int mTotalRestarted = 0;

		/** Fetch the native tag (an integer) for the given label. */
		FeatureEnabled() {
		mNative = nativeAnrTimerCreate(mLabel);
		@@ -537,13 +543,22 @@ public abstract class AnrTimer<V> implements AutoCloseable {

		/** Dump statistics from the native layer. */
		@Override
		void dump(PrintWriter pw, boolean verbose) {
		void dump(IndentingPrintWriter pw, boolean verbose) {
		synchronized (mLock) {
		if (mNative != 0) {
		nativeAnrTimerDump(mNative, verbose);
		} else {
		if (mNative == 0) {
		pw.println("closed");
		return;
		}
		String[] nativeDump = nativeAnrTimerDump(mNative);
		if (nativeDump == null) {
		pw.println("no-data");
		return;
		}
		for (String s : nativeDump) {
		pw.println(s);
		}
		// The following counter is only available at the Java level.
		pw.println("restarted:" + mTotalRestarted);
		}
		}

		@@ -690,11 +705,8 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		synchronized (mLock) {
		pw.format("timer: %s\n", mLabel);
		pw.increaseIndent();
		pw.format("started=%d maxStarted=%d restarted=%d running=%d expired=%d errors=%d\n",
		mTotalStarted, mMaxStarted, mTotalRestarted, mTimerIdMap.size(),
		mTotalExpired, mTotalErrors);
		pw.decreaseIndent();
		mFeature.dump(pw, false);
		pw.decreaseIndent();
		}
		}

		@@ -755,6 +767,14 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		recordErrorLocked(operation, "notFound", arg);
		}

		/** Compare two AnrTimers in display order. */
		private static final Comparator<AnrTimer> sComparator =
		Comparator.nullsLast(new Comparator<>() {
		@Override
		public int compare(AnrTimer o1, AnrTimer o2) {
		return o1.mLabel.compareTo(o2.mLabel);
		}});

		/** Dumpsys output, allowing for overrides. */
		@VisibleForTesting
		static void dump(@NonNull PrintWriter pw, boolean verbose, @NonNull Injector injector) {
		@@ -764,11 +784,18 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		ipw.println("AnrTimer statistics");
		ipw.increaseIndent();
		synchronized (sAnrTimerList) {
		// Find the currently live instances and sort them by their label. The goal is to
		// have consistent output ordering.
		final int size = sAnrTimerList.size();
		ipw.println("reporting " + size + " timers");
		AnrTimer[] active = new AnrTimer[size];
		int valid = 0;
		for (int i = 0; i < size; i++) {
		AnrTimer a = sAnrTimerList.valueAt(i).get();
		if (a != null) a.dump(ipw);
		if (a != null) active[valid++] = a;
		}
		Arrays.sort(active, 0, valid, sComparator);
		for (int i = 0; i < valid; i++) {
		if (active[i] != null) active[i].dump(ipw);
		}
		}
		if (verbose) dumpErrors(ipw);
		@@ -827,6 +854,6 @@ public abstract class AnrTimer<V> implements AutoCloseable {
		/** Discard an expired timer by ID. Return true if the timer was found. */
		private static native boolean nativeAnrTimerDiscard(long service, int timerId);

		/** Prod the native library to log a few statistics. */
		private static native void nativeAnrTimerDump(long service, boolean verbose);
		/** Retrieve runtime dump information from the native layer. */
		private static native String[] nativeAnrTimerDump(long service);
		}

services/core/jni/com_android_server_utils_AnrTimer.cpp

+65 −35

Original line number	Diff line number	Diff line
		@@ -161,14 +161,14 @@ class AnrTimerService {
		// A timer has expired.
		void expire(timer_id_t);

		// Dump a small amount of state to the log file.
		void dump(bool verbose) const;

		// Return the Java object associated with this instance.
		jweak jtimer() const {
		return notifierObject_;
		}

		// Return the per-instance statistics.
		std::vector<std::string> getDump() const;

		private:
		// The service cannot be copied.
		AnrTimerService(AnrTimerService const &) = delete;
		@@ -199,7 +199,7 @@ class AnrTimerService {
		std::set<Timer> running_;

		// The maximum number of active timers.
		size_t maxActive_;
		size_t maxRunning_;

		// Simple counters
		struct Counters {
		@@ -209,6 +209,7 @@ class AnrTimerService {
		size_t accepted;
		size_t discarded;
		size_t expired;
		size_t extended;

		// The number of times there were zero active timers.
		size_t drained;
		@@ -437,7 +438,9 @@ class AnrTimerService::Ticker {

		// Construct the ticker. This creates the timerfd file descriptor and starts the monitor
		// thread. The monitor thread is given a unique name.
		Ticker() {
		Ticker() :
		id_(idGen_.fetch_add(1))
		{
		timerFd_ = timer_create();
		if (timerFd_ < 0) {
		ALOGE("failed to create timerFd: %s", strerror(errno));
		@@ -502,6 +505,11 @@ class AnrTimerService::Ticker {
		}
		}

		// The unique ID of this particular ticker. Used for debug and logging.
		size_t id() const {
		return id_;
		}

		// Return the number of timers still running.
		size_t running() const {
		AutoMutex _l(lock_);
		@@ -617,8 +625,16 @@ class AnrTimerService::Ticker {
		// The list of timers that are scheduled. This set is sorted by timeout and then by timer
		// ID. A set is sufficient (as opposed to a multiset) because timer IDs are unique.
		std::set<Entry> running_;

		// A unique ID assigned to this instance.
		const size_t id_;

		// The ID generator.
		static std::atomic<size_t> idGen_;
		};

		std::atomic<size_t> AnrTimerService::Ticker::idGen_;


		AnrTimerService::AnrTimerService(char const* label,
		notifier_t notifier, void* cookie, jweak jtimer, Ticker* ticker) :
		@@ -629,7 +645,7 @@ AnrTimerService::AnrTimerService(char const* label,
		ticker_(ticker) {

		// Zero the statistics
		maxActive_ = 0;
		maxRunning_ = 0;
		memset(&counters_, 0, sizeof(counters_));

		ALOGI_IF(DEBUG, "initialized %s", label);
		@@ -739,6 +755,12 @@ void AnrTimerService::expire(timer_id_t timerId) {
		elapsed = now() - t.started;
		}

		if (expired) {
		counters_.expired++;
		} else {
		counters_.extended++;
		}

		// Deliver the notification outside of the lock.
		if (expired) {
		if (!notifier_(timerId, pid, uid, elapsed, notifierCookie_, notifierObject_)) {
		@@ -756,8 +778,8 @@ void AnrTimerService::insert(const Timer& t) {
		if (t.status == Running) {
		// Only forward running timers to the ticker. Expired timers are handled separately.
		ticker_->insert(t.scheduled, t.id, this);
		maxActive_ = std::max(maxActive_, running_.size());
		}
		maxRunning_ = std::max(maxRunning_, running_.size());
		}

		AnrTimerService::Timer AnrTimerService::remove(timer_id_t timerId) {
		@@ -767,29 +789,32 @@ AnrTimerService::Timer AnrTimerService::remove(timer_id_t timerId) {
		Timer result = *found;
		running_.erase(found);
		ticker_->remove(result.scheduled, result.id);
		if (running_.size() == 0) counters_.drained++;
		return result;
		}
		return Timer();
		}

		void AnrTimerService::dump(bool verbose) const {
		std::vector<std::string> AnrTimerService::getDump() const {
		std::vector<std::string> r;
		AutoMutex _l(lock_);
		ALOGI("timer %s ops started=%zu canceled=%zu accepted=%zu discarded=%zu expired=%zu",
		label_.c_str(),
		counters_.started, counters_.canceled, counters_.accepted,
		counters_.discarded, counters_.expired);
		ALOGI("timer %s stats max-active=%zu/%zu running=%zu/%zu errors=%zu",
		label_.c_str(),
		maxActive_, ticker_->maxRunning(), running_.size(), ticker_->running(),
		counters_.error);

		if (verbose) {
		nsecs_t time = now();
		for (auto i = running_.begin(); i != running_.end(); i++) {
		Timer t = *i;
		ALOGI(" running %s", t.toString(time).c_str());
		}
		}
		r.push_back(StringPrintf("started:%zu canceled:%zu accepted:%zu discarded:%zu expired:%zu",
		counters_.started,
		counters_.canceled,
		counters_.accepted,
		counters_.discarded,
		counters_.expired));
		r.push_back(StringPrintf("extended:%zu drained:%zu error:%zu running:%zu maxRunning:%zu",
		counters_.extended,
		counters_.drained,
		counters_.error,
		running_.size(),
		maxRunning_));
		r.push_back(StringPrintf("ticker:%zu ticking:%zu maxTicking:%zu",
		ticker_->id(),
		ticker_->running(),
		ticker_->maxRunning()));
		return r;
		}

		/**
		@@ -894,10 +919,15 @@ jboolean anrTimerDiscard(JNIEnv* env, jclass, jlong ptr, jint timerId) {
		return toService(ptr)->discard(timerId);
		}

		jint anrTimerDump(JNIEnv *env, jclass, jlong ptr, jboolean verbose) {
		if (!nativeSupportEnabled) return -1;
		toService(ptr)->dump(verbose);
		return 0;
		jobjectArray anrTimerDump(JNIEnv *env, jclass, jlong ptr) {
		if (!nativeSupportEnabled) return nullptr;
		std::vector<std::string> stats = toService(ptr)->getDump();
		jclass sclass = env->FindClass("java/lang/String");
		jobjectArray r = env->NewObjectArray(stats.size(), sclass, nullptr);
		for (size_t i = 0; i < stats.size(); i++) {
		env->SetObjectArrayElement(r, i, env->NewStringUTF(stats[i].c_str()));
		}
		return r;
		}

		static const JNINativeMethod methods[] = {
		@@ -908,7 +938,7 @@ static const JNINativeMethod methods[] = {
		{"nativeAnrTimerCancel", "(JI)Z", (void*) anrTimerCancel},
		{"nativeAnrTimerAccept", "(JI)Z", (void*) anrTimerAccept},
		{"nativeAnrTimerDiscard", "(JI)Z", (void*) anrTimerDiscard},
		{"nativeAnrTimerDump", "(JZ)V", (void*) anrTimerDump},
		{"nativeAnrTimerDump", "(J)[Ljava/lang/String;", (void*) anrTimerDump},
		};

		} // anonymous namespace