愿历尽千帆 归来仍少年

一个屏幕滑动无响应问题的分析流程

字数统计: 2,048阅读时长: 10 min
2018/05/29

问题现象
在应用中出现屏幕右滑无响应

复现概率:
once

问题平台:
Android N MT6739

Step1 初步分析
考虑到当时按power键能够退出应用回到待机(项目中对power键功能进行了定制),说明没有发生死机
刚接到问题的时候,第一反应是觉得可能发生了ANR,与测试同事沟通,当时没有弹框出来。ok,拿到机器后, 将data/anr文件夹pull出来看下,内容为空。进到event日志中. 搜索"am_anr"关键字,没有搜到。测试同事所言没错,当时没有弹框出来是因为并没有发生ANR
那会不会是低内存呢,这样猜想并不是没有道理的。因为我们机器本身内存比较小,之前经常出现内存不足的情况。进到kernel日志中看下lowmemorykiller杀进程的次数,只有四次且都不在问题发生的时间段,看来当时内存没有紧张
ok,大写的懵逼…下面开始分析日志

Step2 日志分析
测试同事反馈当时因为右滑无法退出(项目中对右滑进行了特殊处理代替虚拟按键返回键),只能通过power键退出
ok,先找到按power键的时间点

step 2.1 main日志
我们知道按键会先到PhoneWindowManagerinterceptKeyBeforeQueueing函数进行处理,然后才会分发给应用,power键也不例外,只是power键会做特殊处理不会分发给应用
根据测试同事反馈的时间点,在main日志中搜到如下对应时间点的日志片段

1
05-28 18:12:42.019221  1038  1103 D WindowManager: interceptKeyBeforeQueueing: eventKeyEvent { action=ACTION_UP, keyCode=KEYCODE_POWER, scanCode=116, metaState=0, flags=0x8, repeatCount=0, eventTime=667518, downTime=667326, deviceId=1, source=0x101 }

这一处的日志便是PhoneWindowManagerinterceptKeyBeforeQueueing函数中打印,问题点确定了在18:12:42.019221之前三四十秒的时间段内,ok,范围缩小了

step2.2 event日志
这里顺便说下,event日志一般记录了各个activity周期及事件,我个人一般看event日志主要看当时的界面变化过程以及确定anr时间点

1
2
3
4
5
05-28 18:11:53.766062  1038  1091 I am_resume_activity: [0,123117617,8,com.XXX.music/.MusicActivity]
....
05-28 18:12:42.130951 1038 1053 I am_pause_activity: [0,123117617,com.XXX.music/.MusicActivity]
....
05-28 18:12:42.223856 1038 1274 I am_resume_activity: [0,69789570,2,com.XXX.launcher/.activity.MainActivity]

这里可以确定问题发生时界面停留在音乐应用,后面因为按了power键的缘故回到了待机界面

step2.3 sys日志
对于sys日志呢,一般输出的是系统日志,一般在main日志里找不到可以在sys日志里找到

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
//Music应用开始播放音乐
05-28 18:10:01.384340 2827 2827 E MusicActivity: Receive: 讲真的
…..
//按power键点亮屏幕
05-28 18:11:53.771419 1038 1103 D WindowManager: interceptKeyBeforeQueueing: eventKeyEvent { action=ACTION_UP, keyCode=KEYCODE_POWER, scanCode=116, metaState=0, flags=0x8, repeatCount=0, eventTime=619270, downTime=619127, deviceId=1, source=0x101 }
05-28 18:11:53.843990 1558 1558 D LauncherMainActivity: screen on
......
05-28 18:11:58.195224 1038 1082 D SystemGestures: mSwipeFireable=false mSwipeType=1
05-28 18:11:58.866527 1038 1082 D SystemGestures: pointer 0 down pointerIndex=0 trackingIndex=0
05-28 18:11:58.866599 1038 1082 D SystemGestures: pointer 0 down x=0.0 y=100.58091
05-28 18:11:58.874044 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,100.58091->253.94191) in 10
05-28 18:11:58.883822 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,100.58091->0.0) in 19
05-28 18:11:58.893310 1038 1082 D SystemGestures: pointer 0 moved (0.0->20.912863,100.58091->203.15353) in 29
05-28 18:11:58.895061 1038 1082 D SystemGestures: Firing onSwipeFromLeft
.....
05-28 18:12:32.243408 1038 1082 D SystemGestures: mSwipeFireable=false mSwipeType=4
05-28 18:12:32.414854 1038 1082 D SystemGestures: pointer 0 down pointerIndex=0 trackingIndex=0
05-28 18:12:32.415105 1038 1082 D SystemGestures: pointer 0 down x=0.0 y=0.0
05-28 18:12:32.423284 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,0.0->253.94191) in 10
05-28 18:12:32.423391 1038 1082 D SystemGestures: Firing onSwipeFromTop
.....
05-28 18:12:34.611702 1038 1082 D SystemGestures: mSwipeFireable=false mSwipeType=1
05-28 18:12:34.861078 1038 1082 D SystemGestures: pointer 0 down pointerIndex=0 trackingIndex=0
05-28 18:12:34.861215 1038 1082 D SystemGestures: pointer 0 down x=0.0 y=86.63901
05-28 18:12:34.868822 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,86.63901->253.94191) in 9
05-28 18:12:34.878235 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,86.63901->0.0) in 19
05-28 18:12:34.888622 1038 1082 D SystemGestures: pointer 0 moved (0.0->31.86722,86.63901->179.25311) in 29
05-28 18:12:34.888704 1038 1082 D SystemGestures: Firing onSwipeFromLeft
.....
05-28 18:12:37.952528 1038 1082 D SystemGestures: mSwipeFireable=false mSwipeType=4
05-28 18:12:38.195578 1038 1082 D SystemGestures: pointer 0 down pointerIndex=0 trackingIndex=0
05-28 18:12:38.195683 1038 1082 D SystemGestures: pointer 0 down x=0.0 y=0.0
05-28 18:12:38.201532 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,0.0->253.94191) in 9
05-28 18:12:38.201606 1038 1082 D SystemGestures: Firing onSwipeFromTop
......
05-28 18:12:40.888861 1038 1082 D SystemGestures: mSwipeFireable=false mSwipeType=1
05-28 18:12:41.131752 1038 1082 D SystemGestures: pointer 0 down pointerIndex=0 trackingIndex=0
05-28 18:12:41.131874 1038 1082 D SystemGestures: pointer 0 down x=0.0 y=95.60166
05-28 18:12:41.137845 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,95.60166->253.94191) in 9
05-28 18:12:41.147534 1038 1082 D SystemGestures: pointer 0 moved (0.0->0.0,95.60166->0.0) in 19
05-28 18:12:41.157208 1038 1082 D SystemGestures: pointer 0 moved (0.0->20.912863,95.60166->209.12863) in 29
05-28 18:12:41.157279 1038 1082 D SystemGestures: Firing onSwipeFromLeft
......
//按power键返回待机界面
05-28 18:12:42.019221 1038 1103 D WindowManager: interceptKeyBeforeQueueing: eventKeyEvent { action=ACTION_UP, keyCode=KEYCODE_POWER, scanCode=116, metaState=0, flags=0x8, repeatCount=0, eventTime=667518, downTime=667326, deviceId=1, source=0x101 }
05-28 18:12:42.036468 1558 1558 D LauncherService: goback to homescreen and clear all background apps
......
//此时通过launcher菜单再次进入Music应用,提示处于高温下
05-28 18:21:56.784003 1558 1558 I LauncherMainActivity: onItemClick, position = 10
05-28 18:21:56.784848 1558 1558 D LauncherMainActivity: isNetwrokOk = :true,isBinded = :true,isHighTemper = :true

这段日志呢可以看出屏幕无响应的一段时间内,是有手势滑动发生的

step2.4 代码分析
既然有手势滑动为什么界面不能退出呢,是不是我们自己写的判断条件出了问题,上面日志中这些片段

1
SystemGestures: pointer 0 moved (0.0->20.912863,95.60166->209.12863) in 29

代表什么意思呢, 跟到代码里看一看
frameworks/base/services/core/java/com/android/server/policy/SystemGesturesPointerEventListener.java

1
2
3
4
5
6
7
8
private int detectSwipe(int i, long time, float x, float y) {
final float fromX = mDownX[i];
final float fromY = mDownY[i];
final long elapsed = time - mDownTime[i];
if (DEBUG) Slog.d(TAG, "pointer " + mDownPointerId[i]
+ " moved (" + fromX + "->" + x + "," + fromY + "->" + y + ") in " + elapsed);
//省略部分代码
}

日志打印的代表X坐标,Y坐标的滑动变化以及滑动时间

此时再来看看日志中问题发生时测试同事滑动轨迹,Y坐标看上去没有问题,X坐标看着有点奇怪,怎么都是从0开始的呢,且松开时移动距离非常小
那么如此小的移动距离,有没有满足滑动退出的条件呢?因为这一块判断条件是客制化的,需要X坐标滑动起码达到60才能满足滑动退出的条件,这里就不贴出具体代码

小结:
在测试同事反应屏幕滑动无响应的时间段内,40秒的时间段内有四次手势发生,手指滑动的X坐标变化幅度很小
鉴于SystemGesturesPointerEventListener.java这支文件中的detectSwipe函数会对X坐标的变化幅度进行判断,至少达到60以上才会返回SWIPE_BACK(该type类型是根据项目客制化添加的)
很显然上面日志中X坐标变化幅度没有达到这个要求,也就导致了onPointerEvent函数中走不到inject back action逻辑中,从而系统判断没有返回事件发生
同测试同事沟通当时是正常的尝试滑动退出,故上面的X坐标变化历程显然有误,数值过小且起始点坐标与落下点坐标也与实际情况不符

综合下来: 判定是屏幕报点不准导致

Have a good day!


公司,上班前,听着歌,惬意
CATALOG