Android 进入退出应用动画卡顿分析

    最近在新项目上，出现了再进入退出应用时，动画会卡顿的现象。因为有过版本切换，为了区分，分别叫做A、B版，A是旧版本，B是新版本。先说A版本的情况，A版本在应用退出的时候比较容易出现卡顿。有同事说有做alpha变化的时候，动画都会卡顿。既然这个动画也卡顿，而且也做了alpha变化，是不是因为做了alpha变化呢？于是把alpha变化去掉，问题还是存在的，应该是跟做不做alpha动画没有关系，问题不在这。中间很多过程不记得了，大概折腾了一周以后发现，在SurfaceFlinger.cpp里面把mDebugDisableHWC(0)改成了mDebugDisableHWC(1),相当于绘图合成的时候，MDP是关闭的，都是用GPU进行合成，结果就出现了卡顿的情况。当然，也可以通过adb
shell dumpsys SurfaceFlinger可以看到

h/w composer state:

  h/w composer present and disable

没有使用h/w composer，即使用了GPU绘图。

这个版本把overlay打开以后，应用进入与退出的动画是好了，没有什么问题。
当我正在A版本解决这个问题的时候，系统确有切换到了新的B版本，结果B版本动画还是卡的。我一看，overlay还是关闭的，理所当然的认为把overlay打开以后，应该就不卡了。结果大出我意料之外，无论打开还是关闭MDP，动画还是会卡顿的。这让我有多纠结呀！本来觉得跟了一周，问题已经解决了，到新的版本B上，又出现了问题。我还没缓过神了！~

B版本上有就分析吧！

B版本在进入退出应用的时候，从Systrace分析来看，在卡顿的时候是在hwc_prepare_primary耗时异常:

 Title hwc_prepare_primary
 Start 2003.446 ms
 Duration 29.842 ms

在绘制一帧的时候一个函数耗时接近30ms的情况，而且绘制的时候会发生联想几次这样的情况，一帧16ms才能保证有60fps的帧率，一个函数就会出现耗时30ms，当然就会卡顿了，正常情况下这个函数是不耗时的。
通过追踪hwc_prepare_primary函数，最后是在耗时都在HAL层的setOverlay里面：

 qdoverlay: setOverlay : 31ms

但setOverlay函数操作简单，只有一个ioctl操作：
inline bool setOverlay(int fd, mdp_overlay& ov) {
      if (ioctl(fd, MSMFB_OVERLAY_SET, &ov) < 0) {
         ALOGE("Failed to call ioctl MSMFB_OVERLAY_SET err=%s",
                 strerror(errno));
         return false;
      }
      return true;
 }

对应在kernel下面的ioctl语句也很简单：
 
 ...
 case MSMFB_OVERLAY_SET:
  ret = copy_from_user(&req, argp, sizeof(req));
  if (!ret) {
   ret = mdss_mdp_overlay_set(mfd, &req);

   if (!IS_ERR_VALUE(ret))
    ret = copy_to_user(argp, &req, sizeof(req));
  }
  if (ret)
   pr_debug("OVERLAY_SET failed (%d)\n", ret);
  break;
 ...

mdss_mdp_overlay_set只是得到了一个锁，而且打印出来kernel里面执行的时间：

mdss_mdp_overlay_ioctl_handler end time_sec: 0, time_nsec :21771

只有0.021ms，user space(30ms)跟kernel space(0.021)的时间不是在一个数量级的。这种user space跟kernel space耗时完全不一致的原因，可能是因为进程调度引起，当然真正的原因需要分析，只是猜测。

通过使用Ftrace分析，产生的原因是SurfaceFlinger在做这个动画的时候，会有block的情况:

 sched_stat_blocked: comm=SurfaceFlinger pid=379 delay=26675625 [ns]

SurfaceFlinger被阻塞了(26ms)。但为什么被阻塞以及是否因为阻塞导致setOverlay 耗时异常，却不得而知。如果知道setOverlay耗时异常的原因，也就找到了产生问题的真正原因。

    这个问题分析到这的时候，我已经跟了三周了。而三周后，我确依然毫无头绪，因为分析到到这的时候，我没有办法继续往下走了，芯片商有4个工程师跟过此问题了，但原因还没有找到。此问题变的越来越棘手了，我却越来越失望，越来越消沉了，我看不到希望，我开始慢慢浮躁，慢慢焦虑，自从跟这个问题以来，我睡不好，吃不爽，心里总有疙瘩一样，现在问题却这样不死不活，我能不失望，能不浮躁吗？此时，我有多想念SystemTap、Dtrace呀！可惜Android没有这种Dynamic
Trace工具！

    我不想就这样放弃这个问题，不想把希望仅仅寄托着芯片供应商上，而且从当前的效果来看，他们并没有起到实质性的作用，只能靠自己了，硬着头皮上吧！。我重头开始分析问题，当问题原因无法找到时，只能再来一遍，如果还是没有结果，那就继续在来一遍，我也不知道自己试了多少遍，如果没有找到问题的原因，说明遗漏了什么。

     终于有一个周五的下午天，我似乎有点眉目了，但是因为是周五下午，而且还出现了另外一个问题，把我打断了。我只能在痛苦中渡过了双休，其实我想去加班看一下的，但我想还是算了，自己觉得有不太对，周一过来验证一下自己的猜想吧！

     问题是这样的，我发现A版本上(也就是不会出现卡顿的版本),每次进入退出动画时，SurfaceFlinger调用dequeueBuffe次数比B版本上（也就是有卡顿的版本上）少。但是周五的我初步的看了一下，dequeueBuffe的调用流程是这样的：

doTraversal 
 ...ViewRootImpl.java

->performTraversals ...ViewRootImpl.java

-> performDraw ...ViewRootImpl.java

-> draw ....ViewRootImpl.java

->mHardwareRenderer.draw ...ViewRootImpl.java

->drawSoftware ...ViewRootImpl.java

->lockCanvas ..ViewRootImpl.java

->surface.lock ...android_view_surface.cpp

->Surface::lock ...Surface.cpp

->Surface::dequeueBuffer
Surface.cpp

dequeueBuffe获取一个可用的buffer。

->unlockCanvasAndPost ...ViewRootImpl.java

要求跟新显示，把视图绘制到屏幕上。

           
     我多希望在应用进出的动画时不仅仅走的不是这个流程呀？如果仅仅走的是这个流程的话，我的跟踪将又是豪无意义的的。为什么呢？如果仅走的是这个流程，说明绘制的时候用的是software的方式，怎么可能是这样呢？我希望应用进出的动画里面的dequeueBuffer是希望在别的地方调用的，那样也行还有一点希望。

     
     注定我的周末是痛苦的，我之所以没有抱太多的希望，是因为我已经经历过很多次这样了，每次的猜测都被证明是错误的，虽然没有证明一千种材料都不适合做灯丝那么多!
     
     过完周末，周一回来后，我在这个流程的里面添加log后发现dequeueBuffe次数比这个流程的次数多，说明还有地方使得系统调用了dequeueBuffe。

     
     当然，如果你知道WindowAnimator.java里面用的是

        SurfaceControl.openTransaction();

        SurfaceControl.setAnimationTransaction();

...

SurfaceControl.closeTransaction();

我想，应该是可以知道没有到View的一级去的，直接就到SurfaceFlinger里面了。
      
     通过打出堆栈信息，验证我的结论是正确的。SurfaceFlinger在handle去handleMessageRefresh里面是会通过OpenGL ES去调用可以去dequeuebuffer，堆栈信息如下：

12-23 12:51:25.785 11736 11738 D : #00 pc 0001e7c6 /system/lib/libgui.so (android::BufferQueue::dequeueBuffer(int*, android::sp<android::Fence>*, unsigned int, unsigned int, unsigned int, unsigned
int)+117)

12-23 12:51:25.785 11736 11738 D : #01 pc 000270fe /system/lib/libgui.so (android::Surface::dequeueBuffer(ANativeWindowBuffer**, int*)+89)

12-23 12:51:25.785 11736 11738 D : #02 pc 0002746c /system/lib/libgui.so (android::Surface::hook_dequeueBuffer_DEPRECATED(ANativeWindow*, ANativeWindowBuffer**)+47)

12-23 12:51:25.785 11736 11738 D : #03 pc 000037ba /system/vendor/lib/egl/eglsubAndroid.so

12-23 12:51:25.785 11736 11738 D : #04 pc 0000a66c /system/vendor/lib/egl/libEGL_adreno.so (egliSyncBackBuffer+248)

12-23 12:51:25.785 11736 11738 D : #05 pc 00076b90 /system/vendor/lib/egl/libGLESv2_adreno.so (rb_surface_sync_for_resolve+27) 

12-23 12:51:25.785 11736 11738 D : #06 pc 00076bf8 /system/vendor/lib/egl/libGLESv2_adreno.so (rb_perform_rendering_target_sync+35)

12-23 12:51:25.785 11736 11738 D : #07 pc 00076c44 /system/vendor/lib/egl/libGLESv2_adreno.so (rb_setup_resolve+27)

12-23 12:51:25.785 11736 11738 D : #08 pc 0007702c /system/vendor/lib/egl/libGLESv2_adreno.so (rb_perform_resolve+187)

12-23 12:51:25.785 11736 11738 D : #09 pc 000773f0 /system/vendor/lib/egl/libGLESv2_adreno.so (rb_resolve+363)

12-23 12:51:25.785 11736 11738 D : #10 pc 0007ba0a /system/vendor/lib/egl/libGLESv2_adreno.so (rb_surface_swap+213)

12-23 12:51:25.785 11736 11738 D : #11 pc 0005fee6 /system/vendor/lib/egl/libGLESv2_adreno.so (gl2_surface_swap+69)

12-23 12:51:25.785 11736 11738 D : #12 pc 00051ad2 /system/vendor/lib/egl/libGLESv2_adreno.so (oglSwapBuffer+85)

12-23 12:51:25.785 11736 11738 D : #13 pc 0002448c /system/vendor/lib/egl/libGLESv1_CM_adreno.so (oglSwapBuffer+7)

12-23 12:51:25.785 11736 11738 D : #14 pc 00012bf4 /system/vendor/lib/egl/libEGL_adreno.so (qeglDrvAPI_eglSwapBuffers+1864)

12-23 12:51:25.785 11736 11738 D : #15 pc 00006bd0 /system/vendor/lib/egl/libEGL_adreno.so (eglSwapBuffers+16)

12-23 12:51:25.785 11736 11738 D : #16 pc 0000fb1a /system/lib/libEGL.so (eglSwapBuffers+277)

12-23 12:51:25.785 11736 11738 D : #17 pc 0001ead4 /system/lib/libsurfaceflinger.so (android::DisplayDevice::swapBuffers(android::HWComposer&) const+131)

12-23 12:51:25.785 11736 11738 D : #18 pc 00024b2e /system/lib/libsurfaceflinger.so (android::SurfaceFlinger::doDisplayComposition(android::sp<android::DisplayDevice const> const&, android::Region
const&)+121) 

12-23 12:51:25.785 11736 11738 D : #19 pc 000270ec /system/lib/libsurfaceflinger.so (android::SurfaceFlinger::doComposition()+95) 

12-23 12:51:25.785 11736 11738 D : #20 pc 00027348 /system/lib/libsurfaceflinger.so (android::SurfaceFlinger::handleMessageRefresh()+47)

12-23 12:51:25.785 11736 11738 D : #21 pc 00027e0c /system/lib/libsurfaceflinger.so (android::SurfaceFlinger::onMessageReceived(int)+63)

12-23 12:51:25.785 11736 11738 D : #22 pc 000150ea /system/lib/libutils.so (android::Looper::pollInner(int)+381)

12-23 12:51:25.785 11736 11738 D : #23 pc 000151ec /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+91)

12-23 12:51:25.785 11736 11738 D : #24 pc 00023444 /system/lib/libsurfaceflinger.so (android::MessageQueue::waitMessage()+35)

12-23 12:51:25.785 11736 11738 D : #25 pc 000241d0 /system/lib/libsurfaceflinger.so (android::SurfaceFlinger::threadLoop()+1)

12-23 12:51:25.785 11736 11738 D : #26 pc 00011a8a /system/lib/libutils.so (android::Thread::_threadLoop(void*)+213)

12-23 12:51:25.785 11736 11738 D : #27 pc 0001157e /system/lib/libutils.so

12-23 12:51:25.785 11736 11738 D : #28 pc 0000cb60 /system/lib/libc.so (__thread_entry+72)

12-23 12:51:25.785 11736 11738 D : #29 pc 0000ccdc /system/lib/libc.so (pthread_create+208)

    这就是说A版本跟B版本在绘图的流程上是有不同的，通过这个堆栈，不断的debug后发现发现是HWComposer::prepare进行layer的合成是不一样的。在A版本中HWComposer::prepare中判断的layer是HWC_OVERLAY，即合成的时候使用的是overlay的方式，在B版本上，HWComposer::prepare中判断的layer是HWC_FRAMEBUFFER，即合成的时候，使用的是GPU的方式。

    通过对比A、B的版本后发现，应用进出动画时：

 1、A版本，SurfaceFlinger Layer只用了overlay合成
 2、B版本，SurfaceFlinger Layer合成是overlay与GPU一起完成的。

这也能解释出A版本，把overlay关闭只用GUP合成也是会卡顿，以及B版本把SystemUI.apk删除后(删除SystemUI.apk后这个版本应用进出时只使用了overlay合成)，动画不会卡顿，顿时问题豁然开朗了，心里的一颗大石头落下来了。

    如果仅仅从performance角度来说，这个问题可以到此为止了，因为已经定位出来了问题的模块了，由模块跟踪就可以了，但悲催的是，我还得继续跟踪着，唉！。
   
    而此时，芯片供应商也换了一个做display的高手来处理问题了，通过他们的调试后发现，卡顿的时候SurfaceFlinger会同时进行六、七层的合成，而他们的平台在四层以下性能是最好的，此时GPU性能完全不够了，需要对这块进行优化。
    
    我很早就想把这个问题总结以下了，苦于一直忙的不可开交，吾日三省吾身的机会都没有，趁着今天元旦放假休息，记录下来，以此祭奠自己那不悔的青春，前前后后在此问题上花了至少一个半月的时间，真狗血。骚年，还是不要去做performance吧！看着华丽，仅仅是看着！这是一个坑呀！玩笑而已，不要当真！其实做performance还是有一定的乐趣的，虽然苦一定、累一定！个人感觉！

2014//01//06更新：
当我看到有卡顿的情况时，GPU的频率是这样：

330000000

330000000

330000000

330000000

330000000

330000000

330000000

而修改了一个不卡顿的版本时，GPU的频率是这样：

330000000

578000000

330000000

330000000

578000000

578000000

578000000

578000000

578000000

578000000

462400000

这是在不停测试的时候发现的问题，我希望这辈子都不要再遇到这种什么CPU调频或者GPU调频机制的问题。看来最有希望找到问题原因的人，还是自己，相信自己吧！不要老把希望寄托在别人身上！自己是唯一能靠的住的人！别人顶多能协助一下你。

当我周五的时候回去7点就睡了，第二天早上10点才起来的时候，就知道有多折腾，当芯片供应商有display team、performance team、graphic team的四五个人在跟这个问题，我确一个人把他扛了两个月的时候，就知道我有多悲催。此处省略一万字的感慨！