一次trouble-shooting

最近在查看应用的线上日志统计时,发现一个 MessageQueue.nativePollOnce() 的记录,具体信息如下:

  at android.os.MessageQueue.nativePollOnce(Native method)  at android.os.MessageQueue.next(MessageQueue.java:325)  at android.os.Looper.loop(Looper.java:142)  at android.os.HandlerThread.run(HandlerThread.java:65)

因为是java层的异常收集,stack trace到这里就结束了,很明显问题实际上是在native层,所以只能通过traces.txt查看更多native层的信息了。

但是又拿不到用户的traces.txt,只好尝试拿自己的手机来看看,打开终端,通过以下命令获取traces.txt:

adb pull /data/anr/traces.txt C:\Users\wsj\Downloads\traces.txt

结果发现其中铺天盖地的都是nativePollOnce的日志,各种应用的不同线程都有报,摘录一段淘宝的日志:

// 显示进程id、ANR发生时间点、ANR发生进程包名----- pid 32617 at 2018-08-17 19:55:27 -----Cmd line: com.taobao.taobao// 一些设备,内存,GC等信息,通常可以忽略...// 发生ANR的堆栈信息,重要部分DALVIK THREADS (196):// 其他一些错误信息..."main" prio=5 tid=1 Native  | group="main" sCount=1 dsCount=0 flags=1 obj=0x73d92550 self=0xebc74000  | sysTid=32617 nice=-10 cgrp=default sched=0/0 handle=0xf01ae4bc  | state=S schedstat=( 6367184163 1210771881 20365 ) utm=458 stm=178 core=5 HZ=100  | stack=0xff4ae000-0xff4b0000 stackSize=8MB  | held mutexes=  kernel: (couldn't read /proc/self/task/32617/stack)  native: #00 pc 00019178  /system/lib/libc.so (syscall+28)  native: #01 pc 000b3e35  /system/lib/libart.so (_ZN3art17ConditionVariable16WaitHoldingLocksEPNS_6ThreadE+88)  native: #02 pc 0026302f  /system/lib/libart.so (_ZN3art3JNI16CallObjectMethodEP7_JNIEnvP8_jobjectP10_jmethodIDz+358)  native: #03 pc 00002b57  /system/lib/libnativehelper.so (jniGetReferent+90)  native: #04 pc 000c8b09  /system/lib/libandroid_runtime.so (_ZN7android26NativeDisplayEventReceiver13dispatchVsyncExij+20)  native: #05 pc 00032555  /system/lib/libandroidfw.so (_ZN7android22DisplayEventDispatcher11handleEventEiiPv+104)  native: #06 pc 000105cd  /system/lib/libutils.so (_ZN7android6Looper9pollInnerEi+572)  native: #07 pc 000102f9  /system/lib/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+32)  native: #08 pc 000e47dd  /system/lib/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+24)  native: #09 pc 001a8df5  /system/framework/arm/boot-framework.oat (Java_android_os_MessageQueue_nativePollOnce__JI+92)  at android.os.MessageQueue.nativePollOnce(Native method)  at android.os.MessageQueue.next(MessageQueue.java:325)  at android.os.Looper.loop(Looper.java:142)  at android.app.ActivityThread.main(ActivityThread.java:6938)  at java.lang.reflect.Method.invoke(Native method)  at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)"com.taobao.taobao_mytaobao_preferences.sp" prio=5 tid=66 Native  | group="main" sCount=1 dsCount=0 flags=1 obj=0x148ddde8 self=0xb9c7da00  | sysTid=2852 nice=0 cgrp=default sched=0/0 handle=0xbce0f970  | state=S schedstat=( 999426 52084 4 ) utm=0 stm=0 core=5 HZ=100  | stack=0xbcd0d000-0xbcd0f000 stackSize=1038KB  | held mutexes=  kernel: (couldn't read /proc/self/task/2852/stack)  native: #00 pc 0004a4d0  /system/lib/libc.so (__epoll_pwait+20)  native: #01 pc 0001bcd5  /system/lib/libc.so (epoll_pwait+60)  native: #02 pc 0001bd05  /system/lib/libc.so (epoll_wait+12)  native: #03 pc 00010407  /system/lib/libutils.so (_ZN7android6Looper9pollInnerEi+118)  native: #04 pc 000102f9  /system/lib/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+32)  native: #05 pc 000e47dd  /system/lib/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+24)  native: #06 pc 001a8df5  /system/framework/arm/boot-framework.oat (Java_android_os_MessageQueue_nativePollOnce__JI+92)  at android.os.MessageQueue.nativePollOnce(Native method)  at android.os.MessageQueue.next(MessageQueue.java:325)  at android.os.Looper.loop(Looper.java:142)  at android.os.HandlerThread.run(HandlerThread.java:65)// 其他一些错误信息...----- end 32617 -----

以上是我手机中traces.txt记录的淘宝的ANR日志摘录,我只摘出了两条nativePollOnce 相关的,第一个是发生在 main 线程,第二个是发生在 com.taobao.taobao_mytaobao_preferences.sp 线程。来看看第二个,即便是native层的部分似乎也没有什么错误信息。直接看第一行native信息:

native: #00 pc 0004a4d0  /system/lib/libc.so (__epoll_pwait+20)

epoll_wait其实是native层用于实现等待的,在管道上等待消息写入,一有消息到来时立马从管道中读取出来并返回结果,这会在后面的 消息循环 中讲到。这么看来,这段日志也只是说明:

目标线程在等待下一条消息的到来。

既然这样,只好先找谷歌了,能搜到的内容不多,stackoverflow上面有一个解释:

Short answer:

The nativePollOnce method is used to “wait” till the next Message becomes available. If the time spent during this call is long, your main (UI) thread has no real work to do and waits for next events to process. There’s no need to worry about that.

Explanation:

Because the “main” thread is responsible for drawing UI and handling various events, it’s Runnable has a loop which processes all these events. The loop is managed by a Looper and its job is quite straightforward: it processes all Messages in the MessageQueue.

A Message is added to the queue for example in response to input events, as frame rendering callback or even your own Handler.post calls. Sometimes the main thread has no work to do (that is, no messages in the queue), which may happen e.g. just after finishing rendering single frame (the thread has just drawn one frame and is ready for the next one, just waits for a proper time). Two Java methods in the MessageQueue class are interesting to us: Message next() and boolean enqueueMessage(Message, long). Message next(), as its name suggest, takes and returns the next Message from the queue. If the queue is empty (and there’s nothing to return), the method calls native void nativePollOnce(long, int) which blocks until a new message is added. At this point you might ask how does nativePollOnce know when to wake up. That’s a very good question. When a Message is added to the queue, the framework calls the enqueueMessage method, which not only inserts the message into the queue, but also calls native static void nativeWake(long), if there’s need to wake up the queue. The core magic of nativePollOnce and nativeWake happens in the native (actually, C++) code. Native MessageQueue utilizes a Linux system call named epoll, which allows to monitor a file descriptor for IO events. nativePollOnce calls epoll_wait on a certain file descriptor, whereas nativeWake writes to the descriptor, which is one of the IO operations, epoll_wait waits for. The kernel then takes out the epoll-waiting thread from the waiting state and the thread proceeds with handling the new message. If you’re familiar with Java’s Object.wait() and Object.notify() methods, you can imagine that nativePollOnce is a rough equivalent for Object.wait() and nativeWake for Object.notify(), except they’re implemented completely differently: nativePollOnce uses epoll and Object.wait() uses futex Linux call. It’s worth noticing that neither nativePollOnce nor Object.wait() waste CPU cycles, as when a thread enters either method, it becomes disabled for thread scheduling purposes (quoting the javadoc for the Object class). However, some profilers may mistakenly recognize epoll-waiting (or even Object-waiting) threads as running and consuming CPU time, which is incorrect. If those methods actually wasted CPU cycles, all idle apps would use 100% of the CPU, heating and slowing down the device.

Conclusion:

You shouldn’t worry about nativePollOnce. It just indicates that processing of all Messages has been finished and the thread waits for the next one. Well, that simply means you don’t give too much work to your main thread ?

android - what is message queue native poll once in android?

似乎不需要太关注这个问题,但又不是很放心,索性再看下 MessageQueue.next() 的源码,了解一下这个 nativePollOnce() 究竟是干嘛的,查了一番,大概是这样:

Java层和Native层其实各有一个MessageQueue,Java层的MessageQueue实际上是从Native层去获取其中的消息。而next方法显然就是用于获取下一条消息的,其中主要通过nativePollOnce从native层的MessageQueue中获取,并且该方法会阻塞线程,如果获取不到消息(比如消息队列中是空的),就一直阻塞,直到获取到消息为止。

可还是没有确切的证据证明这个异常信息不会导致ANR。只知道在系统的 traces.txt 中,有无数条 nativePollOnce 的异常信息,淘宝、微信等等各大应用都有,可平时使用时很少遇到真的崩溃的情况。

后来发现,使用Android Studio开发时,debug模式下的 Thread Dump ,其dump的thread信息中,居然能看到一些 nativePollOnce 的异常堆栈,发现以下几个点:

  • main Thread , LeakCanary-Heap-Dump thread 等都有报出该问题,但我的应用运行很正常
  • 所有报了 nativePollOnce 的线程,都处于 runnable 状态

Android Handler机制 - MessageQueue如何处理消息_第1张图片
Android Handler机制 - MessageQueue如何处理消息_第2张图片

似乎很大程度上可以证明前面 stackoverflow 上说的没错。

本次调查的结论

nativePollOnce 确实没有导致ANR,也不会过度消耗cpu cycle,它只是说明当前handlerthread中没有需要处理的message,线程在等待下一条message的到来,之所以会收集到这种异常堆栈,可能是系统错误的认为这个等待时间过长,将其列入了ANR。

还有一个推测,以前调查过一个线上日志报的 listFiles() 采集到navite层crash的问题,非utf-8编码的文件名,会导致listFiles在native层崩溃,本地也确实复现了该问题,调查后确定,这个问题只会在 Manifest文件Application 下的 debuggable=true 时发生,当其值为 false 时,不会crash,只是 listFiles() 接口返回的那个有问题的文件名不一定能准确识别出来,我想Google做这种机制的目的在于,开发时通过crash提示开发者有非utf-8的文件名存在,你应该检查是否代码有bug,或者考虑出现这种异常文件名是否正常,如果你认为你的业务需求需要对应这种case,并且你能接受api返回的结果中无法准确识别完整的文件名,那么当你的应用上线后(debuggable=false),系统不会上报该异常。

虽然IDE在出release版本的apk时,会强制将 debuggable 设置为true,但有些应用的发包流程可能使用的脚本编译打包,有可能忘记将开发模式下的 true 改为 false ,我解包看了一些线上的应用,发现有不少应用就是设的 true

所以猜测这个 nativePollOnce 的异常同样只会在 debuggable=true 时统计到,但我没有这种环境做验证,来采集线上日志,所以,如果你的应用,采集到线上日志有 nativePollOnce 的异常,又想要解决的话,可以先确认一下你们的线上应用是否设置了 debuggable=true ,如果是的话,可以优化出包流程,将其改为 false ,然后再统计一波线上日志,看还会不会收到 nativePollOnce 的异常,如果有人验证过了,也请告知我一下结果,我也想知道这个推测到底对不对,不胜感激。

这个问题的调查中,明白MessageQueue的工作原理也是很重要的。接下来的内容转载自 Android应用程序消息处理机制 ,对于MessageQueue讲的非常简单明了。

Android消息处理机制概述

Android的消息处理机制主要分为四个部分:

  • 创建消息队列
  • 消息循环
  • 消息发送
  • 消息处理

主要涉及三个类:

  • MessageQueue
  • Looper
  • Handler

创建消息队列

整个创建过程涉及到两个类:MessageQueueLooper。它们在C++层有两个对应的类:NativeMessageQueueLooper。其关系如下图所示:

      +------------+     +------+      |MessageQueue+----^+Looper|      +-----+------+     +------+            |                                |                                |                    +-----------+------+     +------+|NativeMessageQueue+^----+Looper|+------------------+     +------+    A----^B表示B中保存A的引用

创建过程如下所示:

  1. Looper的prepare或者prepareMainLooper静态方法被调用,将一个Looper对象保存在ThreadLocal里面。
  2. Looper对象的初始化方法里,首先会新建一个MessageQueue对象。
  3. MessageQueue对象的初始化方法通过JNI初始化C++层的NativeMessageQueue对象。
  4. NativeMessageQueue对象在创建过程中,会初始化一个C++层的Looper对象。
  5. C++层的Looper对象在创建的过程中,会在内部创建一个管道(pipe),并将这个管道的读写fd都保存在mWakeReadPipeFd和mWakeWritePipeFd中。
    然后新建一个epoll实例,并将两个fd注册进去。
  6. 利用epoll的机制,可以做到当管道没有消息时,线程睡眠在读端的fd上,当其他线程往管道写数据时,本线程便会被唤醒以进行消息处理。

#消息循环

          +------+    +------------+  +------------------+  +--------------+                              |Looper|    |MessageQueue|  |NativeMessageQueue|  |Looper(Native)|                              +--+---+    +------+-----+  +---------+--------+  +-------+------+                                 |               |                  |                   |                                        |               |                  |                   |                           +-------------------------------------------------------------------------------+               |[msg loop]  |   next()      |                  |                   |           |               |            +------------>  |                  |                   |           |               |            |               |                  |                   |           |               |            |               |                  |                   |           |               |            |               | nativePollOnce() |                   |           |               |            |               |    pollOnce()    |                   |           |               |            |               +----------------> |                   |           |               |            |               |                  |                   |           |              |            |               |                  |                   |           |               |            |               |                  |                   |           |               |            |               |                  |                   |           |               |            |               |                  |     pollOnce()    |           |               |            |               |                  +-----------------> |           |               |            |               |                  |                   |           |               |            |               |                  |                   | epoll_wait()              |            |               |                  |                   +--------+  |               |            |               |                  |                   |        |  |               |            |               |                  |                   |        |  |               |            |               |                  |                   | <------+  |               |            |               |                  |                   | awoken()  |               |            +               +                  +                   +           |               |                                                                               |               |                                                                               |               +-------------------------------------------------------------------------------+               
  1. 首先通过调用Looper的loop方法开始消息监听。loop方法里会调用MessageQueue的next方法。next方法会堵塞线程直到有消息到来为止。
  2. next方法通过调用nativePollOnce方法来监听事件。next方法内部逻辑如下所示(简化):
    • 进入死循环,以参数timout=0调用nativePollOnce方法。
    • 如果消息队列中有消息,nativePollOnce方法会将消息保存在mMessage成员中。nativePollOnce方法返回后立刻检查mMessage成员是否为空。
    • 如果mMessage不为空,那么检查它指定的运行时间。如果比当前时间要前,那么马上返回这个mMessage,否则设置timeout为两者之差,进入下一次循环。
    • 如果mMessage为空,那么设置timeout为-1,即下次循环nativePollOnce永久堵塞。
  3. nativePollOnce方法内部利用epoll机制在之前建立的管道上等待数据写入。接收到数据后马上读取并返回结果。

消息发送

          +-------+     +------------+   +------------------+   +--------------+                                  |Handler|     |MessageQueue|   |NativeMessageQueue|   |Looper(Native)|                                  +--+----+     +-----+------+   +---------+--------+   +-------+------+                                     |                |                    |                    |                                            |                |                    |                    |                               sendMessage()|                |                    |                    |                               +----------> |                |                    |                    |                                            |                |                    |                    |                                            |enqueueMessage()|                    |                    |                                            +--------------> |                    |                    |                                            |                |                    |                    |                                            |                |                    |                    |                                            |                |                    |                    |                                            |                |  nativeWake()      |                    |                                            |                |    wake()          |                    |                                            |                +------------------> |                    |                                            |                |                    |                    |                                            |                |                    |    wake()          |                                            |                |                    +------------------> |                                            |                |                    |                    |                                            |                |                    |                    |                                            |                |                    |                    |write(mWakeWritePipeFd, "W", 1)             |                |                    |                    |                                            |                |                    |                    |                                            |                |                    |                    |                                            |                |                    |                    |                                            |                |                    |                    |                                            +                +                    +                    +                               

消息发送过程主要由 Handler 对象来驱动。

  1. Handler对象在创建时会保存当前线程的looper和MessageQueue,如果传入Callback的话也会保存起来。
  2. 用户调用handler对象的sendMessage方法,传入msg对象。handler通过调用MessageQueue的enqueueMessage方法将消息压入MessageQueue。
  3. enqueueMessage方法会将传入的消息对象根据触发时间(when)插入到message queue中。然后判断是否要唤醒等待中的队列。
    • 如果插在队列中间。说明该消息不需要马上处理,不需要由这个消息来唤醒队列。
    • 如果插在队列头部(或者when=0),则表明要马上处理这个消息。如果当前队列正在堵塞,则需要唤醒它进行处理。
  4. 如果需要唤醒队列,则通过nativeWake方法,往前面提到的管道中写入一个"W"字符,令nativePollOnce方法返回。

消息处理

         +------+       +-------+                                                                            |Looper|       |Handler|                                                                            +--+---+       +---+---+                                                                               |               |                                                                                   |               |                                                                       loop()      |               |                                                                       [after next()]              |                                                                       +---------> |               |                                                                                   |               |                                                                                   |dispatchMessage()                                                                                  +-------------> |                                                                                   |               |                                                                                   |               |                                                                                   |               | handleMessage()                                                                   |               +-------+                                                                           |               |       |                                                                           |               |       |                                                                           |               | <-----+                                                                           |               |   (callback or subclass)                                                          |               |                                                                                   +               +                                                                       

Looper对象的loop方法里面的queue.next方法如果返回了message,那么handler的dispatchMessage会被调用。

  • 如果新建Handler的时候传入了callback实例,那么callback的handleMessage方法会被调用。
  • 如果是通过post方法向handler传入runnable对象的,那么runnable对象的run方法会被调用。
  • 其他情况下,handler方法的handleMessage会被调用。

更多相关文章

  1. android 判断当前线程是不是主线程的几种方法
  2. Android httpClient Get&Post方法
  3. Android 给textview添加下划线的一种方法(可复用)
  4. Android中两种实现倒计时的方法
  5. Android获取系统内核版本的方法
  6. Android Studio执行Java类的main方法及解决方法
  7. Android 延迟执行方法

随机推荐

  1. html表格作业
  2. Excelize -Go 开源项目中唯一支持复杂样
  3. java安全编码指南之:基础篇
  4. 一种简单快捷的 java 热部署方式
  5. UI设计师应该学习哪些软件?
  6. Spring Cloud应用在Kubernetes的最佳实践
  7. 干货丨DolphinDB集群如何扩展节点和存储
  8. 【DB宝44】Oracle rac集群中的IP类型简介
  9. 总结3.22
  10. react中的render-props模式