开关机压力测试时卡 bootanimation 分析

N久前写的技术分析报告，现在发出来，希望能帮到有需要的人。

一、现象描述

  做 开关机压力测试，重启时会概率性卡在开机logo处。

  对 system server 发送 signal 6 后能恢复启动,正常进入 launcher。

  复现概率为 16/70000。

二、问题分析

1、分析 log

  初步分析开机log，检查system server主线程，发现每次都随机卡在system_server 启动的不同阶段。

  有卡在 input method 启动阶段，system server 直到收到人为发送的 signal 6，才继续启动下一个 service:Accessibility Manager。

01-01 08:00:09.182 2093 2093 I SystemServer: Input Method Service
01-03 09:06:18.032 2093 2093 I SystemServer: Accessibility Manager

  有卡在 PMS 扫描 apk 阶段：

01-01 08:00:08.095 2101 2101 D PackageManager: Parsing: /system/priv-app/SystemUI
01-03 22:48:19.604 2101 2101 D PackageManager: Parsing: /system/priv-app/UsbInfoStatics

  还有卡在 launcher 启动阶段。

2、具体分析

  由于 system server 主线程卡住， log 中也没有有用信息可以分析，这时可以打印system server 的调用栈，通过分析 system server 的调用栈就能确切知道出问题时 system server 卡在什么地方。

  打印调用栈的方法:

  (1)mkdir /data/anr;

  (2)touch /data/anr/traces.txt;

  (3)chmod -R 777 /data/anr;

  (4)kill -3

  调用栈会打印到/data/anr/traces.txt 里面。

  通过抓取 traces 文件,可以发现 system server 主线程都 block 在同一个地方。问题豁然开朗。

  继续分析 traces.txt。

  Traces.txt 中 System server 的 main thread 调用栈如下图。



  用 Android 自带的 addr2line 和 symbol 文件,根据 traces 中的地址,可以将调用栈和代码对应起来。 symbol 文件在 out/target/product/athena/symbols/system 对应的目录下面。



  执行后,traces 中地址所对应的 art 代码:

/home/sungl/project/hisi-l-551/art/runtime/entrypoints/quick/quick_jni_entrypoints.cc:72
/home/sungl/project/hisi-l-551/art/runtime/entrypoints/entrypoint_utils-inl.h:646
/home/sungl/project/hisi-l-551/art/runtime/thread-inl.h:128
/home/sungl/project/hisi-l-551/art/runtime/base/mutex-inl.h:43

  根据如上代码,加上 traces,分析发生卡 logo 的具体原因。

  System server 主 线 程 触 发 GC , system server 主 线 程 调 用GcDaemon 线 程 的requestGC, 唤起 GCDaemon 去执行 GC 相关操作。



  GCDaemon 线程收到主线程的 GC 请求后,通过 JNI 调用 libart.so,执行相关 GC 操作。这时 systerm server 主线程会处于 Suspend 状态,等待 GCDaemon 相关状态更新后systerm server 主线程会恢复为 Runnable 状态。

  分析 libart 的调用栈。

(1)/home/sungl/project/hisi-l-551/art/runtime/entrypoints/quick/quick_jni_entrypoints.cc:72





  Traces 中看到各个线程的状态在 art 中也有定义。从定义中可以看出,当前 system server 主线程为 Suspended 状态,即是被 GCDaemon 线程给 Suspend 了。



(2)/home/sungl/project/hisi-l-551/art/runtime/entrypoints/entrypoint_utils-inl.h:646

  TransitionFromRunnableToSuspended 是将 Runnable 状态改为Suspended 状态, TransitionFromSuspendedToRunnable 是将 Suspended 状态改为 Runnable 状态。





(3)/home/sungl/project/hisi-l-551/art/runtime/thread-inl.h:128

  当 kSuspendRequest 为 1 时会进入 while 循环,resume_cond_的 condition wait 一直等待唤醒,这个地方也是 system server 主线程最终卡住的地方。



  继续分析 kSuspendRequest 的值是如何改变的。

  在 ModifySuspendCount 可以看到,当 suspend_count 为 0 时,即 suspend 线程为空，则将 kSuspendRequest 复位为 0。



  那什么时候 resume_cond_的 condition wait 会被唤醒呢?

  当主线程被 art 虚拟机 resume 的时候,就会发送 resume_cond_,唤醒 system server主线程。



  总结一下调用流程:

  主线程在从 Suspend 状态切换到 Runnable 状态时,当还有线程处于 suspend 状态，即 kSuspendRequest 为 1,主线程会进入 wait,等到其他线程都 resume 了,art 虚拟机会发 送 resume_cond_ 的 signal 唤 醒 主 线 程 , 这 时 由 于 没 有 线 程 处 于 suspend 状 态，kSuspendRequest 为 0,会退出循环,主线程继续执行下去。

3、问题解决

  从以上分析可以看出,出现这个问题,要么是 suspend_count 计数有问题导致退不出循环,要么是虚拟机没有发送 resume_cond_的 signal。

  但这个问题很明显是 art 虚拟机的原生问题,通过查看 Android 6.0 的提交,找到了相关的修改。

  相关commit如下。

（1）

commit 079101a17575114622f6e1d5be5c9ba643630e9a
Author: Mathieu Chartier <mathieuc@google.com>
Date:   Mon Dec 15 14:23:10 2014 -0800

Move GC daemon locking logic into heap

Fixes deadlock caused by acquirng the mutator lock while
synchronizing on the daemon thread.

Bug: 18739541
Change-Id: I925b8f0f3b58178da6eff17b9c073f655c39597b

（2）

co
4000
mmit 82a800d1408937951155f546a3671b83b7379ab5
Author: Mathieu Chartier <mathieuc@google.com>
Date:   Mon Dec 15 15:59:49 2014 -0800

Decrement suspend count if thread is shutting down

Prevents deadlock caused by incrementing suspend count in
SuspendThreadByPeer, then getting a cleared nativePeer field. This
resulted in us not decrementing the suspend count which caused a
deadlock in WaitForOtherNonDaemonThreadsToExit.

Bug: 18739541
Change-Id: I4a63f1823993a0f99f32025cd479072be49ba8d5