Android Input(九)-Input问题分析指北

原创内容,转载请注明出处,多谢配合。

经过前面八篇文章的铺垫,应该对Input系统有了全方面的了解了,最后一篇打算简单整理下Input相关问题分析。

Input相关问题主要包括这么几类:

一、 tp报点问题

这是偏底层的问题,主要是InputReader读取event及其之间的阶段。
1)查看支持的设备节点

/dev/input $ ls                                                                                                                                  
event0 event1 event2 event3 event4 event5 event6

这里常见的event节点对应的设备: 比如event0对应key、event3对应motion

2)查看报点情况:

  • adb命令来看
 adb shell getevent -ltr 

打印的信息:

[      83.879437] /dev/input/event3: EV_ABS       ABS_MT_POSITION_X    00000100
[      83.879437] /dev/input/event3: EV_ABS       ABS_MT_POSITION_Y    0000065b
[      83.879437] /dev/input/event3: EV_ABS       ABS_MT_TOUCH_MAJOR   00000046
[      83.879437] /dev/input/event3: EV_SYN       SYN_REPORT                  00000000             rate 114
[      83.887649] /dev/input/event3: EV_ABS       ABS_MT_POSITION_X    000000b6
[      83.887649] /dev/input/event3: EV_ABS       ABS_MT_POSITION_Y    00000611
[      83.887649] /dev/input/event3: EV_ABS       ABS_MT_TOUCH_MAJOR   00000038
[      83.887649] /dev/input/event3: EV_SYN       SYN_REPORT                  00000000             rate 121

可以滑动看报点是否正常,以及滑动看rate加速度是否平稳。

  • systrace来看:

iq: 描述system_server中 InputReader读取事件

aq: 描述应用端获取事件

报点异常主要看iq,看一次down move(N) up 的流程是否顺畅,(当然tp报点也有优化,在相同位置是不报的),这个就看经验了朋友,一般来说机械手测量相对比较稳定,容易看出差异。

二、 Input耗时

一次用户输入事件的传递过程可以描述为: 硬件 -> kernel -> system_server -> app
简化出5个时间点:

  • T1 表示 硬件中断的时间
  • T2 表示 InputReader 从 /dev/input/xxx 读出事件的时间(InputReader读取事件的时候对事件打上时间戳)
  • T3 表示 InputDispatcher 向 app 进程发送事件的时间
  • T4 表示 app 主线程开始处理输入事件的时间
  • T5 表示 app 主线程完成处理输入事件的时间

这个流程主要耗时点简单两个部分:(T1-T2这个阶段主要与底层报点相关,参考第一点)

system_server 耗时: T3 - T2

frameworks/native/libs/input/InputTransport.cpp

status_t InputPublisher::publishKeyEvent(...){
    currentTime - eventTime
    return mChannel->sendMessage(&msg);
}

这里是InputDispatcher与窗口建立connection之后,准备发送消息了,可以在这里增加日志打点,通过统计InputReader读取事件的时候对事件打上时间戳 与 执行当前方法的currentTime做对比,可以得知input时间在system_server处理过程中是否耗时。

应用处理耗时: T5 - T4

app端是通过InputEventReceiver来接收消息的,
开始分发的起点函数:

private void dispatchInputEvent(...){
  记录startTime
}

log示例:

03-26 18:25:06.590  1306  1773 W InputTransport: Slow Input: 372ms so far, channel '3908d6b NavigationBar (server)' publisher ~ publishMotionEvent: seq=3004, deviceId=6, source=0x1002, action=0x2, actionButton=0x00000000, flags=0x0, edgeFlags=0x0, metaState=0x0, buttonState=0x0, xOffset=0.000000, yOffset=-2210.000000, xPrecision=1.000000, yPrecision=1.000000, downTime=28011572008000, eventTime=28011595886000, pointerCount=1

分发结束的终点函数:

public final void finishInputEvent(...){
   currentTime - startTime
}

log示例:

03-22 11:04:07.692 7001 7001 W InputEventReceiver: App Input: Dispatching InputEvent took 114ms in main thread! (MotionEvent: event_seq=239, seq=7, action=ACTION_UP)

由此可以知道Input事件是否在应用端分发耗时。

三、 Input ANR

Input在本次input event处理耗时的情况下本身是不会触发ANR检查的,需要下一个input分发才会开始计算ANR超时。

Input ANR的原理与分析方法可以参考我之前的文章:
原理:Android Input(八)- ANR原理分析
分析方法:ANR问题分析

最后做个实战调试:
通过一个motion event的log打印来看下anr流程,开打InputDispatcher.cpp DEBUG_FOCUS开关,这里除了有系统log,我自己也加了点log。

写了个app, MainActivity中Button onClick直接睡眠足够长时间。

ANR发生:

从inBoundQueue取出一个事件:
07-25 19:37:48.760 1517 2010 D InputDispatcher: InputTest: dequeueAtHead

重置ANR Timeout时间
07-25 19:37:48.760 1517 2010 D InputDispatcher: Resetting ANR timeouts.

执行InputDispatcher::handleTargetsNotReadyLocked
对应reason触发的条件:
!connection->waitQueue.isEmpty() && currentTime >= connection->waitQueue.head->deliveryTime+ STREAM_AHEAD_EVENT_TIMEOUT(500ms)
翻译过来是waitQueue不为空,就是之前事件传递到应用端还没有callback回来,且等待队头时间超时500ms,这就意味着无法及时与focus window建立connection连接,开始触发ANR时间统计。

07-25 19:37:48.760 1517 2010 D InputDispatcher: Waiting for application to become ready for input: Window{e347a9 u0 com.stan.perfdemo/com.stan.perfdemo.MainActivity}. Reason: Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 6069.2ms.

反复执行InputDispatcher::findTouchedWindowTargetsLocked,此时对应的mPendingEvent != NULL,那么无法重置ANR Timeout
07-25 19:37:48.760 1517 2010 D InputDispatcher: findTouchedWindow finished: injectionResult=-1, injectionPermission=1, timeSpentWaitingForApplication=0.0ms
07-25 19:37:48.761 1517 2010 D InputDispatcher: InputTest: (mPendingEvent != NULL)=1
07-25 19:37:48.761 1517 2010 D InputDispatcher: findTouchedWindow finished: injectionResult=-1, injectionPermission=1, timeSpentWaitingForApplication=1.3ms
07-25 19:37:48.763 735 826 E ANDR-PERF-MPCTL: Invalid profile no. 0, total profiles 0 only
07-25 19:37:48.853 1517 2010 D InputDispatcher: InputTest: (mPendingEvent != NULL)=1
07-25 19:37:48.854 1517 2010 D InputDispatcher: findTouchedWindow finished: injectionResult=-1, injectionPermission=1, timeSpentWaitingForApplication=93.9ms
...
07-25 19:37:56.770 1517 2010 D InputDispatcher: InputTest: (mPendingEvent != NULL)=1

满足ANR触发时间
07-25 19:37:56.770 1517 2010 D InputDispatcher: InputTest: onANRLocked : currentTime - mInputTargetWaitTimeoutTime=10341423

InputDispatcher::onANRLocked方法的打印,开始走ANR流程
07-25 19:37:56.770 1517 2010 I InputDispatcher: Application is not responding: Window{e347a9 u0 com.stan.perfdemo/com.stan.perfdemo.MainActivity}. It has been 8013.3ms since event, 8010.3ms since wait started. Reason: Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 14079.5ms.
07-25 19:37:56.772 1517 2010 D InputDispatcher: findTouchedWindow finished: injectionResult=-1, injectionPermission=1, timeSpentWaitingForApplication=8010.3ms

然后这里会生成doNotifyANRLockedInterruptible加入commandQueue中,下次执行InputDispatcher::dispatchOnce 时候,先执行command
...

InputMonitor.java 执行notifyANR方法的打印
07-25 19:37:56.773 1517 2010 I WindowManager: Input event dispatching timed out sending to com.stan.perfdemo/com.stan.perfdemo.MainActivity. Reason: Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 14079.5ms.
...
开始AMS执行anr流程dump trace以及弹窗提示并打印ANR log信息
07-25 19:38:00.302 1517 1534 E ActivityManager: ANR in com.stan.perfdemo (com.stan.perfdemo/.MainActivity)
07-25 19:38:00.302 1517 1534 E ActivityManager: PID: 7118
07-25 19:38:00.302 1517 1534 E ActivityManager: Reason: Input dispatching timed out (com.stan.perfdemo/com.stan.perfdemo.MainActivity, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 14079.5ms.)
07-25 19:38:00.302 1517 1534 E ActivityManager: Load: 0.64 / 0.23 / 0.12
07-25 19:38:00.302 1517 1534 E ActivityManager: CPU usage from 15975ms to 0ms ago (2019-07-25 19:37:40.864 to 2019-07-25 19:37:56.839):
07-25 19:38:00.302 1517 1534 E ActivityManager: 2.6% 1517/system_server: 1.7% user + 0.8% kernel / faults: 907 minor

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
禁止转载,如需转载请通过简信或评论联系作者。
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,047评论 6 492
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,807评论 3 386
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 158,501评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,839评论 1 285
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,951评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,117评论 1 291
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,188评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,929评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,372评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,679评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,837评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,536评论 4 335
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,168评论 3 317
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,886评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,129评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,665评论 2 362
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,739评论 2 351

推荐阅读更多精彩内容