乐趣区

关于阿里云:可观测可回溯-Continuous-Profiling-实践解析

jiezi

作者： 虚镜

概述

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

为了更好的为用户提供价值，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 10http://172.22.230.30:8088/que…

客户端的压力的总体目标是把服务端的 CPU 压力管制在 50% 左右。压力测试后果这里评估对利用的影响次要通过 QPS（吞吐）和 RT（时延）作为规范（零碎 CPU 压力管制在 50% 左右）：

JFR Alloc 依赖的两个 JFR Event 有十分重大的性能问题：1. jdk.ObjectAllocationInNewTLAB2. 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 升高；

  1. 找到 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.co…

[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-profil…

[5] jetbrains IntelliJ IDEA：

https://www.jetbrains.com/hel…

*[6] Honest profiler*：

https://github.com/jvm-profil…

*[7] Uber JVM Profiler*

https://github.com/uber-commo…

*[8] Fight Recorder*

https://docs.oracle.com/en/ja…

*[9] JEP 349: JFR Event Streaming*

https://openjdk.org/jeps/349

*[10] JFR Overhead*

https://docs.oracle.com/javas…

退出移动版