启动耗时分析(四)-具体方法耗时分析

原创文章,转载请注明出处,多谢!

如果cpu频率、调度 和 compiler filter都一一排除了,没问题。那接下来就看是否有具体方法耗时。

一、常用的分析手段:

1.systrace
这里可按systrace中各个阶段来逐段对比分析,当然这里也分冷热启。
冷启动可以拆分如下若干阶段:
deliver input / fork process / bind application / activity start / doFrame / drawFrame / SF invalidate&refresh
热启动就主要考虑绘制和渲染了。

看是否差距集中在一个某个阶段内,如果是特定区域的差异那么就来针对具体方法耗时进行分析。
找到有差异的阶段可以通过加trace,来缩小范围和细化具体方法。

各层加trace的方式:
APP:

Trace.beginSection("");
Trace.endSection();

注:抓systrace的时候需要指定对应的app进程。

系统java层:

Trace.traceBegin(Trace.TRACE_TAG_VIEW, "inflate”);
Trace.traceEnd(Trace.TRACE_TAG_VIEW);

注:前面的tag参数对应的抓systrace的开关选项。

Native:

#define ATRACE_TAG ATRACE_TAG_ALWAYS

#include <utils/Trace.h> // for c++
#include <cutils/trace.h> // for c

ATRACE_CALL();
or
ATRACE_BEGIN("");
ATRACE_END();

2. TraceView or AS profile cpu
对于app的问题,可以借助traceView 或者 as profile cpu检查 CPU Activity 和函数跟踪来帮助定位耗时方法,不断缩小范围来定位问题。

3. 反编译
对于三方app,没有源码,可以通过oatdump反编译来分析:
adb shell oatdump --oat-file=/data/app/包名/oat/arm64/base.odex > demo.txt
字节码命令说明

二、实战举例:高德地图耗时分析

1.发现问题

在cpu频率、调度 和 compiler filter都一一排除了的前提下,通过systrace来分析具体启动各阶段耗时情况。

Android N:

Android O:

发现MapContainer执行时间比较长,MapContainer 是高德自己实现的类,应该是高德自己的实现方式在不同 Android 版本上差别比较大。因为高德是三方应用,没有代码,所以借助traceView来分析。

注:如果是冷启动可以使用命令行来抓取:

1)启动指定 Activity 同时启动 trace

am start -n com.stan.note.newdemo/.MainActivity --start-profiler /data/local/tmp/test.trace

am profile com.stan.note.newdemo stop

2)启动指定 Activity 同时启动 trace, 自动结束

am start -n com.stan.note.newdemo/.MainActivity -P /data/local/tmp/test.trace

通过 TraceView 发现有两个相关的方法非常耗时:

com.autonavi.mao.core.OverlayManager.init ()V
com.autonavi.minimap.commute.CommuteOverlay.init ()V

下面通过oatdump来反编译这两个方法

截取一个小片段:

void com.autonavi.minimap.commute.CommuteOverlay.init() (dex_method_idx=20281)

   DEX CODE:
     0x0000: 1202                      | const/4 v2, #+0
     0x0001: e530 0800                 | iget-object-quick v0, v3, // offset@8
     0x0003: 7110 6006 0000            | invoke-static {v0}, android.view.LayoutInflater android.view.LayoutInflater.from(android.content.Context) // method@1632
     0x0006: 0c00                      | move-result-object v0
     0x0007: 6001 a235                 | sget  v1, I com.autonavi.minimap.R$layout.commute_marker_layout // field@13730
     0x0009: e930 1200 1002            | invoke-virtual-quick {v0, v1, v2},  // vtable@18
     0x000c: 0c00                      | move-result-object v0

这里就想找到art指令中对应的函数并加上trace,来确定是哪个具体函数耗时。

比如sget指令,对应到如下解释器解释指令

art/runtime/interpreter/mterp/arm64/op_sget.S

%default { "is_object":"0", "helper":"MterpGet32Static", "extend":"" }
2    /*
3     * General SGET handler wrapper.
4     *
5     * for: sget, sget-object, sget-boolean, sget-byte, sget-char, sget-short
6     */
7    /* op vAA, field//BBBB */
8
9    .extern $helper
10    EXPORT_PC
11    FETCH w0, 1                         // w0<- field ref BBBB
12    ldr   x1, [xFP, #OFF_FP_METHOD]
13    mov   x2, xSELF
14    bl    $helper
15    ldr   x3, [xSELF, #THREAD_EXCEPTION_OFFSET]
16    lsr   w2, wINST, #8                 // w2<- AA
17    $extend
18    PREFETCH_INST 2
19    cbnz  x3, MterpException            // bail out
20.if $is_object
21    SET_VREG_OBJECT w0, w2              // fp[AA]<- w0
22.else
23    SET_VREG w0, w2                     // fp[AA]<- w0
24.endif
25    ADVANCE 2
26    GET_INST_OPCODE ip                  // extract opcode from rINST
27    GOTO_OPCODE ip

这部分是汇编指令,具体指令执行不耗时,肯定是函数耗时。函数调用$helper 对应MterpGet32Static函数。

在对应的函数处加trace

art/runtime/interpreter/mterp/mterp.cc

#include "base/systrace.h"
extern "C" int MterpSet32Static(uint32_t field_idx,
                                int32_t new_value,
                                ArtMethod* referrer,
                                Thread* self)
    REQUIRES_SHARED(Locks::mutator_lock_) {
  return MterpSetStatic<int32_t, Primitive::kPrimInt>(field_idx,
                                                      new_value,
                                                      referrer,
                                                      self,
                                                      &ArtField::SetInt<false>);
}

在对应MterpSetStatic方法加trace.

template <typename return_type, Primitive::Type primitive_type>
ALWAYS_INLINE return_type MterpGetStatic(uint32_t field_idx,
                                         ArtMethod* referrer,
                                         Thread* self,
                                         return_type (ArtField::*func)(ObjPtr<mirror::Object>))
    REQUIRES_SHARED(Locks::mutator_lock_) {
  ScopedTrace trace(__FUNCTION__);
  return_type res = 0;  // On exception, the result will be ignored.
  ArtField* f =
      FindFieldFromCode<StaticPrimitiveRead, false>(field_idx,
                                                    referrer,
                                                    self,
                                                    primitive_type);
  if (LIKELY(f != nullptr)) {
    ObjPtr<mirror::Object> obj = f->GetDeclaringClass();
    res = (f->*func)(obj);
  }
  return res;
}

2.分析问题

MterpGetStatic 就是去获取一个类的静态成员, 为什么会用掉 85 ms ?apk中dex文件会在art中转化为一个DexFile对象,而每一个 DexFile 对象会对应一个 DexCache 对象。DexCache 的作用是用来缓存包含在一个 dex 文件里面的类型 (Type), 方法 (Method), 域 (Field), 字符串 (String) 和静态储存区 (Static Storage) 等信息。

art/runtime/mirror/dex_cache.cc

void DexCache::Init(const DexFile* dex_file,
         ObjPtr<String> location,
         StringDexCacheType* strings,
         uint32_t num_strings,
         TypeDexCacheType* resolved_types,
         uint32_t num_resolved_types,
         MethodDexCacheType* resolved_methods,
         uint32_t num_resolved_methods,
         FieldDexCacheType* resolved_fields,
         uint32_t num_resolved_fields,
         MethodTypeDexCacheType* resolved_method_types,
         uint32_t num_resolved_method_types,
         GcRoot<CallSite>* resolved_call_sites,
         uint32_t num_resolved_call_sites)
   REQUIRES_SHARED(Locks::mutator_lock_);

上面是 DexCache 的初始化函数, num_resolved_fields 表示 DexCache 中缓存 Field 的个数, 来打印一下这个参数

N:

03-21 15:57:56.409 5982 5982 E art : syh DexCache::Init classes.dex num_resolved_fields 56285
03-21 15:57:56.433 5982 5982 E art : syh DexCache::Init classes.dex num_resolved_fields 25449
03-21 15:57:56.437 5982 5982 E art : syh DexCache::Init classes.dex num_resolved_fields 63062
03-21 15:57:56.569 5982 5982 E art : syh DexCache::Init classes.dex num_resolved_fields 7802
03-21 15:57:56.917 5982 6097 E art : syh DexCache::Init classes.dex num_resolved_fields 115
03-21 15:57:58.088 5982 6032 E art : syh DexCache::Init classes.dex num_resolved_fields 16
03-21 15:57:58.993 5982 6121 E art : syh DexCache::Init classes.dex num_resolved_fields 27

O:

03-17 14:31:41.834 5358 5358 E zygote : syh DexCache::Init classes.dex num_resolved_fields 1024
03-17 14:31:41.854 5358 5358 E zygote : syh DexCache::Init classes.dex num_resolved_fields 1024
03-17 14:31:41.860 5358 5358 E zygote : syh DexCache::Init classes.dex num_resolved_fields 1024
03-17 14:31:42.051 5358 5358 E zygote : syh DexCache::Init classes.dex num_resolved_fields 1024
03-17 14:31:42.302 5358 5436 E zygote : syh DexCache::Init classes.dex num_resolved_fields 279
03-17 14:31:42.448 5358 5469 E zygote : syh DexCache::Init classes.dex num_resolved_fields 115
03-17 14:31:42.914 5358 5541 E zygote : syh DexCache::Init classes.dex num_resolved_fields 16
03-17 14:31:44.516 5358 5492 E zygote : syh DexCache::Init classes.dex num_resolved_fields 27

Android O 上, 一个 DexCache 最多缓存 1024 个 Field, 而实际上有上万个 Filed, 导致 MterpGetStatic 的时候 cache 命中率极低, 最终导致 MterpGetStatic 耗时。

3.解决问题

尝试调整cache size与N一致,MterpGetStatic 明显改善, 单一个 inflate 就快了 80 ms, 优化后高德地图的启动时间可以减少 166 ms。

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

推荐阅读更多精彩内容

  • 前言 关于冷启动的优化方法,网上已经有很多的文章了,总结起来,大概有以下几种优化方式: 优化布局,这一步是最简单的...
    事多店阅读 4,976评论 1 11
  • 请保持淡定,分析代码,记住:性能很重要。 启动时间优化 毫无疑问,应用的启动速度越快越好。 本文可以帮助你优化应用...
    Mupceet阅读 11,397评论 5 19
  • 先讲点题外话 简述Activity的几种启动模式 standard标准启动模式,也是Activity的启动模式,以...
    大大大大大先生阅读 6,717评论 0 3
  • 概要 应用运行时的卡顿问题非常影响用户体验,严重降低产品表现力,本文将介绍应用卡顿原因以及分析方法等等。 卡顿问题...
    某昆阅读 2,557评论 1 8
  • part2:重庆市区 “在3D魔幻城市,我上演了自己的魔幻故事。”--啊坨 Day6晚: 较场口夜市-八一好吃街-...
    啊坨阅读 251评论 0 0