BlockCanary源码分析

如何计算主线程中的方法耗时？
看一下Looper的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
            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();
        }
    }

耗时的处理会发生在dispatchMessage中可以替换掉mLogging 并记录开始和结束的时间
记录开始的位置：

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

记录结束的位置：

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

重写Printer的println方法：

@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(); //停止收集堆栈信息
        }
    }

 private boolean isBlock(long endTime) { //是否卡顿
        return endTime - mStartTimestamp > mBlockThresholdMillis;
    }

/**
     * Start monitoring.
     */
    public void start() {
        if (!mMonitorStarted) {
            mMonitorStarted = true;
            Looper.getMainLooper().setMessageLogging(mBlockCanaryCore.monitor); //设置自定义的Printer
        }
    }

private void startDump() { //方法堆栈的信息收集
        if (null != BlockCanaryInternals.getInstance().stackSampler) { //采集堆栈信息 stackSampler继承自AbstractSampler
            BlockCanaryInternals.getInstance().stackSampler.start();
        }

        if (null != BlockCanaryInternals.getInstance().cpuSampler) { //采集CPU信息
            BlockCanaryInternals.getInstance().cpuSampler.start();
        }
    }

AbstractSampler的start方法：

public void start() {
        if (mShouldSample.get()) {
            return;
        }
        mShouldSample.set(true);
        HandlerThreadFactory.getTimerThreadHandler().removeCallbacks(mRunnable);
        HandlerThreadFactory.getTimerThreadHandler().postDelayed(mRunnable, //启动mRunnable
                BlockCanaryInternals.getInstance().getSampleDelay());
    }

private Runnable mRunnable = new Runnable() {
        @Override
        public void run() {
            doSample();
            if (mShouldSample.get()) {
                HandlerThreadFactory.getTimerThreadHandler()
                        .postDelayed(mRunnable, mSampleInterval); //轮询
            }
        }
    };

堆栈采样：

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

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

CPU采样：
Linux中CPU的活动保存在/proc/stat文件中从系统开启时累计到当前时刻

~$ cat /proc/stat
cpu  38082 627 27594 893908 12256 581 895 0 0 //CPU总的使用情况
cpu0 22880 472 16855 430287 10617 576 661 0 0 
cpu1 15202 154 10739 463620 1639 4 234 0 0
intr 120053 222 2686 0 1 1 0 5 0 3 0 0 0 47302 0 0 34194 29775 0 5019 845 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
ctxt 1434984
btime 1252028243
processes 8113
procs_running 1
procs_blocked 0

第二行的数据解析：
user (38082) 处于用户态的运行时间
不包含 nice值为负进程
nice (627) nice值为负的进程所占用的CPU时间
system (27594) 处于核心态的运行时间
idle (893908) 除IO等待时间以外的其它等待时间iowait (12256) 从系统启动开始累计到当前时刻 IO等待时间
irq (581) 硬中断时间
irq (581) 软中断时间
stealstolen(0) 一个其他的操作系统运行在虚拟环境下所花费的时间
guest(0) 这是在Linux内核控制下为客户操作系统运行虚拟CPU所花费的时间

总的CPU时间=以上所有指标的和

某一进程的所有信息保存在/proc/pid/stat中从系统开始时累计到当前时刻
CPU采样：

@Override
protected void doSample() {
    BufferedReader cpuReader = null;
    BufferedReader pidReader = null;
 
    try {
        cpuReader = new BufferedReader(new InputStreamReader( //总CPU采样
                new FileInputStream("/proc/stat")), BUFFER_SIZE);
        String cpuRate = cpuReader.readLine();
        if (cpuRate == null) {
            cpuRate = "";
        }
 
        if (mPid == 0) {
            mPid = android.os.Process.myPid();
        }
        pidReader = new BufferedReader(new InputStreamReader(
                new FileInputStream("/proc/" + mPid + "/stat")), BUFFER_SIZE); //某一进程CPU采样
        String pidCpuRate = pidReader.readLine();
        if (pidCpuRate == null) {
            pidCpuRate = "";
        }
 
        parse(cpuRate, pidCpuRate);
    } catch (Throwable throwable) {
        Log.e(TAG, "doSample: ", throwable);
    } finally {
        try {
            if (cpuReader != null) {
                cpuReader.close();
            }
            if (pidReader != null) {
                pidReader.close();
            }
        } catch (IOException exception) {
            Log.e(TAG, "doSample: ", exception);
        }
    }
}
  
private void parse(String cpuRate, String pidCpuRate) {
    String[] cpuInfoArray = cpuRate.split(" ");
    if (cpuInfoArray.length < 9) {
        return;
    }
 
    long user = Long.parseLong(cpuInfoArray[2]);
    long nice = Long.parseLong(cpuInfoArray[3]);
    long system = Long.parseLong(cpuInfoArray[4]);
    long idle = Long.parseLong(cpuInfoArray[5]);
    long ioWait = Long.parseLong(cpuInfoArray[6]);
    long total = user + nice + system + idle + ioWait
            + Long.parseLong(cpuInfoArray[7])
            + Long.parseLong(cpuInfoArray[8]);
 
    String[] pidCpuInfoList = pidCpuRate.split(" ");
    if (pidCpuInfoList.length < 17) {
        return;
    }
 
    long appCpuTime = Long.parseLong(pidCpuInfoList[13])
            + Long.parseLong(pidCpuInfoList[14])
            + Long.parseLong(pidCpuInfoList[15])
            + Long.parseLong(pidCpuInfoList[16]);
 
    if (mTotalLast != 0) {
        StringBuilder stringBuilder = new StringBuilder();
        long idleTime = idle - mIdleLast;
        long totalTime = total - mTotalLast;
 
        stringBuilder
                .append("cpu:")
                .append((totalTime - idleTime) * 100L / totalTime)
                .append("% ")
                .append("app:")
                .append((appCpuTime - mAppCpuTimeLast) * 100L / totalTime)
                .append("% ")
                .append("[")
                .append("user:").append((user - mUserLast) * 100L / totalTime)
                .append("% ")
                .append("system:").append((system - mSystemLast) * 100L / totalTime)
                .append("% ")
                .append("ioWait:").append((ioWait - mIoWaitLast) * 100L / totalTime)
                .append("% ]");
 
        synchronized (mCpuInfoEntries) {
            mCpuInfoEntries.put(System.currentTimeMillis(), stringBuilder.toString());
            if (mCpuInfoEntries.size() > MAX_ENTRY_COUNT) {
                for (Map.Entry<Long, String> entry : mCpuInfoEntries.entrySet()) {
                    Long key = entry.getKey();
                    mCpuInfoEntries.remove(key);
                    break;
                }
            }
        }
    }
    mUserLast = user;
    mSystemLast = system;
    mIdleLast = idle;
    mIoWaitLast = ioWait;
    mTotalLast = total;
 
    mAppCpuTimeLast = appCpuTime;
}

总结

通过hook Looper中的Printer计算方法的耗时
Thread#getStackTrace 获取堆栈信息
cat /proc/stat 和 /proc/pid/stat 文件读取CPU信息

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 203,772评论 6赞 477
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 85,458评论 2赞 381
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 150,610评论 0赞 337
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 54,640评论 1赞 276
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 63,657评论 5赞 365
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 48,590评论 1赞 281
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 37,962评论 3赞 395
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 36,631评论 0赞 258
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 40,870评论 1赞 297
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 35,611评论 2赞 321
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 37,704评论 1赞 329
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 33,386评论 4赞 319
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 38,969评论 3赞 307
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 29,944评论 0赞 19
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 31,179评论 1赞 260
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 44,742评论 2赞 349
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 42,440评论 2赞 342

BlockCanary源码分析

总结

推荐阅读更多精彩内容