可观测可回溯 | Continuous Profiling 实践解析

标签：Profiling 0.01 0.00 Continuous secs user 回溯 JFR CPU

作者：虚镜

概述

Continuous Profiling 在软件开发生命周期的位置

可观测可回溯 | Continuous Profiling 实践解析_java

CI/CD 的概念非本文重点，不解释了。从上图可以看出。Continuous Profiling（持续性能分析，下文简称为 CP）是生产向开发进行反馈的非常重要的手段。

发展历史

CP 概念的起源于 Google 的论文^[^1]：

Google Wide Profiling：A continuous Profiling infrastucture for data centers

可观测可回溯 | Continuous Profiling 实践解析_java_02

基本思路

CP 意义可以分解为两个：

性能分析(Profile)的意义：识别计算，存储，网络上的性能瓶颈问题，建立代码和性能瓶颈的关联性，从而协助开发者优化代码，解决瓶颈问题；

持续(Continuous)的意义：让性能分析贯穿应用的整个生命周期，从而解决非持续方案(如 ]on-demand)中无法抓到现场的问题。

Profiling 的基本思想

衡量程序性能最直观的方法就是通过响应时间（Response Time，简称 RT）。但仅仅知道程序的运行时间很难指导我们如何把程序优化地更快，我们想要更进一步地了解这段时间之内到底发生了什么。

让我们先从一个例子开始，了解 Linux 下的时间统计告诉了用户什么信息：

下面我们利用 Linux time 计算两件事情的时间消耗：

生成一个 10M 的文件，随机生成数据；（IO 密集）
对上一步生成的文件做个 CRC 计算；（CPU 密集）

可观测可回溯 | Continuous Profiling 实践解析_开发者_03

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

可观测可回溯 | Continuous Profiling 实践解析_开发者_04

因此 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.

可观测可回溯 | Continuous Profiling 实践解析_开发者_05

可以看到 Off-CPU 分析类型是一系统结果的汇总统计，因此也可以将 Off-CPU 因为引起睡眠或者等待的原因不同，可以进一步划分为 file profiling，socket profiling，lock profiling 等等类型。

Continuous 的基本思想

持续（Continuous）相对的概念是按需（On-Demand）。

按需（或者触发式）比较常见的问题就是无法精准的抓取现场从而导致一些偶发（难以复现）的问题无法被识别。

可观测可回溯 | Continuous Profiling 实践解析_性能分析_06

比如上图这样一条曲线（不管它表达什么），反正是有一段异常（或者说和大部分情况不一样的情形），随着自然时间的流逝；用户发现这个异常的时候，曲线已经恢复了，因此无法在去回溯现场。这种情况下，我们发现了一段异常，但是没有更多细节，开发者就无法知道代码内部发生了什么，因此也无从谈起修复和改善代码了。

持续则意味着贯穿整个程序的完整生命周期，不会漏掉任何一个历史上产生过的异常。

Continuous+Profiling 带给开发者的意义是：在生产环节，永远知道代码的所有执行细节。

理解 profiling

用户交互和可视化

性能分析的展现形式通常以 Flame Graph 火焰图来表达：

可观测可回溯 | Continuous Profiling 实践解析_开发者_07

理解火焰图

对火焰图理解的本质是了解性能分析数据(profiling data)究竟是什么。

性能分析数据(profiling data)就是堆栈统计数据。为了帮助读者理解，举个简单的例子：

可观测可回溯 | Continuous Profiling 实践解析_java_08

横坐标表达的一个数值，在不同的场景下，可以赋予不同的含义，比如：

在 cpu profiling 上，表达花费时间多少；
在 alloc profling 上，表达成内存大小；
......

纵坐标是表达是一个 stack trace。

因此上图表达的含义和下面一组数据是一致的。每一行以空格分割，左边的是 stack trace，右边是数值。

a();b();c() 1
a();b();d() 2
c();b() 3

到这里，读者应该对性能分析(profiling)的工作原理有个感性的认识，性能分析的整体流程如图：

可观测可回溯 | Continuous Profiling 实践解析_性能分析_09

因此实现 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 程序运行的代码结构，如下图：

可观测可回溯 | Continuous Profiling 实践解析_性能分析_10

可观测可回溯 | Continuous Profiling 实践解析_开发者_11

对于 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 分配器或者其他的）的分配速度；

可观测可回溯 | Continuous Profiling 实践解析_开发者_12

JVM alloc profiling 关心的则是 TLAB 分配器的分配速度；

可观测可回溯 | Continuous Profiling 实践解析_java_13

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 功能。

可观测可回溯 | Continuous Profiling 实践解析_性能分析_14

可观测可回溯 | Continuous Profiling 实践解析_开发者_15

JFR 的事件包括下面几类信息：

一般信息：关于虚拟机、操作系统和记录的一般信息；
内存：关于内存管理和垃圾收集的信息；
代码：关于方法、异常错误、编译和类加载的信息；
线程：关于应用程序和线程和锁的信息；
I/O：关于文件和套接字输入、输出的信息；
系统：关于正在运行 Java 虚拟机的系统、进程和环境变量的信息；
类型：关于记录中的事件类型的信息。

可观测可回溯 | Continuous Profiling 实践解析_性能分析_16

通过 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 过高导致根本不适合在生产环境常态化采集；

2. Async Profiler

组合使用 Perf_events 和 AsyncGetCallTrace 解决 JVM SafePoint Bias 问题，解决了 overhead 高问题。主流的 java IDE IntelliJ IDEA 和 alibaba 的 Arthas 提供的 profiling 能力通过 Async-profiler 实现的。因此 Arms 的方案里面也借助了这个工具。

Arms Continuous JVM Profiler

为了更好的为用户提供价值，Arms 联合 Alibaba Dragonwell 团队，基于业界主流设计，进行了深度优化，设计出了全新的采集、分析技术方案。其中采集方案兼顾性能和财务成本，优先使用更成熟和完善的 JFR，但在JFR是商业化特性的 OracleJDK 或 Async-Profiler 性能更优的情况下，采用 Async-Profiler 作为替代方案，并且是全自动的，用户无需关注配置细节。

Support list

OpenJDK

可观测可回溯 | Continuous Profiling 实践解析_性能分析_17

说明：

jdk8u272 以下的版本选择 Async-Profilier 和核心原因是没有 JFR 可用；
jdk8u272 之后直到 jdk16 之前，JFR 实现的 alloc 相关事件的开销比较大，因此选择 Async-Profilier；
其他情况，能用 JFR 都用 JFR

Oracle JDK

可观测可回溯 | Continuous Profiling 实践解析_开发者_18

说明：

OracleJDK8 上 JFR 是商业特性，因此选择 Async-Profilier
OracleJDK11 之后的版本的 JFR 是开源特性，alloc 选择 Async-Profilier 的原因一样是因为 JFR 实现的 alloc 相关事件的开销比较大，因此选择 Async-Profilier
其他情况，能用 JFR 都用 JFR。

性能分析类型

目前 Arms 产品化部分包含 2 类 3 个性能分析类型，解决 java 开发者最常见的 CPU 和内存方面的问题：

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]

因此 Async-profiler 和 Oracle 官方并没有更细节的数据，因此我们实际在进行一些测试，供参考：

压力测试模型

压力测试模型如下图示：

可观测可回溯 | Continuous Profiling 实践解析_开发者_19

测试代码包含数据库查询、JSON 序列化、日志文件顺序写、网络收发等。

压力测试客户端

使用 wrk 做并发测试，命令如下：

wrk -t2 -d 10 -c 10http://172.22.230.30:8088/queryRandom

客户端的压力的总体目标是把服务端的 CPU 压力控制在 50%左右。压力测试结果这里评估对应用的影响主要通过 QPS（吞吐）和 RT（时延）作为标准（系统 CPU 压力控制在 50%左右）：

可观测可回溯 | Continuous Profiling 实践解析_java_20

JFR Alloc 依赖的两个 JFR Event 有非常严重的性能问题：1. jdk.ObjectAllocationInNewTLAB2. jdk.ObjectAllocationOutsideTLAB因此本测试不包含 JFR Alloc；JFR 的这个问题直到 JAVA15 以后才得到解决。

我们还做了一组极限压测，将 CPU 全部打满，这种情况的出的结论为 QPS 和 RT 的开销低于 10%。这种极端情况也是存在，数据供参考。

最佳实践路径

CPU 高排查路径

可观测可回溯 | Continuous Profiling 实践解析_java_21

可观测可回溯 | Continuous Profiling 实践解析_性能分析_22

可观测可回溯 | Continuous Profiling 实践解析_开发者_23

1. JVM 程序 CPU 高的传统方式

我们聚焦 User time 高的情况，java 开发者的排查流程：

1.定位 CPU 高的 java 进程的 pid，top；

2.定位具体线程 id，top -p ${pid} -H；

3.计算线程 ID 的 16 进制值，printf "%x\n" ${线程 ID}；

4.根据 stack trace，定位具体瓶颈点，jstack ${pid}| grep ${线程 ID} -A 10；

5.查看 stack trace，识别代码，解决问题。

2. 利用 Arms Continuous Java Profile 解决 JVM user 高的问题

1. 确定是 JVM 业务进程导致 user CPU 升高；

可观测可回溯 | Continuous Profiling 实践解析_java_24

2. 找到 CPU 变高时间点，打开火焰图和人点方法统计，识别代码消耗，解决问题。

可观测可回溯 | Continuous Profiling 实践解析_java_25

直接定位到方法，并且把每个方法的耗时统计出来，如上图左边所示的热点方法。过滤掉线程等相关条件（当 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]