Android ANR的trace文件基本信息解读

Posted 莫川

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Android ANR的trace文件基本信息解读相关的知识，希望对你有一定的参考价值。

ANR堆栈文件的抓取

  • android6以下可以直接读取/data/anr目录下的trace.txt文件，然后过滤出自己进程的anr文件即可
  • android6及以上，没有读取/data/anr的权限，需要native层通过拦截SIGQUIT信号，结合消息机制msg的when超时时间，底层dump堆栈信息。详细原理详见微信技术团队的分享：微信Android客户端的ANR监控方案

Android ANR的trace文件基本信息解读

  • 示例
"main" prio=5 tid=1 Native
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x727c02f8 self=0xb400007a2f210800
  | sysTid=339 nice=-10 cgrp=default sched=0/0 handle=0x7ab698d500
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fc8197000-0x7fc8199000 stackSize=8192KB
  | held mutexes=
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:339)
  at android.os.Looper.loop(Looper.java:200)
  at android.app.ActivityThread.main(ActivityThread.java:8312)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:632)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1049)

线程基本信息

  • 线程优先级：prio=5 (主线程均是5)
  • 线程ID： tid=1 主线程的id一般都是1
  • 线程状态：Native ：表示正在调用JNI
    • 还有其他多种状态，表示发生ANR时主线程的状态
  • 线程组名称：group=“main”
  • 线程被挂起的次数：sCount=0
    • 在等待GC时，有时候挂起的线程数量比较多
  • 线程被调试器挂起的次数：dsCount=0
  • 线程的java的对象地址：obj= 0x7682ab30
  • 线程本身的Native对象地址：self=0x7bd3815c00线程调度信息：

线程优先级信息

  • Linux系统中内核线程ID: sysTid=6317与主线程的进程号相同
  • 线程调度优先级：nice=-10
  • 线程调度组：cgrp=default
  • 线程调度策略和优先级：sched=0/0
  • 线程处理函数地址：handle= 0x7c59fc8548

线程状态信息

  • 线程调度状态：state=S
  • 线程在CPU中的执行时间、线程等待时间、线程执行的时间片长度：schedstat=(1009468742 32888019 224)
  • 线程在用户态中的调度时间值：utm=91
  • 线程在内核态中的调度时间值：stm=9
  • 最后执行这个线程的CPU核序号：core=4

线程堆栈信息

  • 堆栈地址和大小：stack=0x7ff27e1000-0x7ff27e3000 stackSize=8MB

ANR中的主线程状态及ANR示例分析

Blocked

  • case 1
"main" prio=5 tid=1 Blocked
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x72996758 self=0xb400007ac7e10800
  | sysTid=28366 nice=-10 cgrp=default sched=0/0 handle=0x7b4f71b500
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fe0a67000-0x7fe0a69000 stackSize=8192KB
  | held mutexes=
  at com.autonavi.base.ae.gmap.GLMapEngine.addGestureMessage(SourceFile:-1)
  - waiting to lock <0x0f62c521> (a com.autonavi.base.ae.gmap.GLMapEngine) held by thread 96
  at com.amap.api.mapcore.util.c.addGestureMapMessage(SourceFile:2892)
  at com.amap.api.mapcore.util.p$c.b(SourceFile:801)
  at com.amap.api.mapcore.util.am.a(SourceFile:104)
  at com.amap.api.mapcore.util.ak.d(SourceFile:61)
  at com.amap.api.mapcore.util.p.a(SourceFile:195)
  at com.amap.api.mapcore.util.c.onTouchEvent(SourceFile:1795)
  at com.amap.api.mapcore.util.e.onTouchEvent(SourceFile:47)
  • 分析：
    • GLMapEngine锁被线程96持有，主线程一直等待到ANR，需要解决锁等待的问题
  • case 2
"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 cgrp=apps/bg_non_interactive handle=0xb6f4fb4c
  | sysTid=4232 nice=0 sched=0/0 cgrp=apps/bg_non_interactive handle=0xb6f4fb4c
  | state=S schedstat=( 93912199183 67364592009 177636 ) utm=7567 stm=1824 core=1 HZ=100
  | heldMutexes=
 at android.hardware.display.DisplayManagerGlobal.getDisplayInfo(DisplayManagerGlobal.java:172)
 at android.hardware.display.DisplayManagerGlobal.getDisplayInfo(DisplayManagerGlobal.java:166)
 at android.hardware.display.DisplayManagerGlobal.getDisplayInfo(DisplayManagerGlobal.java:159)
  • 分析
    • cgrp=apps/bg_non_interactive 表示app在后台；
    • sCount=1有一个线程被挂起；
    • nice=0 压后台时，线程优先级降低，nice值越小（负数），优先级越高
    • schedstat( 93912199183 67364592009 177636 )，表示线程执行时间很长

Native

  • case 1
"main" prio=5 tid=1 Native
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x727c02f8 self=0xb400007a2f210800
  | sysTid=339 nice=-10 cgrp=default sched=0/0 handle=0x7ab698d500
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fc8197000-0x7fc8199000 stackSize=8192KB
  | held mutexes=
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:339)
  at android.os.Looper.loop(Looper.java:200)
  at android.app.ActivityThread.main(ActivityThread.java:8312)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:632)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1049)
  • 分析
    • 表明ANR时，主线程的状态是在调用JNI，此处主线程的MessageQueue停留在nativePollOnce，表示主线程没有需要处理的消息；此状态大概率是没有dump出状态，或者ANR已经发生，没有dump出ANR的堆栈
  • case 2:
"main" prio=5 tid=1 Native
  | group="" sCount=0 dsCount=0 flags=0 obj=0x7877b2c0 self=0x7e5f214c00
  | sysTid=25160 nice=0 cgrp=default sched=0/0 handle=0x7ee5d67548
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fe88ba000-0x7fe88bc000 stackSize=8MB
  | held mutexes=
  at java.io.FileDescriptor.sync(Native method)
  at android.os.FileUtils.sync(FileUtils.java:197)
  at android.app.SharedPreferencesImpl.writeToFile(SharedPreferencesImpl.java:777)
  at android.app.SharedPreferencesImpl.access$900(SharedPreferencesImpl.java:54)
  at android.app.SharedPreferencesImpl$2.run(SharedPreferencesImpl.java:642)
  at android.app.SharedPreferencesImpl.enqueueDiskWrite(SharedPreferencesImpl.java:661)
  at android.app.SharedPreferencesImpl.access$100(SharedPreferencesImpl.java:54)
  at android.app.SharedPreferencesImpl$EditorImpl.commit(SharedPreferencesImpl.java:580)
  ...
  at android.os.Handler.handleCallback(Handler.java:873)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:242)
  at android.app.ActivityThread.main(ActivityThread.java:7227)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:499)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:962)
  • 分析
    • SP属于IO操作，建议通过apply方式进行，将同步改成异步；或者使用子线程进行保存

Waiting

"main" prio=5 tid=1 Waiting
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x731a0ec8 self=0xb40000753e8b6c00
  | sysTid=28146 nice=-10 cgrp=default sched=0/0 handle=0x753fe804f8
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fd0403000-0x7fd0405000 stackSize=8192KB
  | held mutexes=
  at java.lang.Object.wait(Native method)
  - waiting on <0x025d68dd> (a android.opengl.GLSurfaceView$GLThreadManager)
  at java.lang.Object.wait(Object.java:442)
  at java.lang.Object.wait(Object.java:568)
  at android.opengl.GLSurfaceView$GLThread.onPause(GLSurfaceView.java:1731)
  at android.opengl.GLSurfaceView.onPause(GLSurfaceView.java:579)
  at com.amap.api.mapcore.util.e.onPause(SourceFile:117)
  at com.amap.api.mapcore.util.e.onDetachedGLThread(SourceFile:73)
  at com.amap.api.mapcore.util.c.destroy(SourceFile:5750)
  at com.amap.api.mapcore.util.t.onDestroy(SourceFile:207)
  at com.amap.api.maps.MapView.onDestroy(SourceFile:165)
  • 分析
    • 主线程等待超时导致ANR

Sleeping

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x71ddabd8 self=0xb4000077247b3c00
  | sysTid=17264 nice=0 cgrp=default sched=0/0 handle=0x7725f054f8
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fd62dd000-0x7fd62df000 stackSize=8192KB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
  - sleeping on <0x0b3201c6> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:442)
  at java.lang.Thread.sleep(Thread.java:358)
  at com.amap.api.mapcore.util.c.destroy(SourceFile:5731)
  at com.amap.api.mapcore.util.t.onDestroy(SourceFile:207)
  at com.amap.api.maps.MapView.onDestroy(SourceFile:165)
  • 分析
    • 在主线程使用了Thread.sleep，导致主线程超时ANR

WaitingForGcToComplete

  • case 1
"main" prio=5 tid=1 WaitingForGcToComplete
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x72f93540 self=0x7edd210800
  | sysTid=27919 nice=0 cgrp=default sched=0/0 handle=0x7f641e10d0
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fe2497000-0x7fe2499000 stackSize=8192KB
  | held mutexes=
  at java.util.Arrays.copyOf(Arrays.java:3257)
  at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
  at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
  at java.lang.StringBuilder.append(StringBuilder.java:137)
  at android.os.Handler.toString(Handler.java:862)
  at java.lang.String.valueOf(String.java:2924)
  at java.lang.StringBuilder.append(StringBuilder.java:132)
  at android.os.Looper.loop(Looper.java:185)
  at android.app.ActivityThread.main(ActivityThread.java:8668)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1109)
  • 分析
    • 由于app内存问题，比如缓慢的内存泄漏等，导致APP频繁的GC，数组的copyOf等操作，触发了GC，这类问题的解决不一定是copyOf本身导致的，而有可能是app其他地方内存泄漏导致的；需要等待GC结束之后才能分配内存；
  • case 2
"main" prio=5 tid=1 WaitingForGcToComplete
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x74a91540 self=0x7604810800
  | sysTid=13782 nice=-10 cgrp=default sched=1073741825/2 handle=0x768b7a50d0
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fce4eb000-0x7fce4ed000 stackSize=8192KB
  | held mutexes=
  at java.lang.StringFactory.newStringFromChars(StringFactory.java:260)
  at java.lang.StringBuilder.toString(StringBuilder.java:413)
  at androidAndroid ANR的trace文件基本信息解读


 Android ANR log trace日志文件分析


 android ANR traces.txt文件导出分析


 Android ANR之traces日志线程参数解析大全


 android出现anr(application not response)的分析


 ANR traces中内存占用情况解读