Merge "Log slow message delivery on Looper" into pi-dev (14186bfe) · Commits · e / os / android_frameworks_base

core/java/android/os/Looper.java

+70 −15

Original line number	Diff line number	Diff line
		@@ -77,9 +77,17 @@ public final class Looper {
		private Printer mLogging;
		private long mTraceTag;

		/* If set, the looper will show a warning log if a message dispatch takes longer than time. */
		/**
		* If set, the looper will show a warning log if a message dispatch takes longer than this.
		*/
		private long mSlowDispatchThresholdMs;

		/**
		* If set, the looper will show a warning log if a message delivery (actual delivery time -
		* post time) takes longer than this.
		*/
		private long mSlowDeliveryThresholdMs;

		/** Initialize the current thread as a looper.
		* This gives you a chance to create handlers that then reference
		* this looper, before actually starting the loop. Be sure to call
		@@ -138,6 +146,16 @@ public final class Looper {
		Binder.clearCallingIdentity();
		final long ident = Binder.clearCallingIdentity();

		// Allow overriding a threshold with a system prop. e.g.
		// adb shell 'setprop log.looper.1000.main.slow 1 && stop && start'
		final int thresholdOverride =
		SystemProperties.getInt("log.looper."
		+ Process.myUid() + "."
		+ Thread.currentThread().getName()
		+ ".slow", 0);

		boolean slowDeliveryDetected = false;

		for (;;) {
		Message msg = queue.next(); // might block
		if (msg == null) {
		@@ -152,30 +170,50 @@ public final class Looper {
		msg.callback + ": " + msg.what);
		}

		final long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;

		final long traceTag = me.mTraceTag;
		long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
		long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;
		if (thresholdOverride > 0) {
		slowDispatchThresholdMs = thresholdOverride;
		slowDeliveryThresholdMs = thresholdOverride;
		}
		final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);
		final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);

		final boolean needStartTime = logSlowDelivery \|\| logSlowDispatch;
		final boolean needEndTime = logSlowDispatch;

		if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
		Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
		}
		final long start = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
		final long end;

		final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
		final long dispatchEnd;
		try {
		msg.target.dispatchMessage(msg);
		end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
		dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
		} finally {
		if (traceTag != 0) {
		Trace.traceEnd(traceTag);
		}
		}
		if (slowDispatchThresholdMs > 0) {
		final long time = end - start;
		if (time > slowDispatchThresholdMs) {
		Slog.w(TAG, "Dispatch took " + time + "ms on "
		+ Thread.currentThread().getName() + ", h=" +
		msg.target + " cb=" + msg.callback + " msg=" + msg.what);
		if (logSlowDelivery) {
		if (slowDeliveryDetected) {
		if ((dispatchStart - msg.when) <= 10) {
		Slog.w(TAG, "Drained");
		slowDeliveryDetected = false;
		}
		} else {
		if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",
		msg)) {
		// Once we write a slow delivery log, suppress until the queue drains.
		slowDeliveryDetected = true;
		}
		}
		}
		if (logSlowDispatch) {
		showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);
		}

		if (logging != null) {
		logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
		@@ -196,6 +234,19 @@ public final class Looper {
		}
		}

		private static boolean showSlowLog(long threshold, long measureStart, long measureEnd,
		String what, Message msg) {
		final long actualTime = measureEnd - measureStart;
		if (actualTime < threshold) {
		return false;
		}
		// For slow delivery, the current message isn't really important, but log it anyway.
		Slog.w(TAG, "Slow " + what + " took " + actualTime + "ms "
		+ Thread.currentThread().getName() + " h="
		+ msg.target.getClass().getName() + " c=" + msg.callback + " m=" + msg.what);
		return true;
		}

		/**
		* Return the Looper object associated with the current thread. Returns
		* null if the calling thread is not associated with a Looper.
		@@ -243,9 +294,13 @@ public final class Looper {
		mTraceTag = traceTag;
		}

		/** {@hide} */
		public void setSlowDispatchThresholdMs(long slowDispatchThresholdMs) {
		/**
		* Set a thresholds for slow dispatch/delivery log.
		* {@hide}
		*/
		public void setSlowLogThresholdMs(long slowDispatchThresholdMs, long slowDeliveryThresholdMs) {
		mSlowDispatchThresholdMs = slowDispatchThresholdMs;
		mSlowDeliveryThresholdMs = slowDeliveryThresholdMs;
		}

		/**

core/java/com/android/internal/os/BackgroundThread.java

+7 −1

Original line number	Diff line number	Diff line
		@@ -18,12 +18,15 @@ package com.android.internal.os;

		import android.os.Handler;
		import android.os.HandlerThread;
		import android.os.Looper;
		import android.os.Trace;

		/**
		* Shared singleton background thread for each process.
		*/
		public final class BackgroundThread extends HandlerThread {
		private static final long SLOW_DISPATCH_THRESHOLD_MS = 10_000;
		private static final long SLOW_DELIVERY_THRESHOLD_MS = 30_000;
		private static BackgroundThread sInstance;
		private static Handler sHandler;

		@@ -35,7 +38,10 @@ public final class BackgroundThread extends HandlerThread {
		if (sInstance == null) {
		sInstance = new BackgroundThread();
		sInstance.start();
		sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
		final Looper looper = sInstance.getLooper();
		looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
		looper.setSlowLogThresholdMs(
		SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
		sHandler = new Handler(sInstance.getLooper());
		}
		}

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

+8 −1

Original line number	Diff line number	Diff line
		@@ -17,6 +17,7 @@
		package com.android.server;

		import android.os.Handler;
		import android.os.Looper;
		import android.os.Trace;

		/**
		@@ -28,6 +29,9 @@ import android.os.Trace;
		* to be delayed for a user-noticeable amount of time.
		*/
		public final class FgThread extends ServiceThread {
		private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
		private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;

		private static FgThread sInstance;
		private static Handler sHandler;

		@@ -39,7 +43,10 @@ public final class FgThread extends ServiceThread {
		if (sInstance == null) {
		sInstance = new FgThread();
		sInstance.start();
		sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
		final Looper looper = sInstance.getLooper();
		looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
		looper.setSlowLogThresholdMs(
		SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
		sHandler = new Handler(sInstance.getLooper());
		}
		}

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

+3 −1

Original line number	Diff line number	Diff line
		@@ -28,6 +28,7 @@ import android.os.Trace;
		*/
		public final class UiThread extends ServiceThread {
		private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
		private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;
		private static UiThread sInstance;
		private static Handler sHandler;

		@@ -48,7 +49,8 @@ public final class UiThread extends ServiceThread {
		sInstance.start();
		final Looper looper = sInstance.getLooper();
		looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
		looper.setSlowDispatchThresholdMs(SLOW_DISPATCH_THRESHOLD_MS);
		looper.setSlowLogThresholdMs(
		SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
		sHandler = new Handler(sInstance.getLooper());
		}
		}

services/java/com/android/server/SystemServer.java

+5 −0

Original line number	Diff line number	Diff line
		@@ -156,6 +156,9 @@ public final class SystemServer {
		// give any timezone code room without going into negative time.
		private static final long EARLIEST_SUPPORTED_TIME = 86400 * 1000;

		private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
		private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;

		/*
		* Implementation class names. TODO: Move them to a codegen class or load
		* them from the build system somehow.
		@@ -396,6 +399,8 @@ public final class SystemServer {
		android.os.Process.THREAD_PRIORITY_FOREGROUND);
		android.os.Process.setCanSelfBackground(false);
		Looper.prepareMainLooper();
		Looper.getMainLooper().setSlowLogThresholdMs(
		SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);

		// Initialize native services.
		System.loadLibrary("android_servers");