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

Merge "Log slow message delivery on Looper" into pi-dev

Browse Source
This commit is contained in:
Makoto Onuki
2018-04-30 17:50:58 +00:00
committed by Android (Google) Code Review
parent 8512aa4dda 712886fd97
commit 14186bfe08
5 changed files with 93 additions and 18 deletions
Download Patch File Download Diff File Expand all files Collapse all files

85
core/java/android/os/Looper.java
View File

@@ -77,10 +77,18 @@ 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;
/** Initialize the current thread as a looper.
/**
* 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
* {@link #loop()} after calling this method, and end it by calling
@@ -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;
}
/**

8
core/java/com/android/internal/os/BackgroundThread.java
View File

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

9
services/core/java/com/android/server/FgThread.java
View File

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

4
services/core/java/com/android/server/UiThread.java
View File

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

5
services/java/com/android/server/SystemServer.java
View File

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