可观测可回溯 | Continuous Profiling 实践解析
概述
Cloud Native
Continuous Profiling 在软件开发生命周期的位置
CI/CD 的概念非本文重点,不解释了。从上图可以看出。Continuous Profiling(持续性能分析,下文简称为 CP)是生产向开发进行反馈的非常重要的手段。
发展历史
CP 概念的起源于 Google 的论文 [ 1] :
Google Wide Profiling:A continuous Profiling infrastucture for data centers
基本思路
CP 意义可以分解为两个:
-
性能分析(Profile)的意义:识别计算,存储,网络上的性能瓶颈问题,建立代码和性能瓶颈的关联性,从而协助开发者优化代码,解决瓶颈问题;
-
持续(Continuous)的意义:让性能分析贯穿应用的整个生命周期,从而解决非持续方案(如 ]on-demand)中无法抓到现场的问题。
-
Profiling 的基本思想
衡量程序性能最直观的方法就是通过响应时间(Response Time,简称 RT)。但仅仅知道程序的运行时间很难指导我们如何把程序优化地更快,我们想要更进一步地了解这段时间之内到底发生了什么。
让我们先从一个例子开始,了解 Linux 下的时间统计告诉了用户什么信息:
下面我们利用 Linux time 计算两件事情的时间消耗:
-
生成一个 10M 的文件,随机生成数据;(IO 密集)
-
对上一步生成的文件做个 CRC 计算;(CPU 密集)
time 的输出告诉用户 3 个信息:
-
real:总消耗时间
-
user:用户态消耗时间
-
sys:内核态消耗时
观察 time 的输出,可以看出 user + sys 不等于 real,这是因为程序并不是总是 CPU 上运行的,还可能因为 IO,Lock 等等原因处于睡眠,等待的状态,这段时间既不算在 user CPU time 也不算在 system CPU time。
-
程序在 CPU 上执行的时间(即 user CPU time + system CPU time)称为 CPU time(或 on-CPU time);
-
程序处于睡眠等状态的时间称为 off-CPU time(or blocked time);
-
程序实际运行的时间称为 wall clock time(挂钟时间);
time 的输出 real 对应的概念的是 wall clock time,因此可以看到:
-
对于 IO 密集型的 workload(负载),off-CPU time 是不能忽略的;
-
对于 CPU 密集型 workload(负载),on-CPU time 基本和 wall clock time 相等;
对于一个给定的线程(Linux 上称为轻量级进程):wall clock time = CPU time + off CPU time
因此 Profile 整体分为:
-
On-CPU : where threads are spending time running on-CPU.
-
Off-CPU : where time is spent waiting while blocked on I/O, locks, timers, paging/swapping, etc.
可以看到 Off-CPU 分析类型是一系统结果的汇总统计,因此也可以将 Off-CPU 因为引起睡眠或者等待的原因不同,可以进一步划分为 file profiling,socket profiling,lock profiling 等等类型。
-
Continuous 的基本思想
持续(Continuous)相对的概念是按需(On-Demand)。
按需(或者触发式)比较常见的问题就是无法精准的抓取现场从而导致一些偶发(难以复现)的问题无法被识别。
比如上图这样一条曲线(不管它表达什么),反正是有一段异常(或者说和大部分情况不一样的情形),随着自然时间的流逝;用户发现这个异常的时候,曲线已经恢复了,因此无法在去回溯现场。这种情况下,我们发现了一段异常,但是没有更多细节,开发者就无法知道代码内部发生了什么,因此也无从谈起修复和改善代码了。
持续则意味着贯穿整个程序的完整生命周期,不会漏掉任何一个历史上产生过的异常。
Continuous+Profiling 带给开发者的意义是:在生产环节,永远知道代码的所有执行细节。
理解 profiling
-
用户交互和可视化
性能分析的展现形式通常以 Flame Graph 火焰图来表达:
-
理解火焰图
对火焰图理解的本质是了解性能分析数据(profiling data)究竟是什么。
性能分析数据(profiling data)就是堆栈统计数据。为了帮助读者理解,举个简单的例子:
横坐标表达的一个数值,在不同的场景下,可以赋予不同的含义,比如:
-
在 cpu profiling 上,表达花费时间多少;
-
在 alloc profling 上,表达成内存大小;
-
......
纵坐标是表达是一个 stack trace。
因此上图表达的含义和下面一组数据是一致的。每一行以空格分割,左边的是 stack trace,右边是数值。
a();b();c() 1
a();b();d() 2
c();b() 3
到这里,读者应该对性能分析(profiling)的工作原理有个感性的认识,性能分析的整体流程如图:
因此实现 profiling 的关键点:
-
获取堆栈数据(爬栈):如何护获取问题点(瓶颈)点的堆栈数据;
-
生成火焰图;
-
常见的 Profiling Tools(生成堆栈数据)
常见的工具如 Linux perf,eBPF profile,DTrace,SystemTap 等等,本文将这类用于获取堆栈数据工具统称为 Profiling Tools;Linux 这类工具的用法本文不多介绍,这类工具非常通用并且有效,但对于非C系开发者是没那么友好的。高级语言绝大部分应用开发者其实并不关心很低层次的内容,比如 page fault,numa banlance,context switch,L3 Cache miss 等问题,通常都不在应用开发者的知识图谱中。这部分内容的优化也不再本文的目标读者范围,因此不多叙述。
对于 Profile Tools,我们可以将其分为两类:
-
System Profile:which shows system code paths (eg, JVM GC, syscalls, TCP), but not Java methods.
-
language Profile:These show language methods(eg java method), but usually not system code paths.
-
JVM Profile
-
golang Profile
-
....
不难理解,Profiling Tools 能够爬栈就是因为在特定的代码里进行的 Hook 操作,这类操作一定会产生额外的开销。因此 Profiling Tools 会带来额外的开销(Overhead),不同类型的 Profiling 的 Hook 点不同,因此不同的性能分析类型会导致不同的 Overhead。 很长一段时间,无法将 Profiling 带入生产环节最重要的阻塞点就是 Overhead 太高导致应用的业务逻辑受损严重。 因此评价 Profiling Tools 是否适合上生产最重要的评估就是估算 Overhead。
JVM Profiling
上文提到的工具基本属于 System Profiling Tools 提供的能力,这部分工具的核心能力关注的是 system code paths;对于高级语言上一些特性,能力是不够强的。
下面我们了解高级语言自身的 Profiling Tools 是如何帮助开发者来做性能优化的。
-
golang 内置 pprof [ 2]
-
java11 内置 JFR [ 3]
-
其他高级语言有的有自身的工具,有的没有高级语言没有自身工具,这类通常可以借助 System Profiling Tools(如 perf 或者 ebpf)来实现性能分析。
以 java 为例子,认识下 java 程序运行的代码结构 ,如下图:
对于 java 开发者而言,大部分场景是不考虑 JVM code,glibc code,kernel code 出问题的可能性的,这部分代码相对稳定,而且有稳定的组织去推动解决。因此 JVM Profiling 要表达的核心其实是:爬堆栈,只爬 Java code 这一层次(java stack),这个是大部分应用开发者关注的核心部分,对于下面的部分(native stack)则不在 java 开发者关心的范围。
JVM 还有一个特征,就是把 Linux 底层的概念屏蔽,替换成自己的概念体系,比如:
-
java 开发者更关心 java 线程状态机而不是 JVM 进程的进程状态机;
-
java 开发者更关心 java heap,stack,nio 等内存统计而不是 native heap,native stack 以及 rss,pagecache 的统计;
-
java 开发者关心 CMS 或 G1 垃圾回收情况而不是 Page Reclaim;
-
java 开发者更关心 synchronized,JUC 锁,而不是 OS 锁;
因此,JVM Profiling中的性能分析类型会更贴近 java 开发者的概念体系,而不是 system profile 关心的内容。
举个例子,相较于 on-cpu profiling,作为 java 开发者,你是否会关心 JVM code 或者 glibc 是否存在问题,也许会,但是不可否认,这是非常少见的场景,更多关心的还是 Java code 这一层的问题,因此 JVM Profiling 的 cpu profiling 表达的是 on-cpu profiling for java code。
同理对于内存申请速率 alloc profiling:
-
system alloc profiling 关心的是用户态内存分配器(malloc 分配器或者其他的)的分配速度;
-
JVM alloc profiling 关心的则是 TLAB 分配器的分配速度;
JVM Profiling 和 System profiling 关注点是有不同的:JVM Profiling 关注的是 JVM 上的性能,而不是贯穿从用户态到内核态的整个流程,这是非常重要的一个区别,其他高级语言也是类似的情况。
-
JVM Profiling Tools
JAVA 社区有非常丰富的 JVM Profiling Tools:
-
Async-profiler [ 4] :
-
jetbrains IntelliJ IDEA [ 5]
-
alibaba Arthas
-
JProfiler
-
Honest profiler [ 6]
-
Uber JVM Profiler [ 7]
-
Fight Recorder [ 8]
-
JEP 349: JFR Event Streaming [ 9]
1. JFR
JFR (Java Flight Recorder)是深度嵌入在 JVM 中的功能强大的应用问题诊断与性能剖析工具,在其低开销的加持下,JFR 可在生产环境持续开启。JFR 最开始是 JRockit 和 Oracle JDK 中的商业化特性,Oracle 在 Java 11 对其进行了开源。2019 年阿里巴巴作为主要贡献者,联合 Azul、Datadog、RedHat 等公司,一起将 JFR 移植进 OpenJDK 8 中。目前 Alibaba Dragonwell 8 和 11 中也包含完整的 JFR 功能。
JFR 的事件包括下面几类信息:
-
一般信息:关于虚拟机、操作系统和记录的一般信息;
-
内存:关于内存管理和垃圾收集的信息;
-
代码:关于方法、异常错误、编译和类加载的信息;
-
线程:关于应用程序和线程和锁的信息;
-
I/O:关于文件和套接字输入、输出的信息;
-
系统:关于正在运行 Java 虚拟机的系统、进程和环境变量的信息;
-
类型:关于记录中的事件类型的信息。
通过 JFR 的 Event,可以覆盖几乎所有需要进行性能分析的场景:
-
on cpu profiling
-
alloc profiling
-
lock profiling
-
file read(write) profiling
-
socket read(write) profiling
-
......
JFR 非常优秀,但是在国内环境,依然存在适配问题:
java 迭代速度太快了,java 已经发布了 17 了,但是国内不乏依旧跑在 java8 上的应用;而 JFR 从 11backport 到的最低版本是 8u272(8u262 只是有 JFR 的代码,但是不可用),这就导致了 8u272 之前的 java 没办法用 JFR;
JFR 本身也在发展迭代中,如 jdk.ObjectAllocationInNewTLAB。
jdk.ObjectAllocationOutsideTLAB 在 java16 之前的实现产生的 overhead 过高导致根本不适合在生产环境常态化采集;
Arms Continuous JVM Profiler
Cloud Native
为了更好的为用户提供价值,Arms 联合 Alibaba Dragonwell 团队,基于业界主流设计,进行了深度优化,设计出了全新的采集、分析技术方案。其中采集方案兼顾性能和财务成本,优先使用更成熟和完善的 JFR,但在JFR是商业化特性的 OracleJDK 或 Async-Profiler 性能更优的情况下,采用 Async-Profiler 作为替代方案,并且是全自动的,用户无需关注配置细节。
Support list
-
OpenJDK
-
jdk8u272 以下的版本选择 Async-Profilier 和核心原因是没有 JFR 可用; -
jdk8u272 之后直到 jdk16 之前,JFR 实现的 alloc 相关事件的开销比较大,因此选择 Async-Profilier; -
其他情况,能用 JFR 都用 JFR -
Oracle JDK
-
OracleJDK8 上 JFR 是商业特性,因此选择 Async-Profilier -
OracleJDK11 之后的版本的 JFR 是开源特性,alloc 选择 Async-Profilier 的原因一样是因为 JFR 实现的 alloc 相关事件的开销比较大,因此选择 Async-Profilier -
其他情况,能用 JFR 都用 JFR。
性能分析类型
-
CPU Time:全称 On-CPU Profiling In Java Code,统计 java 代码占用 CPU 时间; -
Allocations:统计 TLAB 分配次数 -
Allocated Memory:统计 TLAB 分配内存总量,单位 bytes;
产品的 roadmap 中后续会考虑搞 lock,file,socket 等等性能分析的能力,这中间的主要核心考量是每一种实现对应的 overhead 评估和实现约束情况。
OverHead
前文说过评价一款 Profiling Tools 是否适合上生产主要是看额外开销是否足够小,Arms 提供的能力整体依赖于 Async-profiler 以及 JFR,这两个工具的开销是关键:
-
Async-profiler:官方未给出数据性结论,只是说开销很低;
-
JFR:按照缺省配置,整体性能下降低于 2% 。 [ 10]
-
压力测试模型
压力测试模型如下图示:
-
压力测试客户端
JFR Alloc 依赖的两个 JFR Event 有非常严重的性能问题:
1. jdk.ObjectAllocationInNewTLAB
2. jdk.ObjectAllocationOutsideTLAB
因此本测试不包含 JFR Alloc;JFR 的这个问题直到 JAVA15 以后才得到解决。
最佳实践路径
-
CPU 高排 查路径
直接定位到方法,并且把每个方法的耗时统计出来,如上图左边所示的热点方法。过滤掉线程等相关条件(当 CPU 瓶颈是因为用户代码导致的,开发者是不需要特别关心线程的,直接将所有线程中的 stack trace 全部进行统计汇总,然后按照每个方法的 Response time 进行汇总)。
-
频繁 GC
第一步,开启压力程序,同时设定 heap 大小为 128M(-Xms128m-Xmx128m)
第二步,压力程序的 gc 日志部分如下图,非常频繁的进行 gc 操作;
85.013: [GC (Allocation Failure) [PSYoungGen: 29518K->3328K(36352K)] 47116K->21252K(123904K), 0.0065644 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
89.993: [GC (Allocation Failure) [PSYoungGen: 31736K->3328K(35840K)] 49660K->21260K(123392K), 0.0061679 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
94.062: [GC (Allocation Failure) [PSYoungGen: 31608K->3232K(36864K)] 49540K->21196K(124416K), 0.0070968 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
99.090: [GC (Allocation Failure) [PSYoungGen: 32934K->1344K(36864K)] 50898K->19332K(124416K), 0.0051987 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
103.114: [GC (Allocation Failure) [PSYoungGen: 29079K->2368K(37376K)] 47067K->20432K(124928K), 0.0056821 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
108.134: [GC (Allocation Failure) [PSYoungGen: 32528K->1344K(36864K)] 50592K->19464K(124416K), 0.0067361 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
113.086: [GC (Allocation Failure) [PSYoungGen: 31748K->3264K(37376K)] 49869K->21503K(124928K), 0.0059270 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
117.178: [GC (Allocation Failure) [PSYoungGen: 31709K->3328K(37376K)] 49948K->21591K(124928K), 0.0049904 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
121.192: [GC (Allocation Failure) [PSYoungGen: 32615K->3607K(37376K)] 50878K->21878K(124928K), 0.0076185 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
126.217: [GC (Allocation Failure) [PSYoungGen: 33278K->1312K(37376K)] 51549K->19615K(124928K), 0.0045188 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
131.159: [GC (Allocation Failure) [PSYoungGen: 32080K->3488K(37376K)] 50383K->21799K(124928K), 0.0046074 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
135.256: [GC (Allocation Failure) [PSYoungGen: 33274K->3488K(37376K)] 51585K->21807K(124928K), 0.0044789 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
140.276: [GC (Allocation Failure) [PSYoungGen: 33871K->1472K(37888K)] 52190K->19799K(125440K), 0.0043370 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
145.296: [GC (Allocation Failure) [PSYoungGen: 32925K->1472K(37888K)] 51252K->19799K(125440K), 0.0044817 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
150.321: [GC (Allocation Failure) [PSYoungGen: 32944K->1440K(37888K)] 51271K->19767K(125440K), 0.0041987 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
155.345: [GC (Allocation Failure) [PSYoungGen: 32896K->1472K(37888K)] 51223K->19799K(125440K), 0.0045417 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
160.374: [GC (Allocation Failure) [PSYoungGen: 33168K->1568K(37888K)] 51495K->19903K(125440K), 0.0051167 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
165.261: [GC (Allocation Failure) [PSYoungGen: 33469K->3616K(37888K)] 51804K->21959K(125440K), 0.0048307 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
170.286: [GC (Allocation Failure) [PSYoungGen: 35284K->3552K(37888K)] 53627K->21895K(125440K), 0.0143238 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
175.316: [GC (Allocation Failure) [PSYoungGen: 35008K->3584K(37888K)] 53351K->21927K(125440K), 0.0060600 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
180.338: [GC (Allocation Failure) [PSYoungGen: 35061K->3584K(37888K)] 53404K->21935K(125440K), 0.0044581 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
185.359: [GC (Allocation Failure) [PSYoungGen: 35044K->3584K(35840K)] 53395K->21935K(123392K), 0.0054453 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
190.384: [GC (Allocation Failure) [PSYoungGen: 35314K->3584K(37376K)] 53665K->21943K(124928K), 0.0050957 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
194.502: [GC (Allocation Failure) [PSYoungGen: 33085K->3584K(37376K)] 51444K->22007K(124928K), 0.0045832 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
199.526: [GC (Allocation Failure) [PSYoungGen: 33952K->1600K(37888K)] 52375K->20039K(125440K), 0.0051886 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Roadmap
1. 诊断类型增强;(file io,socket io,lock 等等)
2. 聚合能力增强;(merge 和 diff)
3. 查询能力增强;(预处理能力,支持长时间聚合)
4. 火焰图交互增强(StackFrame 表达更多含义,当前仅仅包含一个简单字符串);
5. RPC tracing 和 profiling 联动;
6. 多语言(其他高级语言适配);
参考链接
[1] Google 论文:
http://storage.googleapis.com/pub-tools-public-publication-data/pdf/36575.pdf
[2] golang内置pprof :
http://go.dev/blog/pprof
[3] java11内置JFR:
http://docs.oracle.com/en/java/java-components/jdk-mission-control/8/user-guide/using-jdk-flight-recorde r.html#GUID-D38849B6-61C7-4ED6-A395-EA4BC32A9FD6
[4] Async-profiler :
http://github.com/jvm-profiling-tools/async-profiler
[5] jetbrains IntelliJ IDEA :
http://www.jetbrains.com/help/idea/async-profiler.html
[6] Honest profiler :
http://github.com/jvm-profiling-tools/honest-profiler/
[7] Uber JVM Profiler
http://github.com/uber-common/jvm-profiler
[8] Fight Recorder
http://docs.oracle.com/en/java/java-components/jdk-mission-control/8/user-guide/using-jdk-flight-recorder.html#GUID-D38849B6-61C7-4ED6-A395-EA4BC32A9FD6
[9] JEP 349: JFR Event Streaming
http://openjdk.org/jeps/349
[10] JFR Overhead
http://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/performissues001.html
- OpenKruise v1.3:新增自定义 Pod Probe 探针能力与大规模集群性能显著提升
- Koordinator v0.7: 为任务调度领域注入新活力
- 传统大型国企云原生转型,如何解决弹性、运维和团队协同等问题
- Dubbo 3 易用性升级之 Dubbo 官网大改版
- 阿里云容器服务 ACK 产品技术动态(202208)
- RocketMQ Streams在云安全及 IoT 场景下的大规模最佳实践
- RocketMQ 5.0:无状态代理模式的探索与实践
- Apache RocketMQ 5.0 在Stream场景的存储增强
- 快手 RocketMQ 高性能实践
- RocketMQ DLedger架构在小米的大规模实践
- 定时任务报警通知解决方案详解
- Dubbo Mesh 总体技术架构方案
- 说说 Spring 定时任务如何大规模企业级运用
- 龙湖千丁基于 [email protected] 的云原生智慧停车系统架构实践
- 基于 RocketMQ 的 MQTT 服务架构在小米的实践
- 开发者测评:相比 Harbor,我选择 ACR 的三点原因
- 5 分钟完成 ZooKeeper 数据迁移
- Fluid 助力阿里云 Serverless 容器极致提速
- 迁移 Nacos 和 ZooKeeper,有了新工具
- Dubbo 3.1.0 正式发布,数据面原生接入 Service Mesh