如何监控项目里所有UI线程的操作(实战,BlockCanary)?

如何监控项目里所有UI线程的操作(实战,BlockCanary)?


背景

我们都知道,Android系统是线程安全的,也就是只有主线才能更新UI。而保持界面的流畅性,就要求界面1秒钟刷新60次以上。也就是16ms需要刷新一次界面。但是在实际开发过程中,有各种各样的原因,无法达到这一指标。尤其是当项目已经成形,需求的不断变更,开发人员的变更、替换,等等,就变成的更为困难。寻找这些影响主线程执行效率的代码,就变成一个优化性能的重要方面。在学习前人的优秀的设计思想和代码实现,下面带着大家一步一步地实战。

原理

先说一下原理,我们都知道,Android是使用Message/Looper/Handler机制来更新UI的。如果在主线程handler的handleMessage方法进行了耗时的操作,界面也就是不能及时更新,即UI卡顿。关键代码如下:
Handler.dispatchMessage()方法

/**
 * Handle system messages here.
 */
public void dispatchMessage(Message msg) {
    if (msg.callback != null) {
        handleCallback(msg);
    } else {
        if (mCallback != null) {
            if (mCallback.handleMessage(msg)) {
                return;
            }
        }
        handleMessage(msg);
    }
}

在来看一下Handler.dispatchMessage是在哪里被调用的,通过查看源码原来是在Looper.loop里调用,这里处主线程理消息队列的Looper。一个线程只有一个Looper,每一个消息都可以持有不同的Handler。也就是,所有的消息都会在这里进行处理和分发。所以只有监控此处就可以了。
Looper.loop()方法

/**
 * Run the message queue in this thread. Be sure to call
 * {@link #quit()} to end the loop.
 */
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();

    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
        Printer logging = me.mLogging;
        if (logging != null) {
            logging.println(">>>>> Dispatching to " + msg.target + " " +
                    msg.callback + ": " + msg.what);
        }

        msg.target.dispatchMessage(msg);

        if (logging != null) {
            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();
    }
}

找到dispatchMessage的关键代码,即两个logging之间就是又可以出现耗时操作的地方。

// This must be in a local variable, in case a UI event sets the logger
Printer logging = me.mLogging;
if (logging != null) {
    logging.println(">>>>> Dispatching to " + msg.target + " " +
            msg.callback + ": " + msg.what);
}

msg.target.dispatchMessage(msg);

if (logging != null) {
    logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}

你可能要问了,mLogging是什么,我可以打印出来吗?答案:是可以的,不信可以看下源码

public final class Looper {
    private Printer mLogging;

    /**
     * Control logging of messages as they are processed by this Looper.  If
     * enabled, a log message will be written to <var>printer</var>
     * at the beginning and ending of each message dispatch, identifying the
     * target Handler and message contents.
     *
     * @param printer A Printer object that will receive log messages, or
     * null to disable message logging.
     */
    public void setMessageLogging(@Nullable Printer printer) {
        mLogging = printer;
    }
}

/**
 * Simple interface for printing text, allowing redirection to various
 * targets.  Standard implementations are {@link android.util.LogPrinter},
 * {@link android.util.StringBuilderPrinter}, and
 * {@link android.util.PrintWriterPrinter}.
 */
public interface Printer {
    /**
     * Write a line of text to the output.  There is no need to terminate
     * the given string with a newline.
     */
    void println(String x);
}

Looper的mLogging居然是个私有的,而Printer还是接口(默认是没有打印的),不过没有关系Looper提供了
setMessageLogging(@Nullable Printer printer)的公开方法,在自己实现一个Printer,传进出就好了。

1.编写能监控更新UI的代码

好吧,你已经知道,怎么做了。直接粘代码了。

/**
 * Created by zhangls on 2016/7/6.
 */
public class AppContext extends Application {

    @Override
    public void onCreate() {
        super.onCreate();

        Looper.getMainLooper().setMessageLogging(new Printer() {
            @Override
            public void println(String x) {
                Log.e("AppContext", x);
            }
        });
    }
}

打印的log如下:

E/AppContext: <<<<< Finished to Handler (android.app.ActivityThread$H) {414a36b0} null
E/AppContext: >>>>> Dispatching to Handler (android.view.ViewRootImpl) {41d5dbd8} null: 1000
E/AppContext: <<<<< Finished to Handler (android.view.ViewRootImpl) {41d5dbd8} null
E/AppContext: >>>>> Dispatching to Handler (android.view.ViewRootImpl) {41d5dbd8} 

2.找出过滤出耗时操作的Log

这个也不复杂,不多说了,看了代码,你就懂了。

/**
 * Created by zhangls on 2016/7/6.
 */
public class AppContext extends Application {

    @Override
    public void onCreate() {
        super.onCreate();

        Looper.getMainLooper().setMessageLogging(new MyPrinter());
    }

    private static class MyPrinter implements Printer {
        public static final String TAG = "Printer";
        private long mFinishTimeMillis;
        private long mStartTimeMillis;
        private static final int START = 0;
        private static final int FINISH = 1;
        private static final int UNKONW = 2;

        @Override
        public void println(String x) {
            switch (isStart(x)) {
                case START:
                    mStartTimeMillis = System.currentTimeMillis();
                    break;
                case FINISH:
                    mFinishTimeMillis = System.currentTimeMillis();
                    long duration = mFinishTimeMillis - mStartTimeMillis;
                    if (isBlock(duration)) {
                        Log.e(TAG, "block time:" + duration);
                    }
                    break;
            }
        }

        public int isStart(String x) {
            if (!TextUtils.isEmpty(x)) {
                if (x.startsWith(">>>>> Dispatching to Handler")) {
                    return START;
                } else if (x.startsWith("<<<<< Finished to Handler")) {
                    return FINISH;
                }
            }
            return UNKONW;
        }

        private boolean isBlock(long duration) {
            return duration > 16;
        }
    }
}

3.保存主线程所有的堆栈信息

先说下如何获取主线程的堆栈信息
StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
由于这个代码是反射也是一个耗时操作,所以不得不专门写一个Thread来不断获取主线程的堆栈信息。

public class StackInfoCatcher extends Thread {
    private static final String TAG = "StackInfoCatcher";

    private static final int SIZE = 1024;
    private boolean stop = false;
    private long mLastTime = 0;
    private List<StackTraceInfo> mList = new ArrayList<>(SIZE);

    @Override
    public void run() {
        super.run();
        while (!stop) {
            long currentTime = System.currentTimeMillis();
            if ((currentTime - mLastTime) > 500) {
                mLastTime = System.currentTimeMillis();
                StackTraceInfo info = new StackTraceInfo();
                info.mTime = mLastTime;
                StackTraceElement[] stackTrace = Looper.getMainLooper().getThread().getStackTrace();
                info.mLog = stackTraceToString(stackTrace);
                mList.add(info);
            }
            if (mList.size() > SIZE) {
                mList.remove(0);
            }
        }
    }

    public String stackTraceToString(StackTraceElement[] elements) {
        StringBuilder result = new StringBuilder();
        if (null != elements && elements.length > 0) {
            for (int i = 0; i < elements.length; i++) {
                result.append("\tat ");
                result.append(elements[i].toString());
                result.append("\n");
            }

        }
        return result.toString();
    }


    public void stopTrace() {
        stop = true;
    }

    private class StackTraceInfo {
        public long mTime;
        public String mLog;
    }
}

4.获取耗时操作对应的堆栈信息

当主线程遇到耗时操作,则发送广播交由工作线程处理。并把开始时间和结束时间也发送过去。寻找这个时间段主线程产生的LOG和堆栈信息。

class MyPrinter implements Printer {
    private MyPrinter(Context context) {
        this.mContext = context;
        stackInfoCatcher = new StackInfoCatcher(context);
        stackInfoCatcher.start();
    }

    @Override
    public void println(String x) {
        switch (isStart(x)) {
            case START:
                mStartTimeMillis = System.currentTimeMillis();
                break;
            case FINISH:
                mFinishTimeMillis = System.currentTimeMillis();
                long duration = mFinishTimeMillis - mStartTimeMillis;
                if (isBlock(duration)) {
                    LocalBroadcastManager manager= LocalBroadcastManager.getInstance(mContext);
                    Intent intent = new Intent("ACTION_BLOCK");
                    intent.putExtra("start", mStartTimeMillis);
                    intent.putExtra("finish", mFinishTimeMillis);
                    manager.sendBroadcast(intent);
                }
                break;
        }
    }
}
public class StackInfoCatcher extends Thread {
    public StackInfoCatcher(Context context) {
        this.mContext = context;
        LocalBroadcastManager manager = LocalBroadcastManager.getInstance(context);
        mBroadcastReceiver = new BroadcastReceiver() {
            @Override
            public void onReceive(Context context, Intent intent) {
                long endTime = intent.getLongExtra("finish", 0);
                long startTime = intent.getLongExtra("start", 0);
                StackTraceInfo info = getInfoByTime(endTime, startTime);
                if (null != info) {
                    Log.e(TAG, "find block line" + (endTime - startTime));
                    Log.e(TAG, info.mLog);
                } else {
                    Log.e(TAG, "no block line find");
                }
            }
        };
        manager.registerReceiver(mBroadcastReceiver, new IntentFilter("ACTION_BLOCK"));
    }

    public StackTraceInfo getInfoByTime(long endTime, long startTime) {
        for (StackTraceInfo info : mList) {
            if (info.mTime >= startTime && info.mTime <= endTime) {
                return info;
            }
        }
        return null;
    }

    public void stopTrace() {
        stop = true;
        LocalBroadcastManager.getInstance(mContext).unregisterReceiver(mBroadcastReceiver);
    }
}

5.测试并验证

编写一个Button,点击这个按钮主线程睡眠500ms。

public class MainActivity extends AppCompatActivity {

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
    }

    public void click(View view) {
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

对应日志如下

E: no block line find
E: find block line526
E:     at java.lang.VMThread.sleep(Native Method)
       at java.lang.Thread.sleep(Thread.java:1031)
       at java.lang.Thread.sleep(Thread.java:1013)
       at com.example.zhangls.myapplication1.MainActivity.click(MainActivity.java:21)
       at java.lang.reflect.Method.invokeNative(Native Method)
       at java.lang.reflect.Method.invoke(Method.java:511)
       at android.support.v7.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:288)
       at android.view.View.performClick(View.java:3511)
       at android.view.View.onKeyUp(View.java:6073)
       at android.widget.TextView.onKeyUp(TextView.java:5541)
       at android.view.KeyEvent.dispatch(KeyEvent.java:3279)
       at android.view.View.dispatchKeyEvent(View.java:5500)
       at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1246)
       at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1246)
       at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1246)
       at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1246)
       at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1246)
       at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1246)
       at com.android.internal.policy.impl.PhoneWindow$DecorView.superDispatchKeyEvent(PhoneWindow.java:1904)
       at com.android.internal.policy.impl.PhoneWindow.superDispatchKeyEvent(PhoneWindow.java:1386)
       at android.app.Activity.dispatchKeyEvent(Activity.java:2327)
       at android.support.v7.app.AppCompatActivity.dispatchKeyEvent(AppCompatActivity.java:534)
       at android.support.v7.view.WindowCallbackWrapper.dispatchKeyEvent(WindowCallbackWrapper.java:50)
       at android.support.v7.app.AppCompatDelegateImplBase$AppCompatWindowCallbackBase.dispatchKeyEvent(AppCompatDelegateImplBase.java:241)
       at com.android.internal.policy.impl.PhoneWindow$DecorView.dispatchKeyEvent(PhoneWindow.java:1831)
       at android.view.ViewRootImpl.deliverKeyEventPostIme(ViewRootImpl.java:3327)
       at android.view.ViewRootImpl.handleFinishedEvent(ViewRootImpl.java:3300)
       at android.view.ViewRootImpl.handleMessage(ViewRootImpl.java:2460)
       at android.os.Handler.dispatchMessage(Handler.java:99)
       at android.os.Looper.loop(Looper.java:137)
       at android.app.ActivityThread.main(ActivityThread.java:4425)
       at java.lang.reflect.Method.invokeNative(Native Method)
       at java.lang.reflect.Method.invoke(Method.java:511)
       at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:848)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:575)
       at dalvik.system.NativeStart.main(Native Method)

总结

在主线程寸土寸金的地方,这个种办法本身也是占用主线程的执行时间的,所以在打包release版本的时候,要记得把这个去掉。

参考

已标记关键词 清除标记
相关推荐
©️2020 CSDN 皮肤主题: 成长之路 设计师:Amelia_0503 返回首页