退出U盘模式后滑动Launcher卡顿的问题分析

最新推荐文章于 2022-06-05 12:46:51 发布

欧军礼

最新推荐文章于 2022-06-05 12:46:51 发布

阅读量3.1k

点赞数 1

分类专栏： Android性能优化

本文链接：https://blog.csdn.net/oujunli/article/details/19068381

版权

Android性能优化专栏收录该内容

34 篇文章 4 订阅

订阅专栏

最近公司的手机发现退出U盘模式后，在U盘存有图片等内容比较多的情况下，滑动Launcher会有一段时间卡顿的现象。其实不是最近的项目才有的问题，以前的项目就有，一直都没有解决而已，顽疾。

当然，是在U盘不同模式直接切换的时候出现了问题，跟负责Vold的一起分析了一下，没有发现什么异常的地方。测试的时候发现，U盘存储的内容越多，出现卡顿情况的时间越长，可能与media进程有关。不管怎么样，media是在后台进行数据扫描，此时耗费CPU比较多，滑动桌面占用的CPU资源也比较大，按这样的思路，应该是在在CPU的使用上有冲突。top了一下，media在扫描的时候占有的CPU确实比较高，在20%~40%之间。

1830 1 27% S 14 1230360K 53056K bg u0_a30 android.process.media

找负责media的同事一起看看吧!

media的同事说，所有的Android手机都一样，在扫描的时候，CPU占用都是这么高，是没法降低的，看来，media是无法解决了。但是我在对比其他厂家的机器时，却没有发现这个时候滑动Launcher卡顿的情况。我想，竟然觉得瓶颈在CPU上，把CPU全部设置成performance状态，应该问题会有所改善吧？于是尝试了一下，结果问题没有任何的改善！

这是什么情况？难道不是因为竞争CPU而导致的卡顿。问题又毫无头绪了，人生大起大落实在是太快了。明明可以看到Launcer和media占用的CPU都很高，确不是因为CPU的瓶颈导致的问题！！！虽然把CPU设置成performance后，CPU的使用率是降低了，但卡顿现象还是存在的。再用Systrace看了一下，没有发现蛛丝马迹。难道Launcher有问题？找Launcher同事一起分析！

跟Launcher同事一起看了一下Systrace文件，也没有发现问题。当时讨论的时候，我便瞎想起来，如果不是CPU引起的问题，那是不是因为内存引起的呢？毕竟media跟Launcher竞争的资源并不多，除了CPU，也就只有内存影响比较大了。于是我们在刚开始滑动Launcher跟Launcher停止的时候都添加了log，过滤dalvikvm和添加的log后，发现，在卡顿的时候，都有GC的操作。在media扫描的时候，media不仅自己进行了大量的GC，还引起了system_server的GC：

02-11 10:35:30.008 D/dalvikvm(13845): GC_EXPLICIT freed 89K, 36% free 93009K/143540K, paused 2ms+6ms, total 50ms

02-11 10:35:30.058 D/dalvikvm(14440): GC_EXPLICIT freed 592K, 23% free 26298K/34112K, paused 2ms+5ms, total 30ms

02-11 10:35:30.388 D/dalvikvm(13845): GC_EXPLICIT freed 92K, 36% free 93009K/143540K, paused 4ms+10ms, total 91ms

02-11 10:35:30.728 D/dalvikvm(13845): GC_EXPLICIT freed 105K, 36% free 93011K/143540K, paused 3ms+8ms, total 65ms

02-11 10:35:30.768 D/dalvikvm(14440): GC_EXPLICIT freed 597K, 23% free 26298K/34112K, paused 1ms+4ms, total 19ms

02-11 10:35:30.968 D/dalvikvm(13845): GC_EXPLICIT freed 92K, 36% free 93009K/143540K, paused 2ms+9ms, total 70ms

02-11 10:35:31.238 D/dalvikvm(13845): GC_EXPLICIT freed 92K, 36% free 93009K/143540K, paused 3ms+7ms, total 70ms

02-11 10:35:31.288 D/dalvikvm(14440): GC_EXPLICIT freed 600K, 23% free 26299K/34112K, paused 1ms+4ms, total 28ms

02-11 10:35:31.568 D/dalvikvm(13845): GC_EXPLICIT freed 183K, 36% free 93025K/143540K, paused 3ms+6ms, total 77ms

02-11 10:35:31.828 D/dalvikvm(13845): GC_EXPLICIT freed 102K, 36% free 93014K/143540K, paused 5ms+6ms, total 65ms

02-11 10:35:31.868 D/dalvikvm(14440): GC_EXPLICIT freed 600K, 23% free 26299K/34112K, paused 1ms+3ms, total 25ms

02-11 10:35:32.128 D/dalvikvm(13845): GC_EXPLICIT freed 107K, 36% free 93015K/143540K, paused 5ms+8ms, total 83ms

02-11 10:35:32.418 D/dalvikvm(13845): GC_EXPLICIT freed 91K, 36% free 93013K/143540K, paused 4ms+10ms, total 89ms

02-11 10:35:32.458 D/dalvikvm(14440): GC_EXPLICIT freed 609K, 23% free 26299K/34112K, paused 1ms+3ms, total 21ms

02-11 10:35:32.658 D/dalvikvm(13845): GC_EXPLICIT freed 104K, 36% free 93015K/143540K, paused 2ms+7ms, total 56ms

02-11 10:35:32.878 D/dalvikvm(13845): GC_EXPLICIT freed 91K, 36% free 93014K/143540K, paused 3ms+8ms, total 66ms

13845和14440分别是system_server跟media进程：

system 13845 13799 1459616 224164 ffffffff 401034ac S system_server

u0_a30 14440 13799 1235768 53220 ffffffff 401045b0 S android.process.media

当然，media的GC我们可以不用关心，我们关心的是system_server进程的GC，因为system_server的GC是引起Launcher卡顿的原因。这个时候，Launcher的同事说，看来我的猜想是对的，我可以当什么家了！！！

于是乎又跑负责media的同事那，一起看了一会log，无法定位到为什么media引起了system_server进行了GC。我让media的同事先看看，自己也回到座位上看看。

我看GC的原因都是GC_EXPLICIT引起的，也就是system_server某个地方主动调用进行了GC操作引起的。我在Heap.cpp里面在GC_EX的地方把堆栈打出来：

02-11 10:52:43.951 D/dalvikvm( 1048): #00 pc 0002bbd0 /system/lib/libdvm.so
02-11 10:52:43.951 D/dalvikvm( 1048): #01 pc 0002c874 /system/lib/libdvm.so (dvmCollectGarbageInternal(GcSpec const*)+2132)
02-11 10:52:43.951 D/dalvikvm( 1048): #02 pc 000586fe /system/lib/libdvm.so (dvmCollectGarbage()+29)
02-11 10:52:43.951 D/dalvikvm( 1048): #03 pc 00029860 /system/lib/libdvm.so
02-11 10:52:43.951 D/dalvikvm( 1048): #04 pc 0002e50c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
02-11 10:52:43.951 D/dalvikvm( 1048): #05 pc 000630d8 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+291)
02-11 10:52:43.951 D/dalvikvm( 1048): #06 pc 0004cc62 /system/lib/libdvm.so
02-11 10:52:43.951 D/dalvikvm( 1048): #07 pc 0004f1d0 /system/lib/libandroid_runtime.so
02-11 10:52:43.951 D/dalvikvm( 1048): #08 pc 0007391e /system/lib/libandroid_runtime.so (android::javaObjectForIBinder(_JNIEnv*, android::sp<android::IBinder> const&)+273)
02-11 10:52:43.951 D/dalvikvm( 1048): #09 pc 0006c2ee /system/lib/libandroid_runtime.so
02-11 10:52:43.951 D/dalvikvm( 1048): #10 pc 000203cc /system/lib/libdvm.so (dvmPlatformInvoke+112)
02-11 10:52:43.951 D/dalvikvm( 1048): #11 pc 0005107e /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+397)
02-11 10:52:43.951 D/dalvikvm( 1048): #12 pc 00029860 /system/lib/libdvm.so
02-11 10:52:43.951 D/dalvikvm( 1048): #13 pc 0002e50c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
02-11 10:52:43.951 D/dalvikvm( 1048): #14 pc 000630d8 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+291)
02-11 10:52:43.961 D/dalvikvm( 1048): #15 pc 0004fd2c /system/lib/libdvm.so
02-11 10:52:43.961 D/dalvikvm( 1048): #16 pc 0006df0c /system/lib/libandroid_runtime.so
02-11 10:52:43.961 D/dalvikvm( 1048): #17 pc 00072c56 /system/lib/libandroid_runtime.so
02-11 10:52:43.961 D/dalvikvm( 1048): #18 pc 00018182 /system/lib/libbinder.so (android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+57)
02-11 10:52:43.961 D/dalvikvm( 1048): #19 pc 0001bdb2 /system/lib/libbinder.so (android::IPCThreadState::executeCommand(int)+505)
02-11 10:52:43.961 D/dalvikvm( 1048): #20 pc 0001c1c2 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+181)
02-11 10:52:43.961 D/dalvikvm( 1048): #21 pc 000200f4 /system/lib/libbinder.so
02-11 10:52:43.961 D/dalvikvm( 1048): #22 pc 00011a8a /system/lib/libutils.so (android::Thread::_threadLoop(void*)+213)
02-11 10:52:43.961 D/dalvikvm( 1048): #23 pc 0004f16a /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+65)
02-11 10:52:43.961 D/dalvikvm( 1048): #24 pc 0001157e /system/lib/libutils.so
02-11 10:52:43.961 D/dalvikvm( 1048): #25 pc 0000cb60 /system/lib/libc.so (__thread_entry+72)
02-11 10:52:43.961 D/dalvikvm( 1048): #26 pc 0000ccdc /system/lib/libc.so (pthread_create+208)

只有binder通信在native的标准流程堆栈信息，没有我想要的比如从java层调用的System.gc这样的操作的地方，无法定位那个地方主动调用了GC操作而引起卡顿，看来打印堆栈在不同的thread里面是没有多大的意义。

为了更好的分析问题，我又抓了一个systrace看了一下，发现Launcher在绘图的时候，system_server确实有GC操作，导致有点时候绘制一帧花费了很长的时间，如下面的这帧：

上面是system_server GC(explicit)，下面是Launcher进程，system_server进程的GC导致Launcher绘图的时候sleep了，导致卡顿。虽然引起卡顿的原因是知道了，但是没有定位出system_server哪个地方主动调用的GC操作导致卡顿了？为什么media会引起这样的操作？从系统的角度来说，能定位出在system_server那块代码导致GC操作是最好不过的，那样可以让media的同事知道自己进行了什么操作而导致问题，好让media进行相应的优化。个人观点，也可以自己不管了，扔给media去折腾吧！问题很明确是他们引起的，但我还是很想知道是什么原因，好奇害死猫！

既然知道是system_server的问题，而且还知道system_server主动调用了java层的像System.gc这样的接口引起的问题，那此时用traceview看看。于是抓了个traceview看了一下，让我大吃一惊：

启动了那边多的bind进程，而且每个都是跑一下就结束了。能看到有明显的GC操作，就是图中紫色的部分：

从函数的调用流程继续往上走，可以看到：

从trace能看到，在linkToDeath跟nativeReadStrongBinder时，引起了BinderInternal forceGC操作，从而导致卡顿的情况。

把trace给media的同事看了一下，跟踪代码发现，在扫描的时候使用的带notify的uri，导致system_server GC了！难怪会导致system_server有那么多的binder通信操作！

看来做系统的就是跑腿的，一会跑Launcher那看看，一会跑media那看看，一会看Vold那看看，谁都不知道是谁的问题，谁也不承认是自己的问题，而且自己又各种不懂，一不小心就被坑了！只有自己慢慢折腾，找到证据了后才好办呀！随便一个问题，都要花费至少几天的时间去分析，能解决最好，很多是最后完全不知道什么原因导致的，从这个角度来说，应用是多么的happy呀！