<p>这两天我的包工头 歪龙木·灵魂架构师·王半仙·Yrom 给我派了一个活：统计App冷启动时间。这个任务看上去不难，但是要求统计出来的时间要 <strong>准</strong> ，要 <strong>特别准</strong> 。</p>    <p>意思就是，我必须要按Activity绘制到屏幕上这个时间节点作为标杆，来进行我的统计工作。毕竟如果是因为视图处理不当而导致的measure/layout/draw耗时太久，这是不能忍的，需要及时统计到。虽然有点蛋疼，但是这个任务还算有意义，我就深挖一下，把过程分享出来。</p>    <p>注：本文所涉及源码部分的sdk level为21</p>    <h2>onResume真的已经显示了吗？</h2>    <p>如果你看过官方文档中的Activity生命指引，你会发现它说的是</p>    <p>Activity在onResume生命周期中已经是可见状态。</p>    <p>那么我们就去这个onResume中看一看。现在我在Activty的onCreate第一行（ super.onCreate 之前）记录一个时间点，onResume的最后一行( super.onResume 之后)记录一个时间点，将两者的差值记录下来。</p>    <p>打出来的Log是： <strong>I/MainActivity: onCreate -> onResume : 70</strong> 。 即这个过程花费了70ms。那真的是只用了70ms我的Activity就已经完全显示了吗？我们来看两个官方的衡量点：</p>    <ul>     <li>通过adb shell的命令</li>    </ul>    <pre>  <code class="language-java">$ adb shell am start -W com.desmond.demo/.MainActivity    Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] cmp=com.desmond.demo/.MainActivity }  Status: ok  Activity: com.desmond.demo/.MainActivity  ThisTime: 314  TotalTime: 314  WaitTime: 314  Complete  </code></pre>    <ul>     <li>启动Activity时的可以看Tag = ActivityManager打出来的Log：</li>    </ul>    <p>I/ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +314ms</p>    <p>这两个时间是一样的，我们看哪个都行。这个314ms的启动过程和上面的70ms <strong>是同一次启动过程打出来的日志</strong> ，那么问题来了，怎么会和我打出来的Log时间相差这么大？我们先看看系统打出来的时间到底是什么时间。</p>    <p>打出这段log的代码在 ActivityRecord ：</p>    <pre>  <code class="language-java">//ActivityRecord  privatevoidreportLaunchTimeLocked(finallongcurTime){      final ActivityStack stack = task.stack;      if (stack == null) {          return;      }      final long thisTime = curTime - displayStartTime;      final long totalTime = stack.mLaunchStartTime != 0              ? (curTime - stack.mLaunchStartTime) : thisTime;      if (SHOW_ACTIVITY_START_TIME) {          // ...其他代码          StringBuilder sb = service.mStringBuilder;          sb.setLength(0);          sb.append("Displayed ");          sb.append(shortComponentName);          sb.append(": ");          TimeUtils.formatDuration(thisTime, sb);          if (thisTime != totalTime) {              sb.append(" (total ");              TimeUtils.formatDuration(totalTime, sb);              sb.append(")");          }          Log.i(TAG, sb.toString());      }      // ...其他代码  }  </code></pre>    <p>它的调用时机我们后面再讨论，首先看一下它打出了什么。这个函数中将 totalTime 作为Displayed时间打了出来，值为 当前时间 - stack.mLaunchStartTime 。那这个mLaunchStartTime是什么时候被记录的呢？查了一下调用发现在 ActivityStackSupervisor.startSpecificActivityLocked 会调用 stack.setLaunchTime(r) 去设置这个时间。</p>    <p>那么我们可以得出第一个结论：</p>    <p>结论1： <strong>系统打出来的时间包含了进程启动的时间。</strong></p>    <p>因为进程启动都是在 ActivityStackSupervisor.startSpecificActivityLocked() 中进行的，以ActivityThread.main为入口启动一个新进程。</p>    <p>但是进程启动这么耗时？我的test activiy也没有自定义Application，更别提什么耗时操作了。我来实践一下 <strong>热启动</strong> ，App退出，但是不杀进程，再对比一下我打的log和系统log的时间区别。</p>    <p>我：I/MainActivity: onCrete -> onResume : 37</p>    <p>系统： I/ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +103ms</p>    <p>依然差了很多！</p>    <p>看来我们需要研究一下Activity的onResume过程及系统上报Displayed的时机了。</p>    <h2>深入探究onResume过程</h2>    <p>我先对AMS触发Activity的onResume这个过程画了一张图：</p>    <p><img src="https://simg.open-open.com/show/692c973ba30bc8122677e2b053205f63.jpg"></p>    <p>在ActivityManagerService(AMS)告知Activity要resume时，它通过调用 ApplicationThread.scheduleResumeActivity 给 ActivityThread.H （一个Handler）发送消息 RESUME_ACTIVITY ，然后H开始处理消息：</p>    <pre>  <code class="language-java">case RESUME_ACTIVITY:      Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "activityResume");      handleResumeActivity((IBinder) msg.obj, true, msg.arg1 != 0, true);      Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);      break;  </code></pre>    <p>在这个 handleResumeActivity 中就处理了所有的Resume逻辑，我们进去一探究竟。</p>    <pre>  <code class="language-java">//ActivityThread.java  finalvoidhandleResumeActivity(IBinder token,          boolean clearHide, boolean isForward, boolean reallyResume) {      // 一些其他代码        // 这步onResume      ActivityClientRecord r = performResumeActivity(token, clearHide);        if (r != null) {          final Activity a = r.activity;            // 一些其他代码            if (r.window == null && !a.mFinished && willBeVisible) {              r.window = r.activity.getWindow();              View decor = r.window.getDecorView();              decor.setVisibility(View.INVISIBLE);              ViewManager wm = a.getWindowManager();              WindowManager.LayoutParams l = r.window.getAttributes();              a.mDecor = decor;              l.type = WindowManager.LayoutParams.TYPE_BASE_APPLICATION;              l.softInputMode |= forwardBit;              if (a.mVisibleFromClient) {                  a.mWindowAdded = true;                  wm.addView(decor, l); //这步很关键              }          }          //...      }  }  </code></pre>    <p>Activity.onResume() 这一步就是在 performResumeActivity 里面调用的，有兴趣的同学可以去看看，里面代码很简单。</p>    <p>为什么说 wm.addView 这一步很关键？真正对Activity的视图进行计算、绘制、flush到window上是 wm.addWindow 这一步做的，这里面代码比较多，我直接画张图看清晰一点：</p>    <p><img src="https://simg.open-open.com/show/1cf089d9212ad8a374a945be18a91d4a.jpg"></p>    <p>这张图的代码就不放了，关键的类和方法都在里面，有兴趣的同学可以自行翻阅。有几个注意的点：</p>    <ol>     <li>Activity#getWindowManager() 拿到的是Activity的成员变量 mWindowManager ，它是一个 WindowManagerIpml 实例，在 Activity.attach 内被赋值。所以我们在第一步直接就跳转到了 WindowManagerImpl.addView()</li>     <li>ViewRootImpl 在requestLayout的时候将一个Runnable交由 <a href="/misc/goto?guid=4959734628931386359" rel="nofollow,noindex">Choreographer</a> 去调度，让它能够在下一个绘制帧时执行它。这个Runnable内只有一条语句，就是执行 doTraversal ，主要的内容在其中执行的 performTraversal 中，这个函数非常非常长，做的事情大致就是从顶至下的measure/layout/draw，通知 ViewTreeObserver 的各类Listener也大部分都是在这一步中完成的。</li>    </ol>    <p>这时候我们回头看之前 ActivityThread.handleResumeActivity 的代码： <strong>Activity的onResume在wm.addView之前！</strong> 。因为View的计算、绘制等都在wm.addView之后执行，那我们可以得出第二个结论：</p>    <p>结论2： 在onResume的时候是肯定统计不到View的measure/layout/draw时间的。</p>    <p>这时候我们要搞清楚的是，上面系统的Log是在哪一步调用的，它是否包含了View的measure/layout/draw的时间？这个过程可是一顿好找，大概是如下图所示流程：</p>    <p><img src="https://simg.open-open.com/show/7af3098324fc8d1f0683291ac79dfeee.jpg"></p>    <p>5-6步之间被我 <strong>精简</strong> 了一小部分内容，我来简单解释一下这个过程：</p>    <ol>     <li>ViewRootImpl在 performTraversals() 的最后会调用 performDraw() 来将内容绘制到Surface上，最后一步它会执行 mWindowSession.finishDrawing 。这个 mWindowSession 是一个Session对象，它维持着ViewRootImpl与WindowManagerService(WMS)之间的联系。</li>     <li>在这之后WMS通过Handler来调度绘制Surface的任务，它给自己内部类H发送了一个 DO_TRAVERSAL 消息。收到消息之后它就会执行 performLayoutAndPlaceSurfacesLocked 函数，之后有一系列的链式调用由于方法名字太长并且于本文没有太多用处，在我的图里被省略了。最后它会走到 performLayoutAndPlaceSurfacesLockedInner ，这里面会将Surface绘制到屏幕上，并调用 handleAppTransitionReadyLocked ，并如图所示继续向后调用。</li>     <li>ActivityRecord.Token是一个Binder对象，它活在ActivityManagerService进程中，用于AMS与WMS之间的通信。相对应的，AppWindowToken活在WindowManagerService进程中。每一个ActivityRecord.Token都对应一个AppWindowToken。</li>    </ol>    <p>那我们可以确定的是，在看到系统这条日志时，View的计算、绘制已经完成，并且Surface也被绘制到屏幕上。这样我们可以得出第三个结论：</p>    <p>结论3： 系统打出来的日志时Activity已经被完全展示到了屏幕上。</p>    <h2>View绘制结束的回调时机</h2>    <p>得出了结论，那我们要怎么知道什么时候View绘制结束呢？这里就仁者见仁，智者见智了。</p>    <p>首先可以确认的是，所有ViewTreeObserver里面的Listener都是不够准确的。为什么呢？它们里面能统计到的最迟就是 OnDrawListener ，我们可以在 ViewRootImpl#draw() 函数中看到，它是在真正draw这一步之前调用的，也就是说它没有统计到draw的时间。</p>    <p>我提供一个思路，能够准确获取到包括View的measure/layout/draw过程的时间。那就是在 onResume 中添加一个 IdleHandler ：</p>    <pre>  <code class="language-java">@Override  protectedvoidonResume(){      super.onResume();      Looper.myQueue().addIdleHandler(new MessageQueue.IdleHandler() {          @Override          publicbooleanqueueIdle(){              Log.i(TAG, "onCreate -> idle : " + (SystemClock.uptimeMillis() - time));              return false;          }      });  }  </code></pre>    <p>这个IdleHandler是什么？它会在Looper的消息队列处理完当前阻塞的消息（即Idle中，等待获取下一条消息）时被调用。我这里直接指定了主线程的消息队列，那我在 onResume 中给它加入一个IdleHandler，它会什么时候调用呢，我们回顾一下Activity的onResume->ViewRoot的traversal这个过程，我做了一些修改：</p>    <p><img src="https://simg.open-open.com/show/121b397d57cdd1027b2cda06ba7aae75.jpg"></p>    <p>这里有一个需要注意的地方：</p>    <p>ViewRootImpl在向Choreographer发送调度消息时，特地向主线程的Looper消息循环发送了一个“障碍消息”。利用 MessageQueue#postSyncBarrier 可以做到这一点，当出现了这一个障碍消息的时候，消息循环就暂时无法处理后续排入消息。有兴趣的同学可以自行研究这个过程。</p>    <p>Choreographer通过直接在native操作主进程的MessageQueue来排入消息，从而它的执行会无视我们加入的“障碍消息”。即 ViewRootImpl#doTraversal 这个函数也是在一次消息处理中发生的。它此时移除了MessageQueue里面的障碍消息，并且执行performTraversals。</p>    <p>需要注意的是： <strong>这整个过程都是在主线程的消息循环中发生的。</strong> 这个过程可以描述为如下几步：</p>    <ol>     <li>ActivityThread.H在处理 RESUME_ACTIVITY 消息时调用的 handleResumeActivity 会触发 Activity#onResume 与 ViewRootImpl#doTraversal 。</li>     <li>ViewRootImpl#doTraversal 向主进程Looper发送了一个“障碍消息”，使主进程Looper无法继续处理后续消息。</li>     <li>Choreographer通过native向主进程Looper排入消息，移除“障碍消息”，并执行 ViewRootImpl#doTraversal 。</li>    </ol>    <p>所以如果我们在onResume中向主进程添加入一个IdleHandler，它是必然会在这三步都走完，主进程Looper的MessageQueue才可能触发Idle状态，并触发IdleHandler回调。</p>    <p>我们可以实验一下：在添加入的IdleHandler内打点，计算与onCreate第一行打点时间之差，最后打出来的Log：</p>    <pre>  <code class="language-java">MainActivity: onCrete -> onResume : 12  MainActivity: onCrete -> onPreDraw : 138  MainActivity: onCrete -> onPreDraw : 147  MainActivity: onCrete -> idleHandler : 166  ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +192ms  </code></pre>    <p>虽然还是离ActivityManager打出来的差了一点，但是这也是有理由的。我们看上面的WMS绘制Surface那一步，是通过Handler发送异步消息完成的，这里统计不到。</p>    <h2>总结</h2>    <p>虽然没有完全贴近系统打出来的日志，但是通过IdleHandler的方式已经能统计到我想要的内容了（由Activity的onCreate第一步到整个界面显示）。</p>    <p> </p>    <p> </p>    <p>来自：http://blog.desmondyao.com/android-show-time/</p>    <p> </p>