当前位置： 首页 > news >正文

Android ANR log trace日志文件分析

news 来源：原创 2024/5/6 16:02:57

 

 
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接： https://blog.csdn.net/qq_25804863/article/details/49111005

  • 什么是ANR?

    ANR:Application Not Responding，即应用无响应

  • ANR日志Trace文件获取

    系统生成的Trace文件保存在data/anr,可以用过命令adb pull data/anr/取出

    traces.txt只保留最后一次ANR的信息,Android系统有个DropBox功能功能,它能记录系统出现的crash错误.因此保留有发生过的ANR的信息.(log路径:/data/system/dropbox)

    获取系统crash log: adb shell dumpsys dropbox --print >>log.txt

  1.  
    Trace文件怎么生成的?
  2.  
    当 APP(包括系统APP和用户APP)进程出现ANR、应用响应慢或WatchDog的监视没有得到回馈时,
  3.  
    系统会 dump此时的top进程,进程中Thread的运行状态就都dump到这个Trace文件中了.

  • 导致ANR的常见几种情况:

    1：Input dispatching timed out(5 seconds) 按键或触摸事件处理超时(一般是UI主线程做了耗时的操作,这类ANR最常见)

    2：BroadcastTimeout(10 seconds) 广播的分发和处理超时(一般是onReceiver执行时间过长)

    3：ServiceTimeout(20 seconds) Service的启动和执行超时

    另外还有ProviderTimeout和WatchDog等导致的ANR.还有当系统内存或CPU资源不足时容易出现ANR,一般这种情况会有lowmemorykill的log打印.

    应用ANR产生的时候,ActivityManagerService的appNotResponding方法就会被调用,然后在/data/anr/traces.txt文件中写入ANR相关信息.

  1.  
    final void appNotResponding(ProcessRecord app, ActivityRecord activity,
  2.  
    ActivityRecord parent, boolean aboveSystem, final String annotation) {
  3.  
    // ... ...
  4.  
    if (MONITOR_CPU_USAGE) {
  5.  
    updateCpuStatsNow(); // 更新CPU使用率
  6.  
    }
  7.  
    // ... ...
  8.  
    final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
  9.  
    // dumpStackTraces是输出traces文件的函数
  10.  
    File tracesFile = dumpStackTraces( true, firstPids, processCpuTracker, lastPids,
  11.  
    NATIVE_STACKS_OF_INTEREST);
  12.  
     
  13.  
    String cpuInfo = null;
  14.  
    if (MONITOR_CPU_USAGE) {
  15.  
    updateCpuStatsNow(); // 再次更新CPU信息
  16.  
    synchronized (mProcessCpuTracker) {
  17.  
    // 输出ANR发生前一段时间内的CPU使用率
  18.  
    cpuInfo = mProcessCpuTracker.printCurrentState(anrTime);
  19.  
    }
  20.  
    info.append(processCpuTracker.printCurrentLoad());
  21.  
    info.append(cpuInfo);
  22.  
    }
  23.  
    // 输出ANR发生后一段时间内的CPU使用率
  24.  
    info.append(processCpuTracker.printCurrentState(anrTime));
  25.  
     
  26.  
    Slog.e(TAG, info.toString());
  27.  
    if (tracesFile == null) {
  28.  
    // There is no trace file, so dump (only) the alleged culprit's threads to the log
  29.  
    Process.sendSignal(app.pid, Process.SIGNAL_QUIT);
  30.  
    }
  31.  
    // 将ANR信息同时输出到DropBox中
  32.  
    addErrorToDropBox( "anr", app, app.processName, activity, parent, annotation,
  33.  
    cpuInfo, tracesFile, null);
  34.  
    // ... ...
  35.  
    synchronized (this) {
  36.  
    // 显示ANR提示对话框
  37.  
    // Bring up the infamous App Not Responding dialog
  38.  
    Message msg = Message.obtain();
  39.  
    HashMap<String, Object> map = new HashMap<String, Object>();
  40.  
    msg.what = SHOW_NOT_RESPONDING_MSG;
  41.  
    msg.obj = map;
  42.  
    msg.arg1 = aboveSystem ? 1 : 0;
  43.  
    map.put( "app", app);
  44.  
    if (activity != null) {
  45.  
    map.put( "activity", activity);
  46.  
    }
  47.  
    mUiHandler.sendMessage(msg);
  48.  
    }
  49.  
    }

避免ANR?

  1. UI线程尽量只做跟UI相关的工作

  2. 耗时的工作（比如数据库操作，I/O，连接网络或者别的有可能阻碍UI线程的操作）把它放入单独的线程处理

  3. 尽量用Handler来处理UIthread和别的thread之间的交互

分析ANR的Log:

出现ANR的log如下:

  1.  
    06-22 10:37:46.204 3547 3604 E ActivityManager: ANR in org.code:MessengerService // ANR出现的进程包名
  2.  
     
  3.  
    E ActivityManager: PID: 17027 // ANR进程ID
  4.  
     
  5.  
    E ActivityManager: Reason: executing service org.code/.ipc.MessengerService //导致ANR的原因
  6.  
     
  7.  
    E ActivityManager: Load: 8.31 / 8.12 / 8.47
  8.  
     
  9.  
    E ActivityManager: CPU usage from 0ms to 6462ms later: //CPU在ANR发生后的使用情况
  10.  
     
  11.  
    E ActivityManager: 61% 3547/system_server: 21% user + 39% kernel / faults: 13302 minor 2 major
  12.  
     
  13.  
    E ActivityManager: 0.2% 475/debuggerd: 0% user + 0.1% kernel / faults: 6086 minor 1 major
  14.  
     
  15.  
    E ActivityManager: 10% 5742/com.android.phone: 5.1% user + 5.1% kernel / faults: 7597 minor
  16.  
     
  17.  
    E ActivityManager: 6.9% 5342/com.android.systemui: 2.1% user + 4.8% kernel / faults: 4158 minor
  18.  
     
  19.  
    E ActivityManager: 0.1% 477/debuggerd64: 0% user + 0.1% kernel / faults: 4013 minor
  20.  
     
  21.  
    E ActivityManager: 5.7% 16313/org.code: 3.2% user + 2.4% kernel / faults: 2412 minor
  22.  
     
  23.  
    E ActivityManager: 3.7% 17027/org.code:MessengerService: 1.7% user + 2% kernel / faults: 2571 minor 6 major
  24.  
     
  25.  
    E ActivityManager: 2.6% 306/cfinteractive: 0% user + 2.6% kernel
  26.  
    ... ...
  27.  
    E ActivityManager: + 0% 17168/kworker/0:1: 0% user + 0% kernel
  28.  
     
  29.  
    E ActivityManager: 0% TOTAL: 0% user + 0% kernel + 0% softirq // CUP占用情况
  30.  
     
  31.  
    E ActivityManager: CPU usage from 5628ms to 6183ms later:
  32.  
     
  33.  
    E ActivityManager: 42% 3547/system_server: 17% user + 24% kernel / faults: 11 minor
  34.  
     
  35.  
    E ActivityManager: 12% 3604/ActivityManager: 1.7% user + 10% kernel
  36.  
     
  37.  
    E ActivityManager: 12% 3609/android.display: 8.7% user + 3.5% kernel
  38.  
     
  39.  
    E ActivityManager: 3.5% 5304/Binder_6: 1.7% user + 1.7% kernel
  40.  
     
  41.  
    E ActivityManager: 3.5% 5721/Binder_A: 1.7% user + 1.7% kernel
  42.  
     
  43.  
    E ActivityManager: 3.5% 5746/Binder_C: 3.5% user + 0% kernel
  44.  
     
  45.  
    E ActivityManager: 1.7% 3599/Binder_1: 0% user + 1.7% kernel
  46.  
     
  47.  
    E ActivityManager: 1.7% 3600/Binder_2: 0% user + 1.7% kernel
  48.  
     
  49.  
    I ActivityManager: Killing 17027:org.code:MessengerService/u0a85 (adj 1): bg anr
  50.  
     
  51.  
    I art : Wrote stack traces to '/data/anr/traces.txt' //art这个TAG打印对traces操作的信息
  52.  
     
  53.  
    D GraphicsStats: Buffer count: 9
  54.  
     
  55.  
    W ActivityManager: Scheduling restart of crashed service org.code/.ipc.MessengerService in 1000ms
  56.  
     

log打印了ANR的基本信息,我们可以分析CPU使用率推测ANR发生的时候设备在做什么工作;如果CPU使用率很高,接近100%,可能是在进行大规模的计算更可能是陷入死循环;如果CUP使用率很低,说明主线程被阻塞了,并且当IOwait很高,可能是主线程在等待I/O操作的完成.

对于ANR只是分析Log很难知道问题所在,我们还需要通过Trace文件分析stack调用情况.

  1.  
     
  2.  
    ----- pid 17027 at 2017-06-22 10:37:39 ----- // ANR出现的进程pid和时间(和上述log中pid一致)
  3.  
    Cmd line: org.code:MessengerService // ANR出现的进程名
  4.  
    Build fingerprint: 'Homecare/qucii8976v3_64:6.0.1/pansen06141150:eng/test-keys' // 下面记录系统版本,内存等状态信息
  5.  
    ABI: 'arm64'
  6.  
    Build type: optimized
  7.  
    Zygote loaded classes= 6576 post zygote classes=13
  8.  
    Intern table: 13780 strong; 17 weak
  9.  
    JNI: CheckJNI is on; globals= 283 (plus 158 weak)
  10.  
    Libraries: /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libwebviewchromium_loader.so libjavacore.so ( 7)
  11.  
    Heap: 29% free, 8MB/12MB; 75731 objects
  12.  
    Dumping cumulative Gc timings
  13.  
    Total number of allocations 75731
  14.  
    Total bytes allocated 8MB
  15.  
    Total bytes freed 0B
  16.  
    Free memory 3MB
  17.  
    Free memory until GC 3MB
  18.  
    Free memory until OOME 183MB
  19.  
    Total memory 12MB
  20.  
    Max memory 192MB
  21.  
    Zygote space size 3MB
  22.  
    Total mutator paused time: 0
  23.  
    Total time waiting for GC to complete: 0
  24.  
    Total GC count: 0
  25.  
    Total GC time: 0
  26.  
    Total blocking GC count: 0
  27.  
    Total blocking GC time: 0
  28.  
     
  29.  
    suspend all histogram: Sum: 76us 99% C.I. 0.100us-28us Avg: 7.600us Max: 28us
  30.  
    DALVIK THREADS ( 15):
  31.  
    // Signal Catcher是记录traces信息的线程
  32.  
    // Signal Catche(线程名)、(daemon)表示守护进程、prio(线程优先级,默认是5)、tid(线程唯一标识ID)、Runnable(线程当前状态)
  33.  
    "Signal Catcher" daemon prio=5 tid=3 Runnable
  34.  
    //线程组名称、suspendCount、debugSuspendCount、线程的Java对象地址、线程的Native对象地址
  35.  
    | group= "system" sCount=0 dsCount=0 obj=0x12d8f0a0 self=0x5598ae55d0
  36.  
    //sysTid是线程号(主线程的线程号和进程号相同)
  37.  
    | sysTid= 17033 nice=0 cgrp=default sched=0/0 handle=0x7fb2350450
  38.  
    | state=R schedstat=( 4348125 172343 3 ) utm=0 stm=0 core=1 HZ=100
  39.  
    | stack= 0x7fb2254000-0x7fb2256000 stackSize=1013KB
  40.  
    | held mutexes= "mutator lock"(shared held)
  41.  
    native: #00 pc 0000000000489e28 /system/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+236)
  42.  
    native: #01 pc 0000000000458fe8 /system/lib64/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+220)
  43.  
    native: #02 pc 0000000000465bc8 /system/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+688)
  44.  
    native: #03 pc 0000000000466ae0 /system/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+276)
  45.  
    native: #04 pc 000000000046719c /system/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+188)
  46.  
    native: #05 pc 0000000000467a84 /system/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+492)
  47.  
    native: #06 pc 0000000000431194 /system/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+96)
  48.  
    native: #07 pc 000000000043e604 /system/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1256)
  49.  
    native: #08 pc 000000000043f214 /system/lib64/libart.so (art::SignalCatcher::Run(void*)+452)
  50.  
    native: #09 pc 0000000000068714 /system/lib64/libc.so (__pthread_start(void*)+52)
  51.  
    native: #10 pc 000000000001c604 /system/lib64/libc.so (__start_thread+16)
  52.  
    (no managed stack frames)
  53.  
     
  54.  
    //main(线程名)、prio(线程优先级,默认是5)、tid(线程唯一标识ID)、Sleeping(线程当前状态)
  55.  
    "main" prio=5 tid=1 Sleeping
  56.  
    | group= "main" sCount=1 dsCount=0 obj=0x73132d10 self=0x5598a5f5e0
  57.  
    //sysTid是线程号(主线程的线程号和进程号相同)
  58.  
    | sysTid= 17027 nice=0 cgrp=default sched=0/0 handle=0x7fb6db6fe8
  59.  
    | state=S schedstat=( 420582038 5862546 143 ) utm=24 stm=18 core=6 HZ=100
  60.  
    | stack= 0x7fefba3000-0x7fefba5000 stackSize=8MB
  61.  
    | held mutexes=
  62.  
    // java 堆栈调用信息(这里可查看导致ANR的代码调用流程)(分析ANR最重要的信息)
  63.  
    at java.lang.Thread.sleep!(Native method)
  64.  
    - sleeping on < 0x0c60f3c7> (a java.lang.Object)
  65.  
    at java.lang.Thread.sleep(Thread.java: 1031)
  66.  
    - locked < 0x0c60f3c7> (a java.lang.Object) // 锁住对象0x0c60f3c7
  67.  
    at java.lang.Thread.sleep(Thread.java: 985)
  68.  
    at android.os.SystemClock.sleep(SystemClock.java: 120)
  69.  
    at org.code.ipc.MessengerService.onCreate(MessengerService.java: 63) //导致ANR的代码
  70.  
    at android.app.ActivityThread.handleCreateService(ActivityThread.java: 2877)
  71.  
    at android.app.ActivityThread.access$ 1900(ActivityThread.java:150)
  72.  
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java: 1427)
  73.  
    at android.os.Handler.dispatchMessage(Handler.java: 102)
  74.  
    at android.os.Looper.loop(Looper.java: 148)
  75.  
    at android.app.ActivityThread.main(ActivityThread.java: 5417)
  76.  
    at java.lang.reflect.Method.invoke!(Native method)
  77.  
    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java: 726)
  78.  
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java: 616)

在log中显示的pid在traces文件中与之对应,trace log中会打印当前所有线程的堆栈信息,一般我们主要关注main线程的堆栈(也有分析其他线程的情况,通过分析ANR发生时系统状态推测出设备正在进行操作)

而这里然后通过查看堆栈调用信息分析ANR的代码.上述ANR实际上在org.code.ipc.MessengerService.onCreate中63行调用SystemClock.sleep(10000)代码导致的;这是比较简单ANR示例.

以上仅为解决ANR问题提供一个思路,具体问题还需要根据实际情况具体分析

线程状态的分类: java中定义的线程状态:

  1.  
    // libcore/libart/src/main/java/java/lang/Thread.java
  2.  
    /**
  3.  
    * A representation of a thread's state. A given thread may only be in one
  4.  
    * state at a time.
  5.  
    */
  6.  
    public enum State {
  7.  
    /**
  8.  
    * The thread has been created, but has never been started.
  9.  
    */
  10.  
    NEW,
  11.  
    /**
  12.  
    * The thread may be run.
  13.  
    */
  14.  
    RUNNABLE,
  15.  
    /**
  16.  
    * The thread is blocked and waiting for a lock.
  17.  
    */
  18.  
    BLOCKED,
  19.  
    /**
  20.  
    * The thread is waiting.
  21.  
    */
  22.  
    WAITING,
  23.  
    /**
  24.  
    * The thread is waiting for a specified amount of time.
  25.  
    */
  26.  
    TIMED_WAITING,
  27.  
    /**
  28.  
    * The thread has been terminated.
  29.  
    */
  30.  
    TERMINATED
  31.  
    }

C代码中定义的线程状态:

  1.  
    / / /art/runtime/thread_state.h
  2.  
    enum ThreadState {
  3.  
    // Thread.State JDWP state
  4.  
    kTerminated = 66, // TERMINATED TS_ZOMBIE Thread.run has returned, but Thread* still around
  5.  
    kRunnable, // RUNNABLE TS_RUNNING runnable
  6.  
    kTimedWaiting, // TIMED_WAITING TS_WAIT in Object.wait() with a timeout
  7.  
    kSleeping, // TIMED_WAITING TS_SLEEPING in Thread.sleep()
  8.  
    kBlocked, // BLOCKED TS_MONITOR blocked on a monitor
  9.  
    kWaiting, // WAITING TS_WAIT in Object.wait()
  10.  
    kWaitingForGcToComplete, // WAITING TS_WAIT blocked waiting for GC
  11.  
    kWaitingForCheckPointsToRun, // WAITING TS_WAIT GC waiting for checkpoints to run
  12.  
    kWaitingPerformingGc, // WAITING TS_WAIT performing GC
  13.  
    kWaitingForDebuggerSend, // WAITING TS_WAIT blocked waiting for events to be sent
  14.  
    kWaitingForDebuggerToAttach, // WAITING TS_WAIT blocked waiting for debugger to attach
  15.  
    kWaitingInMainDebuggerLoop, // WAITING TS_WAIT blocking/reading/processing debugger events
  16.  
    kWaitingForDebuggerSuspension, // WAITING TS_WAIT waiting for debugger suspend all
  17.  
    kWaitingForJniOnLoad, // WAITING TS_WAIT waiting for execution of dlopen and JNI on load code
  18.  
    kWaitingForSignalCatcherOutput, // WAITING TS_WAIT waiting for signal catcher IO to complete
  19.  
    kWaitingInMainSignalCatcherLoop, // WAITING TS_WAIT blocking/reading/processing signals
  20.  
    kWaitingForDeoptimization, // WAITING TS_WAIT waiting for deoptimization suspend all
  21.  
    kWaitingForMethodTracingStart, // WAITING TS_WAIT waiting for method tracing to start
  22.  
    kWaitingForVisitObjects, // WAITING TS_WAIT waiting for visiting objects
  23.  
    kWaitingForGetObjectsAllocated, // WAITING TS_WAIT waiting for getting the number of allocated objects
  24.  
    kStarting, // NEW TS_WAIT native thread started, not yet ready to run managed code
  25.  
    kNative, // RUNNABLE TS_RUNNING running in a JNI native method
  26.  
    kSuspended, // RUNNABLE TS_RUNNING suspended by GC or debugger
  27.  
    };

两者可以看出在C代码中定义更为详细,Traces中显示的线程状态都是C代码定义的.我们可以通过查看线程状态对应的信息分析ANR问题.

如: TimedWaiting对应的线程状态是TIMED_WAITING

kTimedWaiting, // TIMED_WAITING TS_WAIT in Object.wait() with a timeout 执行了无超时参数的wait函数

kSleeping, // TIMED_WAITING TS_SLEEPING in Thread.sleep() 执行了带有超时参数的sleep函数

  1.  
    ZOMBIE 线程死亡，终止运行
  2.  
    RUNNING/RUNNABLE 线程可运行或正在运行
  3.  
    TIMED_WAIT 执行了带有超时参数的 wait、sleep或join函数
  4.  
    MONITOR 线程阻塞，等待获取对象锁
  5.  
    WAIT 执行了无超时参数的 wait函数
  6.  
    INITIALIZING 新建，正在初始化，为其分配资源
  7.  
    STARTING 新建，正在启动
  8.  
    NATIVE 正在执行JNI本地函数
  9.  
    VMWAIT 正在等待VM资源
  10.  
    SUSPENDED 线程暂停，通常是由于GC或debug被暂停

转载于:https://www.cnblogs.com/xgjblog/p/11466325.html

相关文章：

  • ffmpeg开发文档
  • js 特殊字符替换成换行
  • xampp for mac配置局域网访问
  • Xray写POC插件
  • db timedb / ClickHouse
  • Redis 学习笔记（篇十）：Sentinel
  • OS + Centos7.6 / Windows 10 shuangxitong
  • C#中字符串转换为计算公式
  • SSM框架-SpringMVC
  • SSM框架-mybatis
  • 微软3389远程漏洞CVE-2019-0708批量检测工具
  • 浅谈 赛马问题
  • JDK配置
  • 数据库模糊查询
  • C#视频拍照、视频录制项目示例
  • JavaScript-如何实现克隆(clone)函数
  • [原]深入对比数据科学工具箱：Python和R 非结构化数据的结构化
  • 【Leetcode】104. 二叉树的最大深度
  • canvas 高仿 Apple Watch 表盘
  • Dubbo 整合 Pinpoint 做分布式服务请求跟踪
  • iOS 颜色设置看我就够了
  • IP路由与转发
  • Javascript Math对象和Date对象常用方法详解
  • JWT究竟是什么呢?
  • Meteor的表单提交:Form
  • npx命令介绍
  • 从地狱到天堂，Node 回调向 async/await 转变
  • 从零开始学习部署
  • 微信小程序实战练习（仿五洲到家微信版）
  • 温故知新之javascript面向对象
  • 2017年360最后一道编程题
  • （10）STL算法之搜索（二） 二分查找
  • （5）STL算法之复制
  • （9）STL算法之逆转旋转
  • (zt)基于Facebook和Flash平台的应用架构解析
  • （安全基本功）磁盘MBR，分区表，活动分区，引导扇区。。。详解与区别
  • （安卓）跳转应用市场APP详情页的方式
  • （免费领源码）Java#ssm#MySQL 创意商城03663-计算机毕业设计项目选题推荐
  • （三）elasticsearch 源码之启动流程分析
  • （三）终结任务
  • （十二）devops持续集成开发——jenkins的全局工具配置之sonar qube环境安装及配置
  • （十五）Flask覆写wsgi_app函数实现自定义中间件
  • (使用vite搭建vue3项目（vite + vue3 + vue router + pinia + element plus）)
  • （算法）前K大的和
  • (图)IntelliTrace Tools 跟踪云端程序
  • （学习日记）2024.03.25：UCOSIII第二十二节：系统启动流程详解
  • (原創) 如何優化ThinkPad X61開機速度? (NB) (ThinkPad) (X61) (OS) (Windows)
  • （状压dp）uva 10817 Headmaster's Headache
  • （最全解法）输入一个整数，输出该数二进制表示中1的个数。
  • .net 4.0 A potentially dangerous Request.Form value was detected from the client 的解决方案
  • .NET Compact Framework 3.5 支持 WCF 的子集
  • .NET8.0 AOT 经验分享 FreeSql/FreeRedis/FreeScheduler 均已通过测试
  • .net连接MySQL的方法
  • .NET是什么
  • //解决validator验证插件多个name相同只验证第一的问题