性能深度分析之systemtrace(代码片段)

关键词：

前言

App中大多数的性能指标都和时间相关，如启动速度，列表滑动FPS，页面打开耗时等等。为了优化这些指标，我们需要了解时间都消耗在哪里。

通常我们会打开Time Profiler，通过聚合Call Stack来分析和优化代码耗时。偶尔会出现优化后Time Profiler已经没有什么高耗时的Call Stack，但列表滑动仍然掉帧，这时候应该怎么办呢？

不妨试试System Trace~

一个实际例子

用dyld提供的C接口来注册image加载的回调是一种常见做法，第一次注册回调的时候会立刻把当前已经加载的image回调，所以如果回调函数里有耗时操作，我们一般会在子线程注册。

模拟启动的时候注册dyld回调：

接着在真机上运行这段代码，发现在启动页面会卡很久：

为什么这里会卡很久呢？

试试Time Profiler?

就不具体讲解Time Profiler的用法了，相关资料网上很多，通过分析我们可以拿到如下的调用栈：

嗯～？？不对啊，明明耗时好几秒，怎么统计出来的只有堆栈142ms。可以看到Time Profiler提供的信息有限，以下两条算是比较有用的：

1. 区间选中有3.17s，但是统计到的调用栈却只有142ms
2. iPhone 6一共只有两个Core，两个Core在这段时间内，大部分时候都是空闲的。

似乎线程在等待什么？

System Trace

System Trace一个比较大的优势是可以看到线程的状态，分析上面的代码(如下图)，发现主线程有一段3s左右的时间被block住了，通过右侧的调用栈能看到主线程在didFinishLaunching中调用了imageNamed，后者触发了dlopen，dlopen里在等待一个互斥锁。

切换到Events：Thread State，可以看到线程切换的每一个事件，和状态切换的发生的原因，切换后再选中主线程被block的这段时间，观察这个事件的下一个事件，因为下个事件通常是锁被释放，线程重新进入可执行的状态。

我们发现，主线程因为线程0x9e1f释放锁才进入了可执行的状态。这时候把线程0x9e1f也pin一下，观察到主线程被block这段时间，这个线程在不停的sleep 10ms左右然后继续执行代码，通过右侧的调用栈会发现，sleep的源头是在_dyld_register_func_for_add_image，到这里原因找到了：子线程卡住了主线程。

细心的朋友会发现，右侧的调用栈里并没有最上面C函数：add_image_callback，这是因为add_image_callback内部只调用了usleep，这一层调用完全没有存在的必要，所以release模式下编译器做了优化。

小结

通过System Trace分析，我们很容易就找到了这次启动耗时长的原因：主线程的imageNamed内部触发了dlopen，子线程在执行执行_dyld_register_func_for_add_image的回调，二者都需要先获取同一个互斥锁，所以子线程卡住了主线程。

这个例子让我们见识到了System Trace的威力，那么System Trace一般可以用来分析哪些问题呢？

• 锁的互斥，主要是主线程等子线程释放锁
• 线程优先级，抢占和高优线程超过CPU核心数量
• 虚拟内存，Page Fault的代价其实不小
• 系统调用，了解性能瓶系统正在做什么

Tips: Runtime, dyld存在着很多隐藏的全局互斥锁，很容易踩到雷。

Time Profiler的原理

这部分回答一个问题：为什么刚刚的代码里，Time Profiler看不出端倪？

正常Time Profiler会1ms采样一次，默认只采集所有在运行线程的调用栈，最后以统计学的方式汇总。比如下图中的5次采样中，method3都没有采样到，所以最后聚合到的栈里就看不到method3。

Time Profiler中的看到的时间，并不是代码实际执行的时间，而是栈在采样统计中出现的时间。另外，Time Profiler还有一些配置是容易忽略的，依次点击File -> Recording Options：

• High Frequency，降低采样的时间间隔
• Record Kernel Callstacks，记录内核的调用栈
• Record Waiting Thread，记录被block的线程

第三个选项比较有用，比如刚刚的代码开启Record Waiting Thread，再运行Time Profiler就会发现主线程很长一段时间在等待一个互斥锁：

System Trace

用好System Trace的前提是对操作系统的一些核心基础知识有基本的了解，所以这一小节会讲解下System Trace的各个模块的使用方式以及涉及到的基本原理。

Point of Interest

有时候我们只关心某一段小段时间的性能，如何把时间段和System Trace对应起来呢？

可以通过kdebug_signpost相关的接口相关的接口来打一些点，这些点会在Point of Interest区域中显示，比如刚刚的代码我们想标记出来didFinishLaunch这个方法，就可以在方法的收尾添加kdebug_interval：

kdebug_signpost_start(10, 0, 0, 0, 0); 
kdebug_signpost_end(10, 0, 0, 0, 0); 

然后重新运行System Trace，即可在Point of Interest观察到该方法的执行区间

但显示Code 10明显是不友好的，可以在File -> Recording Options里做Code映射，变成可读的字符串。Color Using Last Argument可以把最后一个code映射到不同颜色，进一步提高辨识度。

> Tips： > - kdebug_signpost_start的几个参数是用来做多级区分的，但整型本身不够友好，显示区间可以也可以用`os_signpost`相关的API > - signpost配合Objective C的Swizzling往往会发挥意想不到的效果

Thread State Trace

System Trace一个比较很重要的特性就是能看到线程不同的状态，以及状态之间切换的原因，通常我们会选择一个时间段，然后汇总观察结果：

几个线程状态说明：

• Running，线程在CPU上运行
• Blocked，线程被挂起，原因有很多，比如等待锁，sleep，File Backed Page In等等。
• Runnable，线程处于可执行状态，但此时等CPU有资源的时候，就可以运行
• Interrupted，被打断，通常是因为一些系统事件，一般不需要关注
• Preempted，被抢占，优先级更高的线程进入了Runnable状态

Blocked和Preempted是优化的时候需要比较关注的两个状态，分析的时候通常需要知道切换到这两个状态的原因，这时候要切换到Events: Thread State模式，然后查看状态切换的前一个和后一个事件，往往能找到状态切换的原因。

Tips：在线程上右键，可以快速把线程设置为filter或者pin，方便分析，尤其是大型App的线程非常多的情况下。

除了Thread State Event比较有用，另外一个比较有用的事Narrative，这里会把所有的事件，包括下文的虚拟内存等按照时间轴的方式汇总：

Virtual Memory Trace

内存分为物理内存和虚拟内存，二者按照Page的方式进行映射。

可执行文件，也就是Mach-O本质上是通过mmap相关API映射到虚拟内存中的，这时候只分配了虚拟内存，并没有分配物理内存。如果访问一个虚拟内存地址，而物理内存中不存在的时候，会怎么样呢？会触发一个File Backed Page In，分配物理内存，并把文件中的内容拷贝到物理内存里，如果在操作系统的物理内存里有缓存，则会触发一个Page Cache Hit，后者是比较快的，这也是热启动比冷启动快的原因之一。

这种刚刚读入没有被修改的页都是Clean Page，是可以在多个进程之间共享的。所以像__TEXT段这种只读的段，映射的都是Clearn Page。

_DATA段是可读写的，当_DATA段中的页没有被修改的时候，同样也可以在两个进程共享。但一个进程要写入，就会触发一次Copy On Write，把页复制一份，重新分配物理内存。这样被写入的页称为Dirty Page，无法在进程之间共享。像全局变量这种初始值都是零的，对应的页在读入后会触发一次内存写入零的操作，称作Zero Fill。

iOS不支持内存Swapping out即把内存交换到磁盘，但却支持内存压缩（Compress memory），对应被压缩的内存访问的时候就需要解压缩（Decompress memory），所以在Virtial Memroy Trace里偶尔能看到内存解压缩的耗时。

System Load

以10ms为纬度，统计活跃的高优线程数量和CPU核心数对比，如果高于核心数量会显示成黄色，小于等于核心数量会是绿色。这个工具是用来帮助调试线程的优先级的：

线程的优先级可以通过QoS来指定，比如GCD在创建Queue的时候指定，NSOperationQueue通过属性指定：

//GCD
dispatch_queue_attr_t attr = dispatch_queue_attr_make_with_qos_class(DISPATCH_QUEUE_SERIAL, QOS_CLASS_UTILITY, -1);
dispatch_queue_t queue = dispatch_queue_create("com.custom.utility.queue", attr);
//NSOperationQueue
operationQueue.qualityOfService = NSQualityOfServiceUtility

选择合适的优先级，避免优先级反转，影响线程的执行效率，尤其是别让后台线程抢占主线程的时间。延伸阅读：libdispatch efficiency tips

System Call & Context Switch

操作系统为了安全考虑，把文件读写(open/close/write/read)，锁(ulock_wait/ulock_wake)等核心操作封装到了内核里，用户态必须调用内核提供的接口才能完成对应的操作，这样的调用称作系统调用System Call。System Trace里提供了系统调用相关的Event：

线程/进程需要轮流到CPU上执行，在切换的时候，必须把线程/进程状态保存下来，之后才能恢复，这种保存/恢复的过程称作上下文切换Context Switch，在System Trace里通常会关注下主线程是否在频繁的上下文切换：

Thermal State

一个大家不怎么关注，但其实挺重要的性能指标是发热状态，因为发热后系统会限制CPU/GPU/IO等使用。System Trace也提供了对应的分析工具

iOS 11之后，可以通过NSProcesssInfo的相关API来获取当前发热状态：

NSProcessInfo.processInfo.thermalState

一共有四种状态，正常的状态是Nominal，后面逐级严重：

• Nominal
• Fair
• Serious
• Critical

Xcode也提供了工具来模拟发热状态，让开发者可以测量不同发热情况下App的体验，在Xcode中，依次选择Window -> Device And Simulator，然后按照下图的方式开启：

Tips：非游戏类App一般不会引起发热，除非有一些逻辑上Bug引起死循环，或者不停发送网络请求。

总结

当遇到性能瓶颈的时候，优先还是建议Time Profiler，因为简单直接，排查效率的问题高。如果遇到Time Profiler里采样到的时间和实际消耗的时间差距比较大的时候，或者像优化FPS这种需要精细化的了解16ms线程都在做什么的时候，可以试试System Trace，也许会有意外的收获。

性能分析之趋势分析(代码片段)

...三、如何正确的做？四、总结一、前言这会想聊一下性能分析中的趋势分析。二、遇到问题我看过很多的性能报告，像这样的表格有很多。（下面这个是平均响应时间的表格）然后画了一个TPS的图是这样：系... 查看详情

性能分析之性能建模简述(代码片段)

...模型六、失效模型七、排队模型八、总结一、前言经常在性能领域里听到建模这个词，也看到有些人写了一些文章或PPT描述建模。今天在网上也搜索了一下，看到有五花八门的内容。我也写一下我对性能建模的理解。二... 查看详情

性能分析之sql性能分析（mysql）(代码片段)

在性能分析中，SQL的分析那是必须的。不同的库又有着不同的命令，但是总体来说，同一类型的数据库，除了有一些手段上的不同之外，给出的结果基本上都是类似的。今天说一下MySQL的。每次我都会说，... 查看详情

mysql之性能分析（mysqlreport工具）(代码片段)

...、mysqlreport作用进行MySQL的配置优化，首先必须找出MySQL的性能瓶颈所在；而SHOWSTATUS输出的报告正是用来计算性能瓶颈的参考数据。mysqlreport不像SHOWSTATUS那样简单的罗列数据，而是对这些参考数据加以融合计算，整理成一个个优... 查看详情

（一文了解）linux性能分析之cpu篇(代码片段)

目录前言一、CPU性能指标1、CPU使用率2、负载均衡3、上下文切换4、CPU缓存命中率二、常用工具1、uptime2、vmstat3、mpstat4、top5、sar6、pidstat7、cat/proc/sotfirqs三、分析CPU性能瓶颈方法分析举例四、性能调优1，编译器选项2、进程绑... 查看详情

性能分析之从io高定位到具体文件(代码片段)

...、概述二、核心原理三、一个实验四、总结一、概述IO的性能分析一直是性能分析的重点之一，分析的思路是：在代码的逻辑清晰的情况下，是完全可以知道哪些文件是频繁读写的。但是对性能分析人员来说，通... 查看详情

linux性能分析工具之----dstat(代码片段)

简介Windows下有性能监视器，Linux下当然也不示弱，亲还在用vmstat、iostat、nfsstat、netstat、ifstat...来查看系统性能状态？那你就弱爆了。今天给亲一个神器,只需他一个你就可以得到以上这么多工具综合的功能。闲言表过，步入正题... 查看详情

性能测试之jvm异常说明和分析工具(代码片段)

StackOverflowError和OutOfMemoryError是JVM里的两种Error。每个运行时区域——程序计数器、Java虚拟机栈、本地方法栈、Java堆、方法区、直接内存发生Error的原因和错误信息是不同的。不是所有的StackOverflowError和OutOfMemoryError都需要调整参... 查看详情

性能分析之gdb调试c++应用去分析coredump(代码片段)

文章目录背景说明问题分析背景说明这个内容只是为了做个记录。因为项目中有出现coredump的情况。问题分析先用GDB调起来。[app@主机Abin]$gdbPROGRAMcore.31018下面是一连串的GDB信息。GNUgdb(GDB)RedHatEnterpriseLinux7.6.1-80.el7Copyright(C)2013Fr... 查看详情

性能分析之dubbo性能参数导致单cpu高(代码片段)

文章目录背景问题分析小结背景今天记录一个小问题。问题不大，也没什么分析的逻辑可以讲的。但是想着比较典型，所以就写一写。这一日，一个朋友发来个问题。​一个Java应用,从visualVm这里看，有10个newI/Owork... 查看详情

jvm性能优化对象内存分配之虚拟机参数调优分析(代码片段)

内容简介本文主要针对于综合层面上进行分析JVM优化方案总结和列举调优参数计划。主要包含：调优之逃逸分析（栈上分配）调优之线程局部缓存（TLAB）调优之G1回收器栈上分配与逃逸分析-XX:+DoEscapeAnalysis... 查看详情

性能分析之php应用进程过多导致的pagefaults(代码片段)

文章目录一、前言二、背景信息三、性能问题一1、问题现象2、问题分析3、优化效果四、性能问题二1、问题现象2、问题分析3、优化效果五、总结一、前言前阵子在7DGroup群里讨论了一个系统遇到的性能问题。在此记录一下，... 查看详情

性能分析之排队论应用(代码片段)

文章目录一、前言二、排队模型1、M/M/1/∞/∞/FCFS：单线程单连接，先到先服务2、M/M/C/∞/∞/FCFS：多线程多连接，先到先服务三、排队的计算1、排队计算12、排队计算23、排队计算34、小结四、数据统计分析1、请求... 查看详情

性能分析之cpu高到定位到代码行（java）(代码片段)

...言线程状态转换关系实例分析小结前言通常情况下，性能报告中只说CPU使用率高的时候，并不能帮助定位问题。因为CPU高会有多种不同的情况。CPU有五种状态(ussyidwast),在vmstat中能显示出来，这个想必很多人都清楚。... 查看详情

性能分析之gdb动态修改内存变量值（c/c++)(代码片段)

...0c;之前写了Java的应用的代码动态调试工具。请参见：性能工具之调试工具GDB（你以为性能分析中用不到吗？)并且之前在群里也有说要写关于如何修改内存变量值的。所以这里也就写一下。后 查看详情

性能分析之死锁和日志相关的一个实例(代码片段)

文章目录一、前言二、问题现象三、问题分析四、性能调优五、总结一、前言这个例子在做性能测试的时候出现的。二、问题现象团队在做性能测试，其实量并不大。只是我觉得没有什么明显的结果，于是我就自己把脚... 查看详情

ios之性能优化·uitableview深度优化(代码片段)

一、前言UITableView的优化主要从四个方面入手：提前计算并缓存好高度（布局），因为tableView:heightForRowAtIndexPath:是调用最频繁的方法；滑动时按需加载，防止卡顿。这个在大量图片展示，网络加载的时... 查看详情

性能分析之响应时间拆分及258原则误区(代码片段)

...何分析和定义的问题。问题大概是两种：我们的系统性能差，应该如何分析响应时间呢？响应时间的长短如何定义呢？258原则是否适用？最大值多长算是不可接受呢？不同的系统怎么定最大值呢 查看详情