利用Hander的日志优化性能

在低端机上，使用过traceview，systrace,handler的日志来优化性能，最有效果的是利用Handler日志来优化.最近在喜马拉雅的pad移植我们的APP，发现页面比较卡顿，但APP上很流畅.但是老板觉得其他APP在pad上比较流畅，我们的APP也能做到，所以分派下来优化性能.Android Stduio的profiler是分析卡顿耗时的利器，但是一旦开启profier，app直接卡死，没想到profiler对性能影响这么大.利用systrace，就得插桩设置section，给所有方法插装不太现实，所以这个方案也抛弃了.那么最后只剩下Handler了，打印主线程耗时的地方，因为卡顿基本和主线程有关.用过之后，是真的好用.

这个功能分为两个内容,

如何判断一个message的执行开始和结束

在Handler执行Message的源码中，有message执行的对开的开始和结束标志

  public static void loop() {final Looper me = myLooper();if (me == null) {throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");}final MessageQueue queue = me.mQueue;// Make sure the identity of this thread is that of the local process,// and keep track of what that identity token actually is.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 blockif (msg == null) {// No message indicates that the message queue is quitting.return;}// This must be in a local variable, in case a UI event sets the loggerfinal Printer logging = me.mLogging;if (logging != null) {//message执行开始 ==============logging.println(">>>>> Dispatching to " + msg.target + " " +msg.callback + ": " + msg.what);}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 dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;final long dispatchEnd;try {msg.target.dispatchMessage(msg);dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;} finally {if (traceTag != 0) {Trace.traceEnd(traceTag);}}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) {//message执行结束 ==============logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);}// Make sure that during the course of dispatching the// identity of the thread wasn't corrupted.final long newIdent = Binder.clearCallingIdentity();if (ident != newIdent) {Log.wtf(TAG, "Thread identity changed from 0x"+ Long.toHexString(ident) + " to 0x"+ Long.toHexString(newIdent) + " while dispatching to "+ msg.target.getClass().getName() + " "+ msg.callback + " what=" + msg.what);}msg.recycleUnchecked();}}

根据这个原理，给Looper设置我们自己的logPrinter

 Looper.getMainLooper().setMessageLogging(new LogMonitorPrinter(Log.DEBUG, "Monitor"));

LogMonitorPrinter的源码如下

import android.os.Looper;
import android.util.Log;
import android.util.LogPrinter;/*** @auther:**** @date:2022/1/12*/
public class LogMonitorPrinter extends LogPrinter {static final String TAG = "LogMonitorPrinter";/*** Create a new Printer that sends to the log with the given priority* and tag.** @param priority The desired log priority:*                 {@link Log#VERBOSE Log.VERBOSE},*                 {@link Log#DEBUG Log.DEBUG},*                 {@link Log#INFO Log.INFO},*                 {@link Log#WARN Log.WARN}, or*                 {@link Log#ERROR Log.ERROR}.* @param tag      A string tag to associate with each printed log statement.*/public LogMonitorPrinter(int priority, String tag) {super(priority, tag);}@Overridepublic void println(String x) {if (x.startsWith(">>>>> Dispatching to")) {LogMonitor.getIntance().startMonitor();}if (x.startsWith("<<<<< Finished to")) {LogMonitor.getIntance().removeMonitor();}super.println(x);}}

如何获取当前message的堆栈.

这里利用一个小技巧，我们利用HandlerThread在异步线程中类似检测anr的方式,在阈值内如果打印，则移除callback，否则执行callback打印main looper的堆栈信息.

import android.os.Handler;
import android.os.HandlerThread;
import android.os.Looper;
import android.util.Log;/*** @auther:**** @date:2022/1/14*/
public class LogMonitor {private static volatile LogMonitor intance = null;public synchronized static LogMonitor getIntance() {if (intance == null) {synchronized (LogMonitor.class) {if (intance == null) {intance = new LogMonitor();}}}return intance;}private Handler mIogHandler;private static final long TIME_BLOCK = 300L;private LogMonitor() {//Handy class for starting a new thread that has a looper. The looper can then be used to create handler classes.HandlerThread mLogThread = new HandlerThread("log");mLogThread.start(); //Note that start() must still be called.mIogHandler = new Handler(mLogThread.getLooper());}private static Runnable mLogRunnable = () -> {StringBuilder sb = new StringBuilder();StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();for (StackTraceElement s : stackTrace) {sb.append(s.toString()).append("\n");}Log.w(LogMonitorPrinter.TAG, sb.toString());};public void startMonitor() {mIogHandler.postDelayed(mLogRunnable, TIME_BLOCK);}public void removeMonitor() {mIogHandler.removeCallbacks(mLogRunnable);}
}

实战效果，在Application的onCreate中进行设置，基本上能打印了在主线程耗时的方法.有复杂布局，有binder调用，有数据库读写，还有大bitmap处理.我们根据需要优化，启动性能提升了4s左右.还有一个额外收益，因为设置了logPrinter，Looper其他日志信息的在我们的进程中也能看到了.我们查到我们的一个接口请求的开始-->回调的返回耗时（一般接口数据返回，用Hanlder切回主线程来刷新UI）远大于实际接口的请求返回数据的耗时，是因为这个message被其他的message block了.然后我们利用Handler的

sendMessageAtTime(msg, 0)

postAtFrontOfQueue()

让我们的message排到队头，优先执行，最快刷新UI，优化我们关键的message被其他message block的现象.message的执行优先级，可以看这篇文章Android 实战中提高Handler发送消息的优先级

当然这在中高端机型上基本上不太可能出现这个情况.