今日头条 ANR 优化实例剖析 <二>

案例四:进程内IO负载异常

上面重点介绍了主线程内部环境导致问题的相关案例,介绍当前消息耗时严重,历史消息耗时严重,以及消息密集这几种类型的分析思路,接下来再分析一个进程内 IO 抢占的案例,下面就来看看如何层层拨云揭雾,寻找真相的。

主线程 Trace 堆栈:

问题分析:

堆栈分析:

上面这个 Trace 信息,也是无从下手,堆栈本身是一个很清晰的系统逻辑,但是现实中确实也有大量 ANR Trace 落在这个场景,难道是系统进入 epoll_wait 之后,没有被及时唤醒?但是从理论上来说这些假设不存在。既然堆栈信息没有太明显,我们就把方向转移到系统侧,看看是否有线索。

系统&进程负载分析:

观察系统负载: 在 ANR Info 中我们搜索 Load 关键字,发现系统各个时段(前 1,5,15 分钟)负载明显很高,并且最近 1 分钟负载为 71,又明显高于前 5,15 分钟,说明有系统负载进一步加重!

观察进程 CPU 分布: 进一步观察 CPU usage from 0 ms to 21506 later 关键字,看到ANR 之后这段时间,内核线程 kworker 的 CPU 占比明显偏高,累计占比超过 45%!其它系统或应用进程 CPU 使用率普遍偏低。 通过前文介绍我们知道 kworker 属于内核线程,当 IO 负载过重时会在该线程有所体现。进一步观察 kswapd0 线程 cpu 使用率,发现只有 2%,而 kswapd0 主要应用在内存紧张的场景,说明这段时间系统内存负载基本正常。通过上面这些信息解读,可以大致推测最近一段时间系统负载过高,应该是 IO 请求导致,至于系统内存压力尚可接受,接下来我们继续求证。

系统 CPU 分布:

观察进一步分析系统整体负载,发现 user 占比只有 5.4%,kernel 占比 11%,但是 iowait 占比高达 57%!明显高于 user,kernel 使用率,说明这段时间系统 IO 负载非常严重。

而这个 IO 占比较高,也进一步实锤了我们上面的“观察进程 CPU 分布”的结论。那么是哪个应用导致的呢?遗憾的,受限于系统日志获取能力,依靠现有的信息并没有明显看到异常进程,那么 IO 发生在哪里,是否和当前进程有关呢?于是我们将思路再次回到应用内部。

应用侧分析:

通过上面的分析,我们基本锁定了是 IO 负载过重导致的问题,接下来便要进一步排查是否是当前进程内部存在异常,于是我们对比了各个线程的耗时(utm+stm)情况:

通过上图线程耗时对比可以清晰的发现,DBHelper-AsyncOp-New 线程无论是 utm 时长,还是 stm 时长,都明显超过其它线程,而 stm 高达 2915! 这个耗时超出了我们的预期,实际场景中我们认为主线程才 CPU 消耗大户,其它线程都是配角。下面我们再看一下线程详情:

进一步查看该线程堆栈,发现存在明显的 IO 操作,而且子线程优先级(nice=0)相对较高,stm(2915)+utm(1259)高达 4000+,换算成时长相当于 CPU 真实执行超过了 40S!

对比主线程耗时(utm:1035,stm:216),以及进程启动时长(4 分 18 秒),可以更好证明了 DBHelper 线程存在异常,stm 明显过长,说明存在大量系统调用,结合该线程业务,可以很快就猜到是 IO 读写引起的问题了。因为该线程本身就是负责应用内部数据库清理功能的。

经过上面的分析之后,下面来看一下主线程调度时序图,看看 IO 负载过重对主线程有多大影响。

消息调度时序图分析

通过上图,可以清晰看到 ANR 消息之前,有多个历史消息耗时存在明显异常,而且 Wall duration 与 Cpu duration 耗时比例差距较大,部分消息 cpu 时长更是小于 1ms(单位 ms,0 则表示小于 1ms),说明在此期间主线程整体调度受到很大影响,而且这些消息内部涉及 IO 访问的逻辑将会受到更大影响。

同时结合我们现场 checkTime 机制,发现 checkTime 调度明显存在严重 delay 情况。

问题结论:

带着上面这些分析信息和数据,我们可以得出如下结论:通过层层分析我们可以发现,发生ANR时的当前消息耗时近2S,但并不是root case,主线程出现多个历史消息耗时,但也不是root case,真正导致本次ANR的原因是DBHelper-AsyncOp线程在过去一段时间进行了长时间的IO操作,严重影响了主线程乃至进程本身的CPU调度,导致后续消息响应不及时,触发系统超时(ANR)。

对于该类问题,除了应用本身优化之外,也与一些机型设备差异有关,例如不同机型 IO 性能本身就存在很大差异,因此理论上无法彻底解决。同时无论是进程内部还是其他进程进行 IO 密集操作,都可能引起系统 IO 负载过重,进而导致系统乃至所有进程调度受到影响,对于该类问题只能进一步的优化相关逻辑,降低 IO 访问频率,减少主线程 IO 访问等等

这类问题,在线上比较常见,但是在开发同学的线下测试过程,性能普遍符合预期,针对线上用户,应用场景错综复杂,绝非线下能模拟,并且针对不同手机设备,不同芯片平台,甚至磁盘可用空间的差异,其 IO 性能也表现的千差万别而这些小概率的问题,在数亿万用户环境中,会频频出现。

案例五:其它进程及系统负载异常

前面我们分析的几类问题,基本都是应用进程内部因素导致的问题,如主线消息耗时,消息密集执行,子线程 IO 资源抢占等等。线上环境中,除了进程或主线线程自身因素导致的问题外,还有一些是外部因素导致的问题,如其它进程或系统负载过重,进而影响当前进程正常调度。下面我们就来看一看这类问题是如何分析的。

主线程 Trace 堆栈:

问题分析:

堆栈分析:

看到上面这个 Trace 信息,同样是熟悉的味道,发生 ANR 时,系统正处于 epoll wait 状态,线程 utm 及 stm 耗时并不算长,累计(376+340)*10=7160ms。观察到这里基本没有看到太多有效信息。接下来继续把方向转移到系统侧,看看是否有线索可循。

系统&进程负载分析:

观察系统负载: 在 ANR Info 中搜索 Load 关键字,看到系统在各个时段(前 1,5,15 分钟)负载比较高,分别为 37.09,39.37,49.44,呈现加重趋势。

观察进程 CPU 分布: 进一步观察"CPU usage from 2401 ms to -22043ms ago"期间,各个进程 CPU 占比情况,看到这段时间目标进程 cpu 使用率很低,只有 17%。看到其它关键进程或线程,如 Kswapd0 线程,cpu 占比 20%,对于该线程来说,其出现则表示系统内存比较紧张了,而且看到了与其相关的 kworker,mmcqd 线程 cpu 占比也比较高。这些线程同时出现,足以说明当前系统环境发生了比较大的问题。

而系统资源紧张,一般是因为某个或多个进程出现内存泄漏或大量 IO 读写导致,结合上面 Top 进程的 CPU 占比,com.youku.phone 以及 com.android.contacts 进程可疑性最大。而发生 ANR 问题的 com.ss.android.article.news 进程其 CPU 占比只有 17%。

观察系统 CPU 分布:

通过上图信息可以看到,系统 CPU 整体使用率达到 54%,kernel 占比 15%,iowait 占比高达 24%,有些偏高。说明系统负载确实存在异常,其结论与我们上面分析的基本一致。

当然在这里比较遗憾的是,因为是线上问题,我们无法通过拿到系统以及其它进程更多信息,否则可以更加清晰的看到发生异常的是哪个进程, 但是接下来要进一步排除是当前进程导致的系统负载问题,我们将视野再次回到应用侧。

应用侧分析:

通过上面的分析,我们基本锁定了是内存负载过重导致的问题,接下来便要进一步排查是否是当前进程内部存在异常,于是我们对比了各线程的耗时(utm+stm)情况:

通过上图可以看到,排名第一的是主线程,其 utm+stm=700,换算成系统时长,70010=7000ms,但是对比观察进程启动时长,发现进程已经启动 108S,我们知道对应进程来说,启动的前 1~2 分钟,主线程是最为繁忙的,大量的业务和系统消息需要在主线程进行执行。同时我们进一步对比系统负载正常的情况,进程启动 2 分钟时主线程 CPU 执行时长明显大于当前时长*。

下面我们再来看一下系统负载过重,对主线程消息调度的影响,如下图:

通过上图,可以清晰看到 ANR 消息之前,有多个历史消息耗时存在明显异常,而且 Wall duration 与 Cpu duration 耗时比例差距较大,从侧面也反映了在此期间主线程整体调度受到较大影响。

超时 Service 消息: 从上图可以清晰看到第一个待调度消息,其 Block 时长超过 18S 之多,接近于前面诸多耗时消息之和。同时从下图可以清晰看到发生 ANR 的这个 service 消息在消息队列排在第 8,消息 block 时长为 18482ms。

在前文应用四大组件超时归类中提到 Service 超时时长分别为 20S 或 200S,现在该消息在应用侧 block 时长为 18482ms,那就说明剩下 1S 多的时间,耗费在系统 AMS 服务发送到客户端 Binder 线程接收过程,否则没有达到 20S 超时,是不会触发系统超时的。因此也进一步说明了系统调度性能存在问题

问题小结

带着上面这些分析信息和相关数据,我们可以得出如下结论:在进程启动前,系统负载已经很重,整个系统调度性能受到较大的影响,尽管发生 ANR 时当前堆栈耗时较长,但并不是 root case,多个历史耗时严重的消息也不是 root case,而导致本次 ANR 的应该是 com.youku.phone 或 com.android.contacts 进程,在过去一段时间进行大量系统资源访问,造成系统负载加重,严重影响了其他进程 CPU 调度,导致主线程消息处理不及时,触发系统超时(ANR)

对于该类问题,因为是其它进程导致系统资源紧张,进而影响了当前进程,因此我们无法从根本上解决,当然能够很好的分析并找出原因,也是对待问题的一种态度吧。

案例六:跨进程死锁

在前面更多从应用侧介绍了 ANR 案例的分析思路,接下来看看如何借助更多系统日志分析这类问题。当然,这类问题如果发生在线上,会因为应用侧无法获取跨进程 Trace 的原因,可能会被误归类为 IPC 耗时场景。

主线程 Trace 堆栈:

问题分析:

堆栈分析:

根据前面讲到的问题分析思路,先观察 Trace 主线程堆栈,从上面堆栈,可以看到业务逻辑发生 Binder 调用被 Block 的情况,但是这次拿到的是完整的 Trace 日志,那么接下来就沿着 Binder 请求逻辑,看一下响应进程的状态。

服务进程分析:

首先查找客户端主线程在和哪个 Binder 线程进行通信,搜索代理接口setAppCallback(Android 命名习惯,代理端和服务端函数命名基本保持一致),发现是 Nfc 的 Binder_3 线程响应了客户端请求:

但是进一步观察堆栈信息,发现 Binder_3 线程被当前进程的主线程 Block,那么沿着这个线索看看主线程状态:

观察主线程状态,发现此刻主线程也在执行 Binder 通信,请求createBeamShareData,同样根据命名习惯,继续搜索关键字createBeamShareData,看看这次请求是哪个进程在响应,结果发现是 ANR 所在进程的 Binder_6 线程响应此请求。

通过观察 Binder_6 线程的堆栈和状态,发现该线程处于 await 状态,明显是在等待其它线程通知唤醒!分析到这里,就需要大家结合 Read the Fuck Code 的精神进一步分析业务逻辑了,在研究一番业务逻辑之后,发现唤醒此线程的业务逻辑,已经通过 Handler 发送到主线程,正等待主线程执行呢,但是如果时序处理的不恰当,就会出现主线程还没来得及执行这个消息,就去监听 NFC 状态,进而引起了连锁反应。至此找到了依赖链路:

通过上图可以清晰的看到本次 ANR 原因:跨进程死锁。

总结:

我们按照前文 ANR 影响因素及归类分别选取了一个线上案例,并进行分析总结。回过头来看,第一类问题按照多数人的"解题思路"可能会很快的找到答案。在面对第二类问题时,如果没有监控工具就可能掉入“Trace 陷阱”了。第三类问题并不常见,但是在公司多个产品都有遇到过,因为这类问题更加隐蔽,如果依靠现有系统日志只能锁定方向,之后需要耗费大量的时间去添加埋点分析定位,但是通过我们的监控工具直观展示并暴露了更多细节,为成功定位问题扮演了关键角色。后面两类因为资源抢占的导致线程调度不及时的问题,通过监控工具很好的还原了 ANR 之前消息调度情况,更加清晰的证实了资源竞争对主线程的影响。

掌握了上述几类问题的分析思路,相信可以帮助大家应对工作中遇到大部分问题,但是所谓“林子大了,什么鸟都有”,下一篇将会介绍「barrier导致主线程假死」,「Service执行时序颠倒」等更加棘手的案例,敬请期待。

PS:关于我


本人是一个拥有6年开发经验的帅气Android攻城狮,记得看完点赞,养成习惯,关注这个喜欢写干货的程序员。

另外耗时两年整理收集的Android一线大厂面试完整考点PDF出炉,【完整版】已更新在我的【Github】,如有面试、进阶需要的朋友们可以去参考参考,如果对你有帮助,可以点个Star哦!

地址:【https://github.com/733gh/xiongfan】

推荐阅读更多精彩内容