一个H5应用卡顿问题分析记录

文章目录

• 1.问题背景
• 2.导出应用
• 3.初步分析
• 4.Systrace分析
• 5.webview的trace分析
• 6.显示为什么会延迟
• 7.抓包分析
• 8.正向分析

1.问题背景

客户反馈有一个应用在我们的新样机上，输入界面非常卡顿，在其他机器上表现正常。现在只有一台安装了客户的应用，能复现问题的机器。
硬件平台：SL8541
Android版本： Android 8.1

2.导出应用

只有一台安装了客户应用的机器，没有app，更别说源码了。首先要想办法把应用取出来，安装到别的机器上去，不然这个环境坏了就没法分析了。
主要思路，是将/data/app中的apk和/data/data下面的数据文件取出来，复制到其他机器上去。
写个脚本一键处理：

adb remount
adb shell setenforce 0
adb push  ServiceHost.ServiceHost-CZtGOt1HDc-lSyYEWeVbbg==.zip  /data/app/
adb shell " cd /data/app/ && tar xvf ServiceHost.ServiceHost-CZtGOt1HDc-lSyYEWeVbbg==.zip ServiceHost.ServiceHost-CZtGOt1HDc-lSyYEWeVbbg== "
adb shell " chmod 777 -R  /data/app/ServiceHost.ServiceHost-CZtGOt1HDc-lSyYEWeVbbg== "
adb shell " pm install -r /data/app/ServiceHost.ServiceHost-CZtGOt1HDc-lSyYEWeVbbg==/base.apk "
adb push ServiceHost.ServiceHost.zip /data/data/
adb shell " cd /data/data && tar xvf ServiceHost.ServiceHost.zip  ServiceHost.ServiceHost "
adb shell " chmod 777 -R /data/data/ServiceHost.ServiceHost "
adb shell sync
adb shell stop zygote
adb shell start zygote
ping -n 50 127.0.0.1>nul
adb shell am start -n ServiceHost.ServiceHost/md5bd7813ef94204169d60c7bafe7bcc17b.ServiceHostView
pause

3.初步分析

top -m 5

cpu负载不高，内存占用虽然大点，但也还算正常，因为这个应用本身也比较大。

dumpsys meminfo

系统可用内存充足，不太可能是GC导致的卡顿。
实际上，除了客户应用的输入界面卡顿以外，系统是非常流畅的。

4.Systrace分析

我们用Android sdk提供的systrace工具，抓一份systrace分析一下。
工具路径：sdk/platform-tools/systrace
如果抓systrace报错，请看 Systrace环境配置
指定ServiceHost.ServiceHost这个包名，抓一份5秒的trace，只点击一次屏幕，这样比较容易分析和还原这个过程。

python2.7 systrace.py -t 5 sched gfx input view webview wm am app network -a ServiceHost.ServiceHost -o out.html

抓取完成后，用浏览器打开。
我们这里用Chrome打开，如下图。可以看到，在这个过程中，cpu并不忙。

往下拉一点，看下ServiceHost.ServiceHost应用相关的线程有没有问题。
用鼠标拉取这一段处理过程，测量一下，一共是1.264S。用秒表测量时间，从点击按键到UI显示星号，大约是1.5S。那么可以确定，我们选取的这一段，就是一次点击到UI显示的全过程。
下图我们看到有输入事件，以及3次渲染，其中第2次和第3次渲染间隔时间很长，大约是1S。
这3次渲染，分别对应手指按下，手指抬起，以及显示星号。也就是说，从手指抬起，到星号显示出来，花了1S，难怪体验非常卡顿！

那么，为什么第2次渲染和第3次渲染间隔1S呢，这也许是问题的关键。
再往下拉，看一下webview相关的线程，好像做了一些事情。

放大一点看，发现webview有个本地的http请求。抓了几次systrace分析，都是这个请求之后，才进行第3次UI渲染。http请求跟渲染有没有关系？这是一个疑点，但按理说，显示不应该跟网络有关系。

从Systrace目前只提取到这些信息。
还需要继续分析，为什么第2次渲染跟第3次渲染间隔1S？应用是不是在发http请求做什么事情？

5.webview的trace分析

没有其他思路了，我们尝试抓一个webview的trace看看，能更清楚地看到webview内部在做什么事情。
怎样抓webview的trace

先看个大概，红色的圆圈表示更新屏幕。Chrome_InProcRenderThread线程里面，这些绿色的线条出现得很有规律，差不多1S一次。

放大一点，可以清晰地看到，这个周期性的线条，是一个本地的http请求，应该是应用在取什么数据，或者是心跳包。由于请求带有“Events”，为描述方便，我们称之为Events请求。

仔细看，还能找到另外一个请求，请求带有“command”，为描述方便，我们称之为command请求。

6.显示为什么会延迟

从目前的分析结果看，cpu负载轻，剩余内存充足，基本可以确定不是系统导致的卡顿，而是应用本身的问题。
那么，是不是因为应用在等数据，导致显示延迟呢？因为本地的http请求刚好是1S一次，有理由怀疑。
如何证明？
最简单的是排除法，既然是本地http请求，那么我们把回环网卡lo禁用，这个请求就永远不会返回了。

ifconfig lo down

这一招非常有效，禁用lo后，再点击按键，UI再也不会更新了。说明UI确实是等http请求返回才更新的！
上文提到，应用有2个http请求，一个是Events，一个是command，那么，UI到底是在等哪个请求返回呢？
继续用排除法。我们用iptables设置网络规则，禁止特定的url访问。

iptables -A INPUT -m string --string "command" --algo bm --to 65535 -j DROP
iptables -A OUTPUT -m string --string "command" --algo bm --to 65535 -j DROP

以上两条命令的意思是，INPUT链和OUTPUT链，禁止带有“command”字符的url访问。
通过这个方法，我们确定了UI是等command请求返回后，才更新的。至于为什么是这样，目前也没有足够的分析手段。

7.抓包分析

分析到这里，其实也只是找到了可能的问题点。TCP网络层很复杂，要找到原因不是那么容易。只能感慨老外太能折腾，竟然在应用里面搞个client和本地server，数据还各种加密，让你无法分析。
我们通过对比测试，发现这个问题只在SL8541上出现，在MSM8909和A63上都没有问题，怀疑还是跟平台关系大一点。
通过tcpdump抓包对比分析SL8541和MSM8909，又有一点新发现。
发现每点击一次，应用会发送一个command请求。

tcpdump -i lo

SL8541的command请求，从请求到返回耗时1S，如下图：

MSM8909的command请求，从请求到返回耗时200ms，如下图：

现在问题的原因就很明确了，点击按钮，应用发送command请求，command请求返回后，更新UI。由于SL8541平台command请求响应很慢，导致UI更新延迟，体验卡顿。

8.正向分析

至此，也没有什么好办法了，只能在kernel网络层加日志，一步步往下分析。
求助原厂，最终定位到是SL8541平台的网络层，TCP/IP重传超时的最小值TCP_RTO_MIN被他们改过，原生linux是HZ/5，也就是200ms，SL8541平台改成了HZ，刚好是1S。

diff --git a/idh.code/kernel/include/net/tcp.h b/idh.code/kernel/include/net/tcp.h
old mode 100644
new mode 100755
index f4eb1223cf..eb2810fe84
--- a/idh.code/kernel/include/net/tcp.h
+++ b/idh.code/kernel/include/net/tcp.h
@@ -132,7 +132,7 @@ void tcp_time_wait(struct sock *sk, int state, int timeo);
#define TCP_ATO_MIN    4U
#endif
#define TCP_RTO_MAX    ((unsigned)(7*HZ))
-#define TCP_RTO_MIN    ((unsigned)(HZ))
+#define TCP_RTO_MIN    ((unsigned)(HZ/5))
#define TCP_TIMEOUT_INIT ((unsigned)(1*HZ))    /* RFC6298 2.1 initial RTO value        */
#define TCP_TIMEOUT_FALLBACK ((unsigned)(3*HZ))        /* RFC 1122 initial RTO value, now
* used as a fallback RTO for the

最后，感慨一下，这个坑挖得真大！