写点什么

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

  • 2022-10-28
    浙江
  • 本文字数:8304 字

    阅读完需:约 27 分钟

作者: 虚镜

概述

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

1.png


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

发展历史

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


Google Wide Profiling:A continuous Profiling infrastucture for data centers


2.png

基本思路

CP 意义可以分解为两个:


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

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


  • Profiling 的基本思想


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


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


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


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

  2. 对上一步生成的文件做个 CRC 计算;(CPU 密集)


3.png


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


4.png


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


5.png


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


  • Continuous 的基本思想


持续(Continuous)相对的概念是按需(On-Demand)。


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


6.png


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


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


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

理解 profiling

  • 用户交互和可视化


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


7.png


  • 理解火焰图


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


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


8.png


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


  • 在 cpu profiling 上,表达花费时间多少;

  • 在 alloc profling 上,表达成内存大小;

  • ......


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


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


a();b();c() 1a();b();d() 2c();b() 3
复制代码


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


9.png


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


10.png


11.png


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


12.png


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


13.png


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


14.png


15.png


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


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

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

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

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

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

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

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


16.png


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


17.png


说明:


  • jdk8u272 以下的版本选择 Async-Profilier 和核心原因是没有 JFR 可用;

  • jdk8u272 之后直到 jdk16 之前,JFR 实现的 alloc 相关事件的开销比较大,因此选择 Async-Profilier;

  • 其他情况,能用 JFR 都用 JFR

  • Oracle JDK


18.png


说明:


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


  • 压力测试模型


压力测试模型如下图示:


19.png


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


  • 压力测试客户端


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


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


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


20.png


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


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

最佳实践路径

  • CPU 高排查路径


21.png


22.png


23.png


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 {线程 ID} -A 10;


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


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


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


24.png


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


25.png


直接定位到方法,并且把每个方法的耗时统计出来,如上图左边所示的热点方法。过滤掉线程等相关条件(当 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 内存是的主要申请是哪些方法:


26.png


第四步,优化代码。

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

发布于: 刚刚阅读数: 5
用户头像

阿里巴巴云原生 2019-05-21 加入

还未添加个人简介

评论

发布
暂无评论
可观测可回溯 | Continuous Profiling 实践解析_阿里云_阿里巴巴云原生_InfoQ写作社区