通过 dump 虚拟机线程方法栈和堆内存来分析 Android 卡顿和 OOM 问题

1,518 阅读10分钟

通过 dump 虚拟机线程方法栈和堆内存来分析 Android 卡顿和 OOM 问题

Android 中的性能问题无非就是卡顿和 OOM,虽然总体就这两种,但是造成这两种性能问题的原因却是非常多,需要具体的原因具体分析,而且这是非常复杂的。本篇文章只是简单介绍如何找到造成这些问题的直接原因的工具(也算是入门分析),更深层次的问题你可能还需要别的知识。

卡顿(ANR)通常是主线程阻塞导致,主线程阻塞也可能有很多其他原因,比如在竞争其他线程的锁,在做耗时的运算,等待 UI 绘制的 Buffer 等等,我们要分析这些问题就需要 dump 所有的线程方法栈,通过这些方法栈再一步一步分析具体问题。

OOM 通常是堆内存增长到最大的限制,导致程序无法继续运行而导致的崩溃,本篇我们主要分析的是 Dalvik 虚拟机栈的内存,而没有 Native 栈的内存(而这部分内存也非常重要,后续考虑单独写文章分析)。

dump 方法栈

如果想要更加直观的展示卡顿问题其实 Systrace 是一个更加好用的工具,它能够更加直观地显示主线程每一帧的耗时,哪一帧对应方法栈(它的方法栈很简单而且没有 native 信息,如果要显示自己栈的信息需要手动在代码添加 trace。)的耗时信息,还有各种的锁信息,Binder 唤醒信息:

systrace.png 我上面的这个图就是造成了掉帧,主线程有大段时间是 sleep 状态,在等待 RenderThread,然后 RenderThread 比较忙在绘制前两次的 VSYNC 数据,然后还在等待 IjkPlayer 线程,IjkPlayer 本身有较多的时间是 Runnable 状态(表示线程等待 CPU 执行,说明先当前时刻 CPU 很忙)。具体想要看 systrace 怎么使用,大家可以找找别的文章。

systrace 相对比较直观,它是截取了程序运行一个时间段内的状态,能够明确发现是哪一帧发生了卡顿,但是相对程序的方法栈信息就比较少,而且这个方法只能够用于调试,无法获取线上用户的数据。
相对于线上用户我们就不能使用 systrace 的方法,而需要在探测到线程卡顿的时候 dump 出所有线程的方法栈信息相对于是比较好的一个方式。
那么怎么探测卡顿呢?我们可以通过设置主线程 Looper 中的 Printer 来监听每个主线程的 Message 的执行时间来判断卡顿,比如这个时候某个 Message 执行超过了 2s 我们就认为卡顿了。如果不了解 Handler 的同学可以参考我的这篇文章:Android Handler 工作原理

那么怎么 dump 所有线程的栈信息呢?在 JavaAndroid 的环境非常简单直接可以通过以下方法获取到所有的栈信息。

val allStacks = Thread.getAllStackTraces()
for ((t, stack) in allStacks) {
    println("Stack in ${t.name}")
    for (s in stack) {
        println(s)
    }
}

以上方法确实简单高效,但是只能获取到简单的 Java 栈,没有 native 信息,没有线程状态,也没有锁状态。

那我们要怎么才能 dump 更加详细的栈信息呢?在 Java 环境中可以使用 jdk 中的工具 jstackdump 线程栈信息,但是它在 Android 中并不能用。那在 Android 中要怎么获取详细的栈信息呢?
Android 发生 ANR 时会向目标应用进程发送 SIGQUITLinux 信号,应用进程默认的信号处线程 Signal Catcherdump 所有的线程栈信息和虚拟机的 GC 信息到本地文件,这些文件在 /data/anr/ 目录下,他们是文本文件,直接读取就好了。但是你可能会说我们只是想要在卡顿时获取,但是卡顿并不一定会触发 ANR。确实是这样,但是我不是说过吗,ANR 通知到应用进程是通过 Linux 信号,如何发送一个 LinuxSIGQUIT 信号并不难,可以上网搜索一下。当收到 SIGQUIT 信号后,Signal Catcher 守护线程就会把栈信息写入到本地文件。
进入 Android 手机的 shell 命令行终端,可以通过 kill -SIGQUIT [pid] 命令来发送 (推荐使用虚拟机更方便获取 root 权限,使用 adb root 获取权限,然后通过 adb shell 进入终端)。
以下是我测试获取的部分堆信息(我没有列出 GC 信息,感兴趣的自己去看看):

// ...

DALVIK THREADS (25):
"Signal Catcher" daemon prio=10 tid=6 Runnable
  | group="system" sCount=0 dsCount=0 flags=0 obj=0x134c0228 self=0xb40000749aad67b0
  | sysTid=8055 nice=-20 cgrp=top-app sched=0/0 handle=0x731950fcc0
  | state=R schedstat=( 94147207 2576958 55 ) utm=5 stm=4 core=3 HZ=100
  | stack=0x7319418000-0x731941a000 stackSize=995KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 000000000049ee50  /apex/com.android.art/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)
  native: #01 pc 00000000005abfa8  /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool, BacktraceMap*, bool) const+376)
  native: #02 pc 00000000005c90e0  /apex/com.android.art/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+924)
  native: #03 pc 00000000005c3020  /apex/com.android.art/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+528)
  native: #04 pc 00000000005c21ec  /apex/com.android.art/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, bool)+1920)
  native: #05 pc 00000000005c168c  /apex/com.android.art/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+776)
  native: #06 pc 000000000056d64c  /apex/com.android.art/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+196)
  native: #07 pc 0000000000582be0  /apex/com.android.art/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1396)
  native: #08 pc 0000000000581bac  /apex/com.android.art/lib64/libart.so (art::SignalCatcher::Run(void*)+348)
  native: #09 pc 00000000000af8c8  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  native: #10 pc 000000000004fe08  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)
  (no managed stack frames)
  
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x725b86a8 self=0xb40000749aad8380
  | sysTid=8045 nice=-10 cgrp=top-app sched=0/0 handle=0x75c13d14f8
  | state=S schedstat=( 3274180825 2052143817 7347 ) utm=263 stm=63 core=0 HZ=100
  | stack=0x7fee25a000-0x7fee25c000 stackSize=8192KB
  | held mutexes=
  native: #00 pc 000000000009bab8  /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
  native: #01 pc 0000000000019ad0  /system/lib64/libutils.so (android::Looper::pollInner(int)+184)
  native: #02 pc 00000000000199b0  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
  native: #03 pc 0000000000110f74  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:335)
  at android.os.Looper.loop(Looper.java:183)
  at android.app.ActivityThread.main(ActivityThread.java:7656)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)


"RenderThread" daemon prio=7 tid=18 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x134c06d8 self=0xb40000749aaf7820
  | sysTid=8067 nice=-10 cgrp=top-app sched=0/0 handle=0x72c27dccc0
  | state=S schedstat=( 5484600361 852151802 11227 ) utm=89 stm=458 core=1 HZ=100
  | stack=0x72c26e5000-0x72c26e7000 stackSize=995KB
  | held mutexes=
  native: #00 pc 000000000009bab8  /apex/com.android.runtime/lib64/bionic/libc.so (__epoll_pwait+8)
  native: #01 pc 0000000000019ad0  /system/lib64/libutils.so (android::Looper::pollInner(int)+184)
  native: #02 pc 00000000000199b0  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)
  native: #03 pc 000000000020ee3c  /system/lib64/libhwui.so (android::uirenderer::ThreadBase::waitForWork()+132)
  native: #04 pc 0000000000230370  /system/lib64/libhwui.so (android::uirenderer::renderthread::RenderThread::threadLoop()+80)
  native: #05 pc 00000000000154d0  /system/lib64/libutils.so (android::Thread::_threadLoop(void*)+260)
  native: #06 pc 0000000000014d94  /system/lib64/libutils.so (thread_data_t::trampoline(thread_data_t const*)+412)
  native: #07 pc 00000000000af8c8  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  native: #08 pc 000000000004fe08  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)
  (no managed stack frames)


"GLThread 266" prio=5 tid=19 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x134c0750 self=0xb40000749aaf93f0
  | sysTid=8070 nice=0 cgrp=top-app sched=0/0 handle=0x72c15e0cc0
  | state=S schedstat=( 37459048343 3167531629 19183 ) utm=257 stm=3488 core=1 HZ=100
  | stack=0x72c14dd000-0x72c14df000 stackSize=1043KB
  | held mutexes=
  native: #00 pc 000000000004aecc  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
  native: #01 pc 00000000001af92c  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
  native: #02 pc 000000000037e750  /apex/com.android.art/lib64/libart.so (art::(anonymous namespace)::CheckJNI::ReleaseStringCharsInternal(char const*, _JNIEnv*, _jstring*, void const*, bool, bool)+508)
  native: #03 pc 00000000000c9388  /system/lib64/libandroid_runtime.so (android_glGetUniformLocation__ILjava_lang_String_2(_JNIEnv*, _jobject*, int, _jstring*)+100)
  at android.opengl.GLES20.glGetUniformLocation(Native method)
  at com.tans.tmediaplayer.render.texconverter.Yuv420pImageTextureConverter$convertImageToTexture$1.invoke(Yuv420pImageTextureConverter.kt:43)
  at com.tans.tmediaplayer.render.texconverter.Yuv420pImageTextureConverter$convertImageToTexture$1.invoke(Yuv420pImageTextureConverter.kt:32)
  at com.tans.tmediaplayer.render.GLUtilKt.offScreenRender(GLUtil.kt:191)
  at com.tans.tmediaplayer.render.texconverter.Yuv420pImageTextureConverter.convertImageToTexture(Yuv420pImageTextureConverter.kt:32)
  at com.tans.tmediaplayer.render.tMediaPlayerView$FrameRenderer.onDrawFrame(tMediaPlayerView.kt:196)
  at android.opengl.GLSurfaceView$GLThread.guardedRun(GLSurfaceView.java:1573)
  at android.opengl.GLSurfaceView$GLThread.run(GLSurfaceView.java:1272)
  
"tMediaPlayerDecoderThread" prio=5 tid=25 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x134c0b20 self=0xb40000749ab056a0
  | sysTid=8083 nice=10 cgrp=top-app sched=0/0 handle=0x72bd3fecc0
  | state=S schedstat=( 50362882932 5311662131 15661 ) utm=4917 stm=119 core=2 HZ=100
  | stack=0x72bd2fb000-0x72bd2fd000 stackSize=1043KB
  | held mutexes=
  native: #00 pc 000000000004aecc  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)
  native: #01 pc 00000000001af92c  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
  native: #02 pc 0000000000669abc  /apex/com.android.art/lib64/libart.so (art::GoToRunnable(art::Thread*)+460)
  native: #03 pc 00000000006698ac  /apex/com.android.art/lib64/libart.so (art::JniMethodEnd(unsigned int, art::Thread*)+28)
  native: #04 pc 00000000020952a0  /memfd:jit-cache (deleted) (offset 2000000) (art_jni_trampoline+160)
  native: #05 pc 0000000002017940  /memfd:jit-cache (deleted) (offset 2000000) (com.tans.tmediaplayer.tMediaPlayer.decodeNativeInternal$tmediaplayer_debug+48)
  native: #06 pc 0000000002012cc0  /memfd:jit-cache (deleted) (offset 2000000) (com.tans.tmediaplayer.tMediaPlayerDecoder$decoderHandler$2$1.dispatchMessage+2848)
  native: #07 pc 0000000002022830  /memfd:jit-cache (deleted) (offset 2000000) (android.os.Looper.loop+1328)
  native: #08 pc 000000000013387c  /apex/com.android.art/lib64/libart.so (art_quick_osr_stub+60)
  native: #09 pc 000000000033d108  /apex/com.android.art/lib64/libart.so (art::jit::Jit::MaybeDoOnStackReplacement(art::Thread*, art::ArtMethod*, unsigned int, int, art::JValue*)+344)
  native: #10 pc 000000000068ae84  /apex/com.android.art/lib64/libart.so (MterpMaybeDoOnStackReplacement+208)
  native: #11 pc 0000000000132350  /apex/com.android.art/lib64/libart.so (MterpHelpers+240)
  native: #12 pc 0000000000397020  /system/framework/framework.jar (offset 92b000) (android.os.Looper.loop+1084)
  native: #13 pc 000000000067f6f0  /apex/com.android.art/lib64/libart.so (MterpInvokeStatic+1224)
  native: #14 pc 000000000012d994  /apex/com.android.art/lib64/libart.so (mterp_op_invoke_static+20)
  native: #15 pc 000000000036eca4  /system/framework/framework.jar (offset 92b000) (android.os.HandlerThread.run+56)
  native: #16 pc 0000000000305c58  /apex/com.android.art/lib64/libart.so (art::interpreter::Execute(art::Thread*, art::CodeItemDataAccessor const&, art::ShadowFrame&, art::JValue, bool, bool) (.llvm.8100235316906539105)+268)
  native: #17 pc 000000000066b1fc  /apex/com.android.art/lib64/libart.so (artQuickToInterpreterBridge+780)
  native: #18 pc 000000000013cff8  /apex/com.android.art/lib64/libart.so (art_quick_to_interpreter_bridge+88)
  native: #19 pc 0000000000133564  /apex/com.android.art/lib64/libart.so (art_quick_invoke_stub+548)
  native: #20 pc 00000000001a8a78  /apex/com.android.art/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+200)
  native: #21 pc 0000000000554c6c  /apex/com.android.art/lib64/libart.so (art::JValue art::InvokeVirtualOrInterfaceWithJValues<art::ArtMethod*>(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, art::ArtMethod*, jvalue const*)+460)
  native: #22 pc 00000000005a4008  /apex/com.android.art/lib64/libart.so (art::Thread::CreateCallback(void*)+1308)
  native: #23 pc 00000000000af8c8  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64)
  native: #24 pc 000000000004fe08  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)
  at com.tans.tmediaplayer.tMediaPlayer.decodeNative(Native method)
  at com.tans.tmediaplayer.tMediaPlayer.decodeNativeInternal$tmediaplayer_debug(tMediaPlayer.kt:496)
  at com.tans.tmediaplayer.tMediaPlayerDecoder$decoderHandler$2$1.dispatchMessage(tMediaPlayerDecoder.kt:51)
  - locked <0x07f95ec5> (a com.tans.tmediaplayer.tMediaPlayerBufferManager$Companion$MediaBuffer)
  at android.os.Looper.loop(Looper.java:223)
  at android.os.HandlerThread.run(HandlerThread.java:67)
  
// ...

除了基础的 Java 栈,还包括 native 的栈信息,每个线程所属于的分组,他们所持有的 mutex 锁信息和栈占用内存大小等等信息。

dump 堆内存

dump 堆内存可不像线程栈那么简单,因为标准的 hprof 文件通常比较大,如果想要获取线上用户的内存信息快照信息,要考虑到上传文件的大小,要考虑上传,需要了解 hprof 文件结构,然后裁剪掉不重要的一些信息,减小需要上传的数据;dump 堆内存还有一个比较重要的问题,就是性能问题,因为本来用户的内存都不够用,手机特别卡,如果再 dump 内存会导致手机更加卡,会比较严重影响用户体验。
所以我认为 dump 线上用户的堆内存,就需要解决上述两个问题,文件过大上传到服务器问题;dump 过程过于消耗设备性能。
我这里直接通过 Android Studio 中的 Profilerdump 堆内存信息,应该还有别的工具可以通过编程的方式来 dump 内存信息,大家可以去网上找找。

使用 Profiler 选中 Memory, 选中 Capture heap dump 表示 dump 堆内存,在你需要的时间点点击 Record,就可以完成 dump

request_dump_stack.png

dump 完成后,就能够看到以下内存的信息:

dump_stack.png

首先可以通过左侧的保存按钮将堆内存快照保存到文件,这是标准的 JVM hprof 快照文件,可以供其他的工具打开。看到右上方有一些重要数据 Classes (类数量),Leaks (内存泄漏的 ActivityFragmentDialog 等等),Count (对象数量,和 Allocations 是一样的),Shallow SizeRetained Size
其他参数都很好理解,但是 Shallow SizeRetained Size 大家可能混淆不清楚,他们只是不同的计算对象内存大小的方式。

  • Shallow Size
    这里举一个例子,假如一个对象包含 1 个 int (4 Bytes) 类型的成员变量;1 个 long (8 Bytes) 类型的成员变量;包含 1 个引用的其他的对象(引用本身占用 4 Bytes,其他对象在堆中占用 10 Bytes),我们不考虑对象头等其他的占用的内存,我们只考虑我们的我们列出来的数据。通过 Shallow Size 计算,该对象占用的内存大小为 4 Bytes + 8 Bytes + 4 Bytes = 20 Bytes,这里就不需要计算引用的对象本身在堆内存中占用的大小。

  • Retained Size
    同样是上面的例子通过 Retained Size 来计算就是 4 Bytes + 8 Bytes + 4 Bytes + 10 Bytes = 30 BytesRetained Size 计算的大小要包含所引用对象在堆中占用的内存大小。不过所引用的对象 GC Roots 也有引用时就不计算大小,不知道 GC Roots 的同学去找找其他的资料。参考如下图( obj1 计算大小时,就不需要考虑 obj3obj5 在内存中的大小):

retained_objects.gif

通过对 Shallow SizeRetained Size 的对比分析,可以得出结论 Shallow Size <= Retained Size, 但是我们看到 Profiler 展示的 Shallow Size 是远远大于 Retained Size,哈哈,我也不知道原因,我也找其他资料了,没有找到相关信息,知道的同学可以在下面留言。但是当我选中某个对象查看具体实例的时候就能够满足 Shallow Size <= Retained Size

我们可以选中某个对象查看它的对应的所有实例,选择对应的实例能够看到实例的一些信息:

dump_instance.png

我们可以看到实例对应的成员变量他们的一些信息,这里又多了一个 Depth 参数,它是表示当前对象到 GC Roots 的最小跳数。选中成员变量右击可以跳转到对应的实例中。

选择 References 还可以看到所有的其他对象对它的引用:

dump_ref.png

通过 Android StudioProfiler 我们能够很容易分析出虚拟机中的内存泄漏和造成 OOM 的代码。

Profiler 可不是只能简单地 dump 堆内存哦,它还可以捕获一段时间内对象的分配和销毁,这个功能也能帮我们分析很多问题,比如说 Android 动画过程中造成的内存抖动,我们能够快速定位到由于分配哪个对象导致的内存抖动(优秀的程序应该做到随时间的流逝内存的占用是一条平滑的曲线,而不是变化剧烈的折线)。

java_allocation.png

我们选中 Record Java/Kotlin allocations 后然后点击 Record 就可以开始记录当前的对象分配和销毁,当需要停止时记得点击大红按钮就好了(不过这个功能很消耗性能,无论是电脑还是调试的手机)。

allocation_instance.png 选择的这段时间是触发 GC 前后的时间,其中包含这段时间内的一些重要信息:Allocation (这段时间内新建对象个数),Deallocation (这段时间内回收对象个数),Total Count (当前剩余对象个数),Shallow SizeShallow Size Change

我们可以选择某一个对象,然后会列出这段时间内这个类所有的创建和回收的实例:

allocation_info.png 有的对象标识了“三条杠”,这些对象能够查看到它的分配的方法栈。

如果选择 Visualization 还能够看到你选的对象创建实例的所有方法栈信息:

allocation_map.png

到这里我们分析 Android Dalvik 虚拟机堆内存的方式就介绍完了,不过这只是虚拟机中的堆内存,很多时候我们出现问题的是 native 的堆内存😂,后续考虑再单独出文章来介绍。

总结

除了线程方法栈的 dump,其他的方式都不适合线上分析。
不要以为学会了方法栈的 dump 和虚拟机堆内存的 dump 就能够彻底解决这些问题,他们只是帮你发现这些问题,要彻底解决这些问题还需要很多其他方面的知识。