BlockCanary源码解析

BlockCanary原理

如何计算主线程的方法执行耗时

计算方法耗时最简单粗暴的就是在方法之前前记录下开始时间,方法执行完后用当前时间剪去方法开始执行的时间就完事了,但是主线程那么多方法总不能每一个方法都这个干吧?那肯定崩!有没有一个统一的地方来实现这个功能?当然有了,不然这篇博客到这里就戛然而止了......

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

            final long traceTag = me.mTraceTag;
            if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
                Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
            }
            try {
                msg.target.dispatchMessage(msg);
            } finally {
                if (traceTag != 0) {
                    Trace.traceEnd(traceTag);
                }
            }

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

如上代码中的loop()方法是Looper中的,我们的目的是监测主线程的卡顿问题,因为UI更新界面都是在主线程中进行的,所以在主线程中做耗时操作可能会造成界面卡顿,而主线程的Looper早已经在APP启动的时候Android framework里面创建了main looper,那么一个线程对应一个Looper,Looper当中有一个MessageQueue,专门用来接收Handler发送过来的msg,并且在looper()方法中循环去从MessageQueue中去取msg,然后执行,而且是顺序执行的,那么前面一个msg还没处理完,loop()就会等待它处理完了才会再去执行下一个msg,如果前面一个msg处理很慢,那就会造成卡顿了,在msg.target.dispatchMessage(msg)前有:

if (logging != null) {
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }

而在dispatchMessage执行完了之后,又有:

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

所以,我们只需要计算打印这两天log的时间差,就能得到dispatchMessage的耗时,android提供了Looper.getMainLooper().setMessageLogging(Printer printer)来设置这个logging对象,所以只要自定义一个Printer,然后重写println(String x)方法即可实现耗时统计了,所以原理真的很简单,原理固然简单,但是还是要学会发现这个小技巧,对于BlockCanary而言,初始化:

public class MyApplication extends Application {

    @Override
    public void onCreate() {
        super.onCreate();
        BlockCanary.install(this, new BlockCanaryContext()).start();

    }
}

查看start()方法里面的代码:

/**
     * Start monitoring.
     */
    public void start() {
        if (!mMonitorStarted) {
            mMonitorStarted = true;
            Looper.getMainLooper().setMessageLogging(mBlockCanaryCore.monitor);
        }
    }

而monitor是一个继承Printer的LooperMonitor类new出来的对象,重写print(String x)方法:

@Override
    public void println(String x) {
        if (mStopWhenDebugging && Debug.isDebuggerConnected()) {
            return;
        }
        if (!mPrintingStarted) {
            mStartTimestamp = System.currentTimeMillis();
            mStartThreadTimestamp = SystemClock.currentThreadTimeMillis();
            mPrintingStarted = true;
            startDump();
        } else {
            final long endTime = System.currentTimeMillis();
            mPrintingStarted = false;
            if (isBlock(endTime)) {
                notifyBlockEvent(endTime);
            }
            stopDump();
        }
    }

在dispatchMessage执行之前打印log的时候执行print,mPrintingStarted为false,所以就记录当前的时间,以及当前线程时间mPrintingStarted设置为true,而dispatchMessage执行完后第二次打印log执行print方法,mPrintingStarted是true的,这时候dispatchMessage已经执行结束,然后就能计算耗时,搜集方法堆栈信息,cpu信息等等

方法堆栈信息的搜集

private void startDump() {
        if (null != BlockCanaryInternals.getInstance().stackSampler) {
            BlockCanaryInternals.getInstance().stackSampler.start();
        }

        if (null != BlockCanaryInternals.getInstance().cpuSampler) {
            BlockCanaryInternals.getInstance().cpuSampler.start();
        }
    }

在LooperMonitor的print方法中会执行这个方法,同时采集方法堆栈信息和cpu信息,对于堆栈信息stackSampler.start():

abstract class AbstractSampler {

    private static final int DEFAULT_SAMPLE_INTERVAL = 300;

    protected AtomicBoolean mShouldSample = new AtomicBoolean(false);
    protected long mSampleInterval;

    private Runnable mRunnable = new Runnable() {
        @Override
        public void run() {
            doSample();

            if (mShouldSample.get()) {
                HandlerThreadFactory.getTimerThreadHandler()
                        .postDelayed(mRunnable, mSampleInterval);
            }
        }
    };

    public AbstractSampler(long sampleInterval) {
        if (0 == sampleInterval) {
            sampleInterval = DEFAULT_SAMPLE_INTERVAL;
        }
        mSampleInterval = sampleInterval;
    }

    public void start() {
        if (mShouldSample.get()) {
            return;
        }
        mShouldSample.set(true);

        HandlerThreadFactory.getTimerThreadHandler().removeCallbacks(mRunnable);
        HandlerThreadFactory.getTimerThreadHandler().postDelayed(mRunnable,
                BlockCanaryInternals.getInstance().getSampleDelay());
    }

    public void stop() {
        if (!mShouldSample.get()) {
            return;
        }
        mShouldSample.set(false);
        HandlerThreadFactory.getTimerThreadHandler().removeCallbacks(mRunnable);
    }

    abstract void doSample();
}

调用start方法之后就执行:

private Runnable mRunnable = new Runnable() {
        @Override
        public void run() {
            doSample();

            if (mShouldSample.get()) {
                HandlerThreadFactory.getTimerThreadHandler()
                        .postDelayed(mRunnable, mSampleInterval);
            }
        }
    };

并且这里控制stackSampler.start()只能执行一次,在run方法里面我们可以发现每次间隔mSampleInterval就会去重新跑一次doSample(),这里会执行StackSampler的doSample():

@Override
    protected void doSample() {
        StringBuilder stringBuilder = new StringBuilder();

        for (StackTraceElement stackTraceElement : mCurrentThread.getStackTrace()) {
            stringBuilder
                    .append(stackTraceElement.toString())
                    .append(BlockInfo.SEPARATOR);
        }

        synchronized (sStackMap) {
            if (sStackMap.size() == mMaxEntryCount && mMaxEntryCount > 0) {
                sStackMap.remove(sStackMap.keySet().iterator().next());
            }
            sStackMap.put(System.currentTimeMillis(), stringBuilder.toString());
        }
    }

mCurrentThread就是主线程对象,0.8 * mSampleInterval(卡顿时长阀值)后的去获取线程的堆栈信息并保存到sStackMap中,这里的意思是,我们认为方法执行超过mSampleInterval就表示卡顿,当方法执行时间已经到了mSampleInterval的0.8倍的时候还没执行完,那么这时候就开始采集方法执行堆栈信息了,如果方法在0.9 * mSampleInterval的时候执行完成,那么不会警告卡顿,但是如果方法执行耗时超过mSampleInterval,那就把0.8 * mSampleInterval这个时间点的堆栈信息认为是造成耗时原因的堆栈信息,而且,这里只要方法还没执行完,就会间隔mSampleInterval去再次获取函数执行堆栈信息并保存,这里之所以遥在0.8 * mSampleInterval的时候就去获取堆栈信息时为了获取到准确的堆栈信息,因为既然函数耗时已经达到0.8 * mSampleInterval了,并且函数还没执行结束,那么很大概率上会导致卡顿了,所以提前获取函数执行堆栈保证获取到造成卡顿的函数调用堆栈的正确性,后面又不断间隔mSampleInterval去获取函数执行堆栈式要获取到更多完整的堆栈信息,当方法执行完成后就会停止获取函数执行堆栈了,所有的函数执行堆栈信息最多存100条,也就是最多有100个函数调用堆栈,以当前的时间戳作为key,当监测到卡顿的时候,要把之前保存在sStackMap的函数堆栈信息展示通知出来,通过时间戳就能取到:

private void notifyBlockEvent(final long endTime) {
        final long startTime = mStartTimestamp;
        final long startThreadTime = mStartThreadTimestamp;
        final long endThreadTime = SystemClock.currentThreadTimeMillis();
        HandlerThreadFactory.getWriteLogThreadHandler().post(new Runnable() {
            @Override
            public void run() {
                mBlockListener.onBlockEvent(startTime, endTime, startThreadTime, endThreadTime);
            }
        });
    }

然后再看mBlockListener.onBlockEvent(startTime, endTime, startThreadTime, endThreadTime),因为初始化的时候在BlockCanaryInternals构造函数里面已经setMonitor了,并且实现了onBlockEvent:

public BlockCanaryInternals() {

        stackSampler = new StackSampler(
                Looper.getMainLooper().getThread(),
                sContext.provideDumpInterval());

        cpuSampler = new CpuSampler(sContext.provideDumpInterval());

        setMonitor(new LooperMonitor(new LooperMonitor.BlockListener() {

            @Override
            public void onBlockEvent(long realTimeStart, long realTimeEnd,
                                     long threadTimeStart, long threadTimeEnd) {
                // Get recent thread-stack entries and cpu usage
                ArrayList<String> threadStackEntries = stackSampler
                        .getThreadStackEntries(realTimeStart, realTimeEnd);
                if (!threadStackEntries.isEmpty()) {
                    BlockInfo blockInfo = BlockInfo.newInstance()
                            .setMainThreadTimeCost(realTimeStart, realTimeEnd, threadTimeStart, threadTimeEnd)
                            .setCpuBusyFlag(cpuSampler.isCpuBusy(realTimeStart, realTimeEnd))
                            .setRecentCpuRate(cpuSampler.getCpuRateInfo())
                            .setThreadStackEntries(threadStackEntries)
                            .flushString();
                    LogWriter.save(blockInfo.toString());

                    if (mInterceptorChain.size() != 0) {
                        for (BlockInterceptor interceptor : mInterceptorChain) {
                            interceptor.onBlock(getContext().provideContext(), blockInfo);
                        }
                    }
                }
            }
        }, getContext().provideBlockThreshold(), getContext().stopWhenDebugging()));

        LogWriter.cleanObsolete();
    }

再看ArrayList<String> threadStackEntries = stackSampler .getThreadStackEntries(realTimeStart, realTimeEnd) 获取函数堆栈信息:

public ArrayList<String> getThreadStackEntries(long startTime, long endTime) {
        ArrayList<String> result = new ArrayList<>();
        synchronized (sStackMap) {
            for (Long entryTime : sStackMap.keySet()) {
                if (startTime < entryTime && entryTime < endTime) {
                    result.add(BlockInfo.TIME_FORMATTER.format(entryTime)
                            + BlockInfo.SEPARATOR
                            + BlockInfo.SEPARATOR
                            + sStackMap.get(entryTime));
                }
            }
        }
        return result;
    }

这里面就是通过把开始时间,结束时间和刚才保存起来的堆栈信息的key,也就是保存堆栈信息的时间做对比,在开始时间和结束时间这个范围内的堆栈信息才是有用的,如果一个函数执行了3秒,那么这里会把这三秒内的所有函数执行堆栈信息都取出来,然后再封装成BlockInfo通知到外面,同时可存到文件中,到这里造成卡顿的函数执行堆栈已经采集完成

CPU信息采集

  • 采集当前cpu的使用率,如果cpu使用率太高,可能会导致cpu处理来不及,所以函数执行到一半可能暂时挂起,等待cpu重新调度
  • 采集当前cpu是否繁忙而处理不过来,道理如上,cpu繁忙会导致函数执行一半倍挂起,需要等到下一次cpu调度后重新继续执行
  • 当前app的cpu占用率
  • 用户使用情况,系统使用情况
  • %ioWait:首先 %iowait 升高并不能证明等待I/O的进程数量增多了,也不能证明等待I/O的总时间增加了;   例如,在CPU繁忙期间发生的I/O,无论IO是多还是少,%iowait都不会变;当CPU繁忙程度下降时,有一部分IO落入CPU空闲时间段内,导致%iowait升高。   再比如,IO的并发度低,%iowait就高;IO的并发度高,%iowait可能就比较低。

可见%iowait是一个非常模糊的指标,如果看到 %iowait 升高,还需检查I/O量有没有明显增加,avserv/avwait/avque等指标有没有明显增大,应用有没有感觉变慢,如果都没有,就没什么好担心的。

BlockCanary几个核心

  • LooperMonitor负责统计方法耗时
  • StackSampler函数执行堆栈采集
  • CpuSampler式cpu信息采集
  • 耗时异常信息提醒与展示,相关信息持久化到文件,这些比较简单了,这里就不再详细叙述述
  • 综合来看BlockCanary的一个执行流程时这样的,这边使用下BlockCanary的github上面的一张图片:

flow.png

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • Android中使用Contentprovider导致进程被杀死

    Contentprovider也是四大组件之一,支持跨进程调用,因此肯定会用到IPC的Binder机制来实现跨进程调用,在应用层就是AIDL

    大大大大大先生
  • IM二分法智能心跳策略

    大大大大大先生
  • Android开发之逻辑单元测试

    以上createInetSocketAddress方法就是我在编写单元测试的时候单独抽离出来的方法,一方面我需要mock一个InetSocketAddress来...

    大大大大大先生
  • 设计更美好的生活|Mix+人工智能 No.55

    Google Lens,智慧镜头,让你打开相机就可以辨认花草、翻译文字、识别地标。

    mixlab
  • pmq学习二-生产者和消费者流程

    学习一个框架,通常从example开始。同时一个消息中间件是从生产者开始,消费者消费消息。这里mq-client-test-001里面的两个类开始。

    路行的亚洲
  • golang 设置 http response 响应头与坑

    之前遇到个问题,在一段代码中这样设置WriteHeader,最后在header中取Name时怎么也取不到。

    我的小碗汤
  • golang 设置 http response 响应头与坑

    之前遇到个问题,在一段代码中这样设置WriteHeader,最后在header中取Name时怎么也取不到。

    我的小碗汤
  • Coinbase大变!它要与‘’垃圾代币‘’同流合污了?

    受美国证券交易委员会(SEC)的监管影响,Coinbase 是加密数字货币领域最保守的交易所之一,这家市值80亿美元的公司仅仅向用户提供了不超过10种的数字加密...

    区块链大本营
  • Code | Python30个编程技巧!

    1. 原地交换两个数字 Python 提供了一个直观的在一行代码中赋值与交换(变量值)的方法,请参见下面的示例: ? 3. 使用三元操作符来进行条件赋值 三元...

    IT派
  • ASP.NET Core 性能优化最佳实践

    译文原文地址:https://docs.microsoft.com/en-us/aspnet/core/performance/performance-best...

    newbe36524

扫码关注云+社区

领取腾讯云代金券