perfetto 简介

转自:https://cloud.tencent.com/developer/article/1905180

 

1. 抓取页面简介

1.1 Recording settings

录制的设置,主要有三种模式,适合不同的场景。

1.1.1  Stop when full

in-memory buffer size

代表可以存储trace的最大buffer大小。在内存中,不会影响到IO。

Max duration

设置此次 trace 抓取的最大时长。

Stop when full模式下,perfetto停止工作受Max duration和buffer size影响,一旦满足其中一个条件,perfetto将会停止。 优点:trace不会因为overwrite而导致丢失。 缺点:如果trace太多,会导致提前结束,无法录制到出现问题时候的trace。 一般10s,64mb也就够用了。

1.1.2 Ring buffer 

可以看到选项和2.1 Stop when full一样,意思也是一样。Ring buffer模式只会收到Max duration的影响,时间到了就停止抓取trace,但是trace会有被overwrite的风险。

 

1.1.3 Long trace

用于长时间地抓取trace,但是由于需要定时将buffer中的trace写到文件里面去,会有IO的影响。前面两个选项和前两个模式的意思是一样的。

Flush on disk every

间隔多少时间将buffer中的trace写入到文件中。这个数值不能太大也不能太小。太大了,容易丢trace,太小了容易影响IO。

Long trace主要是受Max duration,或者ctrl + c暂停命令。

 

1.2. CPU

CPU选项是经常使用的,基本上除了syscalls不打开,前面三个都会常规打开

1.2.1 Coarse CPU usage countor

粗粒度的CPU使用统计

1.2.2 Scheduling details

可以看到每个CPU上运行的task。

1.2.3 CPU frequency and idle states

可以看到每颗CPU的运行频率以及是否空闲

1.2.4 Syscalls

需要userdebug版本系统,可以记录每一个系统调用,但是对性能影响比较大

 

1.3. GPU

可以记录 GPU 主频以及GPU 内存使用

1.3.1 GPU Frequency

可以看到GPU频率

1.3.2 GPU Memory

可以看到GPU内存使用量以及各个进程的占用,仅Android 12+以上使用。

 

1.4 Power

1.5 Memory

 

1.6 Android apps & svcs

1.6.1 Atrace userspace anotations

开启这个选项之后,选择合适的atrace tag就可以开启对应的trace了,这个tag就对应了System Tracing的界面的catergray。

1.6.2 Event log (logcat)

可以实时记录log,然后将log和trace信息一一对应。 非常有利于分析问题。选择合适的log类型,就可以记录log了。

生成的perfetto文件,滑动下方的android log,可以看到有一根竖线,对应到trace的tag,日志和trace tag的一一对应

 

1.6.3 Frame timeline

这个是Android 12(S)的新功能,具体如何使用可以参考这个网址的官方视频

https://www.youtube.com/playlist?list=PLWz5rJ2EKKc-xjSI-rWn9SViXivBhQUnp

可以看到SF某一帧是合成的APP的哪一帧,已经合成的状态,具体作用,大家可以参考上面的链接视频。

 

1.7 Chrome

这个选项,主要是分析webview相关的性能问题,如果遇到需要分析webview相关的性能问题,可以尝试开启这些功能。

1.8 Advanced settings

目前就一个功能,开启ftrace,对于需要分析内核性能问题,可以开启这个,选择对应的tag。或者可以自己增加。

 

1.9 开启 APP 的 Atrace

atrace_apps: "*"

 

1.10 总结配置:

adb shell perfetto \
  -c - --txt \
  -o /data/misc/perfetto-traces/trace \
<<EOF

buffers: {
    size_kb: 63488
    fill_policy: DISCARD
}
buffers: {
    size_kb: 2048
    fill_policy: DISCARD
}
data_sources: {
    config {
        name: "android.gpu.memory"
    }
}
data_sources: {
    config {
        name: "linux.process_stats"
        target_buffer: 1
        process_stats_config {
            scan_all_processes_on_start: true
        }
    }
}
data_sources: {
    config {
        name: "android.log"
        android_log_config {
            log_ids: LID_EVENTS
            log_ids: LID_CRASH
            log_ids: LID_KERNEL
            log_ids: LID_DEFAULT
            log_ids: LID_RADIO
            log_ids: LID_SECURITY
            log_ids: LID_STATS
            log_ids: LID_SYSTEM
        }
    }
}
data_sources: {
    config {
        name: "android.surfaceflinger.frametimeline"
    }
}
data_sources: {
    config {
        name: "linux.sys_stats"
        sys_stats_config {
            stat_period_ms: 1000
            stat_counters: STAT_CPU_TIMES
            stat_counters: STAT_FORK_COUNT
        }
    }
}
data_sources: {
    config {
        name: "linux.ftrace"
        ftrace_config {
            ftrace_events: "sched/sched_switch"
            ftrace_events: "power/suspend_resume"
            ftrace_events: "sched/sched_wakeup"
            ftrace_events: "sched/sched_wakeup_new"
            ftrace_events: "sched/sched_waking"
            ftrace_events: "power/cpu_frequency"
            ftrace_events: "power/cpu_idle"
            ftrace_events: "power/gpu_frequency"
            ftrace_events: "gpu_mem/gpu_mem_total"
            ftrace_events: "sched/sched_process_exit"
            ftrace_events: "sched/sched_process_free"
            ftrace_events: "task/task_newtask"
            ftrace_events: "task/task_rename"
            ftrace_events: "ftrace/print"
            atrace_categories: "am"
            atrace_categories: "adb"
            atrace_categories: "aidl"
            atrace_categories: "dalvik"
            atrace_categories: "audio"
            atrace_categories: "binder_lock"
            atrace_categories: "binder_driver"
            atrace_categories: "bionic"
            atrace_categories: "camera"
            atrace_categories: "database"
            atrace_categories: "gfx"
            atrace_categories: "hal"
            atrace_categories: "input"
            atrace_categories: "network"
            atrace_categories: "nnapi"
            atrace_categories: "pm"
            atrace_categories: "power"
            atrace_categories: "rs"
            atrace_categories: "res"
            atrace_categories: "rro"
            atrace_categories: "sm"
            atrace_categories: "ss"
            atrace_categories: "vibrator"
            atrace_categories: "video"
            atrace_categories: "view"
            atrace_categories: "webview"
            atrace_categories: "wm"
            atrace_apps: "*"
        }
    }
}
duration_ms: 10000

EOF

 

2 trace 过大加载问题

当trace文件大于1G时,Open trace file会出现oops 内存溢出无法访问。

此时需要使用trace_processor来辅助

# 下载官方trace_processor
curl -LO https://get.perfetto.dev/trace_processor
chmod +x ./trace_processor

运行如下命令来加载perfetto trace文件:

./trace_processor --full-sort -D xxx.pftrace

Windows下也可以运行如下命令(不稳定,内存耗用大):

python3 trace_processor --full-sort -D xxx.pftrace

Chrome浏览器打开 https://ui.perfetto.dev/#!/ ,会自动检测本地是否已经有trace_processor生成的HTTP SERVER(9001端口),如下图提示,请选择

“YES, use loaded trace”,将自动解析 trace_processor已经加载的pftrace文件。

3 常规分析

3.1 图例指标

3.1.1 slice (片段,选中片段后会显示黑色边框)

对应代码中 Trace.beginSection/ATRACE_BEGIN 记录的事件

3.1.2 counter (计数器,离散的数值点)

代码中Trace.traceCounter/ATRACE_INT记录的事件

3.1.3 sched/freq (CPU调度、频率)

 

3.1.4 thread_state (线程状态)

点击片段上方线程调度信息片段(Running),可以看到线程当前运行在哪个CPU上

点击箭头 ,可以在CPU调度中看到该运行片段以及调度时延信息。

被P:tv.danmaku.bili 32363的 T(Thread):RenderThread 32522线程唤醒,从就绪到运行延迟了26us,再次点击箭头,可以回到原片段,这个跳转比systrace更加灵活方便。同样的,Binder调用也可以如此在目标和原调用线程跳转来分析查看。

3.2 添加标记

点击最上方的时间轨道即可添加时间点标记;通过按住鼠标左键选中一块区域或者点击某一片段,然后按下“shift+m”即可添加常驻区域标记。选中已经添加的标记,底部出现的Current Selection TAB里可以为其添加标记名,更改其颜色,以及执行移除操作。

按下“m”添加的是临时区域标记,再次选中另外一块区域添加临时区域时,上一个临时区域会自动移除。

 

3.3 锁竞争(lock contention)

看到lock contention 片段,可以点击上边的monitor contention来查看当前对象锁竞争发生的调用栈,如下详情中显示当前对象锁被Owner (Binder:1754_16)持有,其持锁当前运行在serviceDoneExecuting (AMS.java 16426行),且当前等待该对象锁的线程已经有2个了;当前线程执行被阻塞在getUidState方法中(AMS.java 6614行)。

 

4 SQL查询以及展示

在已经加载trace的perfetto UI界面, Search框中输入 : ,即可开启SQL输入,我们就可以使用SQL来查询并定位具体的trace片段(slice)。

输入SQL语句,Enter,得到查询结果,显示在底部表格中,点击表格中的每一行,可以跳转到具体的slice中,根据trace上下文可以进一步分析问题。

如果仅需要执行SQL查询数据,也可以点击UI界面左侧导航栏中的Query (SQL),输入SQL语句,按CTRL + ENTER执行SQL查询。

[ 此处列出几个常用的Table/View的格式及关键字段信息 ]

slice表,横向track上的一条条小片段

ts:片段起始时间戳(单位ns)

dur:片段持续时长(ns)

track_id属于哪个track(水平timeline)

name: 片段标注的名称,对应Trace中打印的方法名、标记等信息

thread_track表,utid标识线程tid,并不是真实的线程tid

thread表,表示各线程信息,其中utid和thread_track表的utid关联

process表,upid和thread表的upid关联,表示线程所属的父进程

sched_slice,线程调度片段

thread_state,各track上边的线程调度片段,标识线程运行状态

 

列举几个常用的SQL查询:

1、列出所有doFrame片段,按耗时倒序排列,取前100条

select slice_id,track_id,ts,dur,dur/1e6,name from slice WHERE name like '%doFrame%' order by dur desc limit 100

2、在1 查询的基础上,指定process name为systemui,即systemui自身的绘帧信息

select slice_id,track_id,ts,dur,dur/1e6,slice.name from slice JOIN thread_track ON slice.track_id = thread_track.id JOIN thread USING(utid) JOIN process USING(upid) WHERE process.name = 'com.android.systemui' and slice.name like '%doFrame%' order by dur desc limit 100

3、system_server中各OPF:关键字片段的耗时信息,包含各片段的真实running_time(每个slice可能有一段时间running,一段时间sleep,一段时间runnable,需要借助thread_state表来查询slice中各调度时间片的状态)

select slice_id,track_id,thread.utid,slice.ts,slice.dur,(slice.dur/1e6) as dur_ms, (select total(case when thread_state.ts < slice.ts then MIN(slice.ts+slice.dur,thread_state.ts+thread_state.dur)-slice.ts when (thread_state.ts+thread_state.dur) > (slice.ts+slice.dur) then (slice.ts+slice.dur-MAX(thread_state.ts,slice.ts)) else thread_state.dur end) from thread_state where thread_state.utid=thread.utid and thread_state.state='Running' and thread_state.ts < (slice.ts+slice.dur) and (thread_state.ts+thread_state.dur) > slice.ts)/1e6 as total_running,slice.name from slice JOIN thread_track ON slice.track_id = thread_track.id JOIN thread USING(utid) JOIN process USING(upid) WHERE process.name='system_server' and slice.name like 'OPF:%' order by slice.dur desc limit 400

4、system_server中的锁竞争情况(lockcontention),lock_depth表示当时参与此对象锁竞争的线程个数

select count(1) as lock_depth, s.slice_id,s.track_id,s.ts,s.dur,s.dur/1e6 as dur_ms,ctn.otid,s.name

from slice s, (select slice_id,track_id,ts,dur,name,substr(name, 46, instr(name,')')-46) as otid 

from slice t

WHERE name like 'Lock contention on a monitor lock %'

order by dur) ctn

JOIN thread_track ON s.track_id=thread_track.id JOIN thread USING(utid) JOIN process USING(upid)

WHERE

    process.name = 'system_server'

and s.name like 'Lock contention on a monitor lock %'

    and substr(s.name, 46, instr(s.name,')')-46) = ctn.otid

    and ctn.slice_id <> s.slice_id

    and ctn.ts >= s.ts and (ctn.ts+ctn.dur) <= (s.ts+s.dur)

group by s.slice_id

order by s.dur desc

posted @ 2023-01-17 00:29  魄魄熊  阅读(2185)  评论(0编辑  收藏  举报