[未解之谜]Email加载邮件详情慢

问题描述

打开Emial主界面，点击打开一封邮件，待邮件详情完全加载出来结束。这个过程相对参考机慢300ms左右.
问题机Email版本:versionName=v5.2.10.3.0214.0
参考机Email版本:versionName=v7.0.4.1.0312.0_0228

问题分析

硬件对比

• cpu 采用命令adb shell cat /proc/cpuinfo分别查看问题机与参考机cpu信息。得到下图结果
  
  二者cpu均为高通4核cpu。
• memory 采用命令adb shell cat /proc/meminfo分别查看memory信息。得道下图结果。
  
  内存总大小问题机大于参考机
• 分辨率 采用命令adb shell wm size和adb shell wm density分别查看分辨率
  参考机:
  Physical size: 720x1280
  Physical density: 320
  问题机:
  Physical size: 720x1280
  Physical density: 320
  问题机地分辨率低。

Systrace对比

在不链接网络的情况下，用相同的邮箱账号登陆邮件，测试发现确实能感受到问题机比参考机慢一点。为了尽量排除其他方面的影响，adb shell pm disable 掉其他一些无关应用，然后抓取不链接网络情况下问题机的systrace。

./systrace.py –app=com.tct.email gfx input wm am sm res pm database disk mmc load view sched dalvik webview -o mick-email-new-v7.html

参考机systrace结果：

问题机systrace结果：

可以看到问题机1s～2s的时间区间内出现了一段真空地带,这个真空地带表明负责显示邮件内容的UI Thread这段时间没有在干活。这个真空地带是需要check的，很可能就是问题所在。

在键盘输入4，或者鼠标点击面板的最后一个图标，拉动鼠标选中空白地带，这时该区域呈高亮状态，方便观察。

高亮的空白区域耗时0.88s，也就是说在这0.88s UI Thread处在空闲状态，这个是非常不合理的。

上图是查看空白区域的结果，查看重点用红框标示了出来。
针对框2，这个区域在我的浏览器为空白底色，不仔细放大观察，以为没什么东西，当用鼠标点击就会出现框3。这个是该bug给我们留下的线索。追上去，咬住它！
点击框3中的kworker/1:4，得到下图：

框3清楚的显示出UI Thread为sleeping状态。它竟然在组织正需要它的时候闷头睡大觉，可恶>_<。
取而代之的是一个名叫kworker/1:4的家伙在干活干的飞起。这尼玛什么鬼，看起来是内核线程在工作啊。
同时我们知道了kworker/1:4的线程id：tid: 25514。是时候看看kworker/1:4是何方神圣了。

要找出kworker究竟在干什么，不是一件容易的事情。对这方面缺乏经验，只能google之。
根据http://bootloader.wikidot.com/linux:android:kmsg尝试探究kworker。

首先尝试klog：
单编/system/core/klog将生成的klog push到手机。无奈运行后没有生成任何文件，换路跟踪。

再次尝试：adb shell dmesg |grep 25514

[53573.013494] c1 [kworker/1:4 25514] BMS: lookup_soc_ocv: soc_final=100 soc_ocv=100 soc_cutoff=2 ocv_uv=4365250 batt_temp=284[53638.385439] c1 [kworker/1:4 25514] BMS: lookup_soc_ocv: soc_final=100 soc_ocv=100 soc_cutoff=2 ocv_uv=4364155 batt_temp=290[53642.865874] c1 [kworker/1:4 25514] power_supply battery: 2017-04-14 05:47:34 status:Discharging,health:Good,voltage:4351mV,capacity:100,current:148mA,temperature:28.6C,chgvoltage:111mV[53652.355277] c1 [kworker/1:4 25514] power_supply battery: 2017-04-14 05:56:56 status:Discharging,health:Good,voltage:4351mV,capacity:100,current:0mA,temperature:28.6C,chgvoltage:111mV[53655.318874] c1 [kworker/1:4 25514] BMS: lookup_soc_ocv: soc_final=100 soc_ocv=100 soc_cutoff=2 ocv_uv=4363258 batt_temp=286[53655.452755] c1 [kworker/1:4 25514] power_supply battery: 2017-04-14 06:04:51 status:Charging(USB),health:Good,voltage:4383mV,capacity:100,current:57mA,temperature:28.2C,chgvoltage:4932mV[53655.486877] c1 [kworker/1:4 25514] power_supply battery: 2017-04-14 06:04:51 status:Full,health:Good,voltage:4380mV,capacity:100,current:57mA,temperature:28.2C,chgvoltage:4925mV

从这段log还是看出了点端倪。kworker/1:4 是在执行power相关的逻辑。
先追查lookup_soc_ocv 函数出处：
kernel/drivers/power/qpnp-vm-bms.c，底层同事添加了一行log：

#if defined (BUILD_ENG_VERSION)    pr_err("soc_final=%d soc_ocv=%d soc_cutoff=%d ocv_uv=%u batt_temp=%d\n",            soc_final, soc_ocv, soc_cutoff, ocv_uv, batt_temp);#endif

这里也加了判断，只有eng版本才会打印该log。而我因为需要root权限采取了user版本+eng boot的组合刷机。同时用user版本的boot测试也看到了kworker在block UI Thread。因此这个不是问题。
剩下power_supply来排查，无奈对kernel所知甚少，没有找出power_supply为何回出现。至此该条线陷入走投无路的窘境。

其它debug手段

Systrace这条分析线没有突破，就尝试其它debug手段，先从vm配置查起。

adb shell getprop|grep dalvik

到到如下结果：

这里先介绍下系统的java vm各个配置项的含义。

• dalvik.vm.heapgrowthlimit 从字面解释就是堆内存的增长上限。也就是一个普通Android进程可使用的java层最大内存，如果给应用设置了android:largeHeap="true" 属性，那么它就不在普通了，可使用的最大内存就取决与dalvik.vm.heapsize的值了。
• dalvik.vm.heapsize Android Java空间的堆内存上限。如果没有设置android:largeHeap="true" 属性，真正约束进程堆内存上限的还是dalvik.vm.heapgrowthlimit 属性的值
• dalvik.vm.heapstartsize Android进程Java空间初始堆大小
• dalvik.vm.heapmaxfree Android进程Java堆内存最大剩余空间
• dalvik.vm.heapminfree Android进程Java堆内存最小剩余空间
• dalvik.vm.heaptargetutilization Android进程Java堆内存利用率

以上是比较书面的解释，打个通俗的比方来对照理解上面各项的含义。

银行信用卡总部计划为个人提供一种额度最高上线为20万元的卡，这个就是heapsize。然后具体到各个分行执行时，考虑到风控，到普通个人头上时，该信用卡额度降成了10万，这就是heapgrowthlimit。如果王麻子跟分行的行长熟，老铁给我给我提升额度呗，这就是王麻子设置了largeheap=true。行长说没问题，给你搞到最高额度，于是王麻子的额度就不在受分行10万元的额度限制了，但它依然受总行20万元的限制。

然后王麻子开始第一次使用信用卡，不管王麻子实际要用多少钱，银行只提供1万元。多了他留着，不够在提申请。这个就是heapstartsize。

银行出于风险收益考虑，怕王麻子顶额透支信用卡风险太高，如果放款太少的话银行收益又低。因此就提出了一个信额使用率的概念，就是heaptargetutilization，它等于已经分配出去的内存空间/可用内存空间。
在配合上最大闲置资金heapmaxfree和最小闲置资金heapminfree一起来管控收放资金。

上面说了这么多，检查下来dalvik.vm的配置不是导致性能的瓶颈。

在看CPU方面，从Systrace确实看到问题机的CPU相对于参考机有部分闲置情况。进入手机shell环境，使用命令：

echo 1 > /sys/devices/system/cpu/cpu0/online
echo 1 > /sys/devices/system/cpu/cpu1/online
echo 1 > /sys/devices/system/cpu/cpu2/online
echo 1 > /sys/devices/system/cpu/cpu3/online

将4颗CPU都拉起来，但依然还有问题，看起来瓶颈也不在CPU。

email的正文是webview渲染出来的。可能也回涉及到GPU，在从这个方向debug。使用命令：

echo performance > /sys/class/kgsl/kgsl-3d0/devfreq/governor

将GPU调整至性能模式，依然有问题。

内存不是瓶颈，CPU/GPU不是瓶颈，不由的让我考虑emcc的影响，之前跑一些跑分软件就发现问题机的emcc读写速率不及参考机。最直接有效的办法是交换参考机和问题机的emcc，然而在实际操作中，硬件结构同事并不那么配合。因此也只能停留在猜想阶段了。

自己猜测，问题的瓶颈在于加载Email详情需要从数据库和文件读取邮件正文内容，这个过程不可避免的涉及I/O，问题机的emcc读取速率较低，因此在该处形成了性能瓶颈。

写在后面

该问题看似找到了一点突破口，但在分析转到kernel部分后无法继续在分析。还得多掌握Linux底层调试技巧跟方法。

后续若有进展还会更新，也欢迎看到得朋友提供思路跟方法。