Merge "Add stats logging to ServiceManager and NPMS" into pi-dev (a26e7559) · Commits · e / os / android_frameworks_base

Android.bp

+1 −0

Original line number	Diff line number	Diff line
		@@ -603,6 +603,7 @@ java_library {
		"core/java/android/content/EventLogTags.logtags",
		"core/java/android/speech/tts/EventLogTags.logtags",
		"core/java/android/net/EventLogTags.logtags",
		"core/java/android/os/EventLogTags.logtags",
		"core/java/android/webkit/EventLogTags.logtags",
		"core/java/com/android/internal/app/EventLogTags.logtags",
		"core/java/com/android/internal/logging/EventLogTags.logtags",

core/java/android/os/EventLogTags.logtags

0 → 100644

+6 −0

Original line number	Diff line number	Diff line
		# See system/core/logcat/event.logtags for a description of the format of this file.

		option java_package android.os

		230000 service_manager_stats (call_count\|1),(total_time\|1\|3),(duration\|1\|3)
		230001 service_manager_slow (time\|1\|3),(service\|3)

core/java/android/os/ServiceManager.java

+125 −1

Original line number	Diff line number	Diff line
		@@ -18,7 +18,9 @@ package android.os;

		import android.util.Log;

		import com.android.internal.annotations.GuardedBy;
		import com.android.internal.os.BinderInternal;
		import com.android.internal.util.StatLogger;

		import java.util.HashMap;
		import java.util.Map;
		@@ -26,9 +28,76 @@ import java.util.Map;
		/** @hide */
		public final class ServiceManager {
		private static final String TAG = "ServiceManager";
		private static final Object sLock = new Object();

		private static IServiceManager sServiceManager;

		/**
		* Cache for the "well known" services, such as WM and AM.
		*/
		private static HashMap<String, IBinder> sCache = new HashMap<String, IBinder>();

		/**
		* We do the "slow log" at most once every this interval.
		*/
		private static final int SLOW_LOG_INTERVAL_MS = 5000;

		/**
		* We do the "stats log" at most once every this interval.
		*/
		private static final int STATS_LOG_INTERVAL_MS = 5000;

		/**
		* Threshold in uS for a "slow" call, used on core UIDs. We use a more relax value to
		* avoid logspam.
		*/
		private static final long GET_SERVICE_SLOW_THRESHOLD_US_CORE =
		SystemProperties.getInt("debug.servicemanager.slow_call_core_ms", 10) * 1000;

		/**
		* Threshold in uS for a "slow" call, used on non-core UIDs. We use a more relax value to
		* avoid logspam.
		*/
		private static final long GET_SERVICE_SLOW_THRESHOLD_US_NON_CORE =
		SystemProperties.getInt("debug.servicemanager.slow_call_ms", 50) * 1000;

		/**
		* We log stats logging ever this many getService() calls.
		*/
		private static final int GET_SERVICE_LOG_EVERY_CALLS_CORE =
		SystemProperties.getInt("debug.servicemanager.log_calls_core", 100);

		/**
		* We log stats logging ever this many getService() calls.
		*/
		private static final int GET_SERVICE_LOG_EVERY_CALLS_NON_CORE =
		SystemProperties.getInt("debug.servicemanager.log_calls", 200);

		@GuardedBy("sLock")
		private static int sGetServiceAccumulatedUs;

		@GuardedBy("sLock")
		private static int sGetServiceAccumulatedCallCount;

		@GuardedBy("sLock")
		private static long sLastStatsLogUptime;

		@GuardedBy("sLock")
		private static long sLastSlowLogUptime;

		@GuardedBy("sLock")
		private static long sLastSlowLogActualTime;

		interface Stats {
		int GET_SERVICE = 0;

		int COUNT = GET_SERVICE + 1;
		}

		public static final StatLogger sStatLogger = new StatLogger(new String[] {
		"getService()",
		});

		private static IServiceManager getIServiceManager() {
		if (sServiceManager != null) {
		return sServiceManager;
		@@ -52,7 +121,7 @@ public final class ServiceManager {
		if (service != null) {
		return service;
		} else {
		return Binder.allowBlocking(getIServiceManager().getService(name));
		return Binder.allowBlocking(rawGetService(name));
		}
		} catch (RemoteException e) {
		Log.e(TAG, "error in getService", e);
		@@ -177,4 +246,59 @@ public final class ServiceManager {
		super("No service published for: " + name);
		}
		}

		private static IBinder rawGetService(String name) throws RemoteException {
		final long start = sStatLogger.getTime();

		final IBinder binder = getIServiceManager().getService(name);

		final int time = (int) sStatLogger.logDurationStat(Stats.GET_SERVICE, start);

		final int myUid = Process.myUid();
		final boolean isCore = UserHandle.isCore(myUid);

		final long slowThreshold = isCore
		? GET_SERVICE_SLOW_THRESHOLD_US_CORE
		: GET_SERVICE_SLOW_THRESHOLD_US_NON_CORE;

		synchronized (sLock) {
		sGetServiceAccumulatedUs += time;
		sGetServiceAccumulatedCallCount++;

		final long nowUptime = SystemClock.uptimeMillis();

		// Was a slow call?
		if (time >= slowThreshold) {
		// We do a slow log:
		// - At most once in every SLOW_LOG_INTERVAL_MS
		// - OR it was slower than the previously logged slow call.
		if ((nowUptime > (sLastSlowLogUptime + SLOW_LOG_INTERVAL_MS))
		\|\| (sLastSlowLogActualTime < time)) {
		EventLogTags.writeServiceManagerSlow(time / 1000, name);

		sLastSlowLogUptime = nowUptime;
		sLastSlowLogActualTime = time;
		}
		}

		// Every GET_SERVICE_LOG_EVERY_CALLS calls, log the total time spent in getService().

		final int logInterval = isCore
		? GET_SERVICE_LOG_EVERY_CALLS_CORE
		: GET_SERVICE_LOG_EVERY_CALLS_NON_CORE;

		if ((sGetServiceAccumulatedCallCount >= logInterval)
		&& (nowUptime >= (sLastStatsLogUptime + STATS_LOG_INTERVAL_MS))) {

		EventLogTags.writeServiceManagerStats(
		sGetServiceAccumulatedCallCount, // Total # of getService() calls.
		sGetServiceAccumulatedUs / 1000, // Total time spent in getService() calls.
		(int) (nowUptime - sLastStatsLogUptime)); // Uptime duration since last log.
		sGetServiceAccumulatedCallCount = 0;
		sGetServiceAccumulatedUs = 0;
		sLastStatsLogUptime = nowUptime;
		}
		}
		return binder;
		}
		}

services/core/java/com/android/server/StatLogger.java→core/java/com/android/internal/util/StatLogger.java

+62 −9

Original line number	Diff line number	Diff line
		@@ -14,14 +14,14 @@
		* limitations under the License.
		*/

		package com.android.server;
		package com.android.internal.util;

		import android.os.SystemClock;
		import android.util.Slog;
		import android.util.proto.ProtoOutputStream;

		import com.android.internal.annotations.GuardedBy;
		import com.android.internal.util.IndentingPrintWriter;
		import com.android.server.StatLoggerProto;
		import com.android.server.StatLoggerProto.Event;

		import java.io.PrintWriter;
		@@ -30,8 +30,6 @@ import java.io.PrintWriter;
		* Simple class to keep track of the number of times certain events happened and their durations for
		* benchmarking.
		*
		* TODO Update shortcut service to switch to it.
		*
		* @hide
		*/
		public class StatLogger {
		@@ -47,12 +45,35 @@ public class StatLogger {
		@GuardedBy("mLock")
		private final long[] mDurationStats;

		@GuardedBy("mLock")
		private final int[] mCallsPerSecond;

		@GuardedBy("mLock")
		private final long[] mDurationPerSecond;

		@GuardedBy("mLock")
		private final int[] mMaxCallsPerSecond;

		@GuardedBy("mLock")
		private final long[] mMaxDurationPerSecond;

		@GuardedBy("mLock")
		private final long[] mMaxDurationStats;

		@GuardedBy("mLock")
		private long mNextTickTime = SystemClock.elapsedRealtime() + 1000;

		private final String[] mLabels;

		public StatLogger(String[] eventLabels) {
		SIZE = eventLabels.length;
		mCountStats = new int[SIZE];
		mDurationStats = new long[SIZE];
		mCallsPerSecond = new int[SIZE];
		mMaxCallsPerSecond = new int[SIZE];
		mDurationPerSecond = new long[SIZE];
		mMaxDurationPerSecond = new long[SIZE];
		mMaxDurationStats = new long[SIZE];
		mLabels = eventLabels;
		}

		@@ -67,19 +88,46 @@ public class StatLogger {

		/**
		* @see {@link #getTime()}
		*
		* @return the duration in microseconds.
		*/
		public void logDurationStat(int eventId, long start) {
		public long logDurationStat(int eventId, long start) {
		synchronized (mLock) {
		final long duration = getTime() - start;
		if (eventId >= 0 && eventId < SIZE) {
		mCountStats[eventId]++;
		mDurationStats[eventId] += (getTime() - start);
		mDurationStats[eventId] += duration;
		} else {
		Slog.wtf(TAG, "Invalid event ID: " + eventId);
		return duration;
		}
		if (mMaxDurationStats[eventId] < duration) {
		mMaxDurationStats[eventId] = duration;
		}

		// Keep track of the per-second max.
		final long nowRealtime = SystemClock.elapsedRealtime();
		if (nowRealtime > mNextTickTime) {
		if (mMaxCallsPerSecond[eventId] < mCallsPerSecond[eventId]) {
		mMaxCallsPerSecond[eventId] = mCallsPerSecond[eventId];
		}
		if (mMaxDurationPerSecond[eventId] < mDurationPerSecond[eventId]) {
		mMaxDurationPerSecond[eventId] = mDurationPerSecond[eventId];
		}

		mCallsPerSecond[eventId] = 0;
		mDurationPerSecond[eventId] = 0;

		mNextTickTime = nowRealtime + 1000;
		}

		mCallsPerSecond[eventId]++;
		mDurationPerSecond[eventId] += duration;

		return duration;
		}
		}

		@Deprecated
		public void dump(PrintWriter pw, String prefix) {
		dump(new IndentingPrintWriter(pw, " ").setIndent(prefix));
		}
		@@ -91,9 +139,14 @@ public class StatLogger {
		for (int i = 0; i < SIZE; i++) {
		final int count = mCountStats[i];
		final double durationMs = mDurationStats[i] / 1000.0;
		pw.println(String.format("%s: count=%d, total=%.1fms, avg=%.3fms",

		pw.println(String.format(
		"%s: count=%d, total=%.1fms, avg=%.3fms, max calls/s=%d max dur/s=%.1fms"
		+ " max time=%.1fms",
		mLabels[i], count, durationMs,
		(count == 0 ? 0 : ((double) durationMs) / count)));
		(count == 0 ? 0 : durationMs / count),
		mMaxCallsPerSecond[i], mMaxDurationPerSecond[i] / 1000.0,
		mMaxDurationStats[i] / 1000.0));
		}
		pw.decreaseIndent();
		}

services/core/java/com/android/server/AlarmManagerService.java

+1 −0

Original line number	Diff line number	Diff line
		@@ -88,6 +88,7 @@ import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.util.ArrayUtils;
		import com.android.internal.util.DumpUtils;
		import com.android.internal.util.LocalLog;
		import com.android.internal.util.StatLogger;
		import com.android.server.AppStateTracker.Listener;

		import java.io.ByteArrayOutputStream;