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

语言: CN / TW / HK

概述

Cloud Native

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

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

发展历史

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

Google Wide Profiling:A continuous Profiling infrastucture for data centers

基本思路

CP 意义可以分解为两个:

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

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

  • Profiling 的基本思想

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

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

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

  1. 生成一个 10M 的文件,随机生成数据;(IO 密集)

  2. 对上一步生成的文件做个 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 的关键点:

  1. 获取堆栈数据(爬栈):如何护获取问题点(瓶颈)点的堆栈数据;

  2. 生成火焰图;

  • 常见的 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 的事件包括下面几类信息:

  1. 一般信息:关于虚拟机、操作系统和记录的一般信息;

  2. 内存:关于内存管理和垃圾收集的信息;

  3. 代码:关于方法、异常错误、编译和类加载的信息;

  4. 线程:关于应用程序和线程和锁的信息;

  5. I/O:关于文件和套接字输入、输出的信息;

  6. 系统:关于正在运行 Java 虚拟机的系统、进程和环境变量的信息;

  7. 类型:关于记录中的事件类型的信息。

通过 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

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。

性能分析类型

目前 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 官方并没有更细节的数据,因此我们实际在进行一些测试,供参考:

  • 压力测试模型

压力测试模型如下图示:

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

使用 wrk 做并发测试,命令如下:

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

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

JFR Alloc 依赖的两个 JFR Event 有非常严重的性能问题:

1. jdk.ObjectAllocationInNewTLAB

2. jdk.ObjectAllocationOutsideTLAB

因此本测试不包含 JFR Alloc;JFR 的这个问题直到 JAVA15 以后才得到解决。

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

最佳实践路径

  • CPU 高排 查路径

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 升高;

2. 找到 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]

第三步,利用 Allocated  Memory 定位 collect-heap 内存是的主要申请是哪些方法:


第四 ,优化代码。

Roadmap

1. 诊断类型增强;(file io,socket io,lock 等等)

2. 聚合能力增强;(merge 和 diff)

3. 查询能力增强;(预处理能力,支持长时间聚合)

4. 火焰图交互增强(StackFrame 表达更多含义,当前仅仅包含一个简单字符串);

5. RPC tracing 和 profiling 联动;

6. 多语言(其他高级语言适配);

参考链接

[1]  Google 论文:

https://storage.googleapis.com/pub-tools-public-publication-data/pdf/36575.pdf

[2]  golang内置pprof

https://go.dev/blog/pprof

[3] java11内置JFR:

https://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

https://github.com/jvm-profiling-tools/async-profiler

[5]  jetbrains IntelliJ IDEA 

https://www.jetbrains.com/help/idea/async-profiler.html

[6]  Honest profiler

https://github.com/jvm-profiling-tools/honest-profiler/

[7]  Uber JVM Profiler

https://github.com/uber-common/jvm-profiler

[8]  Fight Recorder

https://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

https://openjdk.org/jeps/349

[10]  JFR Overhead

https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/performissues001.html