利用Hander的日志优化性能

快乐的编码小猪

已于 2022-01-24 19:34:55 修改

阅读量346

点赞数

分类专栏： Android 文章标签： android Handler 性能优化

于 2022-01-24 16:35:47 首次发布

本文链接：https://blog.csdn.net/hanshengjian/article/details/104527880

版权

Android 专栏收录该内容

28 篇文章 0 订阅

订阅专栏

在低端机上，使用过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 block
            if (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 logger
            final 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);
    }


    @Override
    public 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的