5

使用 perf 解决 JDK8 小版本升级后性能下降的问题

 2 years ago
source link: https://my.oschina.net/openeuler/blog/5122995
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

使用 perf 解决 JDK8 小版本升级后性能下降的问题

编者按:在升级 JDK8U 的小版本后(从 8u74 升级到 8u202),遇到性能剧烈下降的问题(性能下降 13 倍)。该应用是一个非常简单的 Web 应用,且应用在 JDK 升级前后并无任何发布修复。通常来说 JDK 小版本升级都是问题修改,不影响功能和性能使用,而应用性能剧烈下降一定是 JDK 的内部 bug。对于这样明确由 JDK 引起的性能问题,该如何解决?最常见的方法是通过工具分析 JVM 执行过程,检查函数执行的情况是否发生变化,如果找到变化,则可以深入分析哪些因素引起了变化,并进一步得到根因。笔者使用 perf 工具分析 JVM 执行时的热点函数,并对出现问题的函数进行剖析,使用函数插桩来分析函数的执行次数,发现不同版本行为差异的根源,并找到了引起问题的根因。希望读者遇到性能问题时可以参照本文使用 perf 工具对问题进行定位。

工欲善其事,必先利其器。程序员在定位性能瓶颈的时候,要是有一个趁手的性能调优工具,能一针见血地指出程序的性能问题,可谓事半功倍。

Linux 中最常用的性能调优工具 Perf(Linux 系统原生提供的性能分析工具),使用 perf 先对应用(假设要采样的应用为 JavaApp)进行采样,使用 record 命令,如下:

perf record java JavaApp

另外 perf 能按出现的百分比降序打印 CPU 正在执行的函数名以及调用栈,如命令:

perf report -n

可打印出:

524d72a2-be9c-43e6-a122-3b72db88fe8b.png

这种结果的输出还是不直观的,Linux 性能优化大师 Brendan Gregg 发明了火焰图(因整个图形看起来像燃烧的火焰而得名),以全局的方式来看各个函数的调用时间分布,以图形化的方式列出调用栈。

初识火焰图

火焰图是基于 perf 的结果生成的图形,我们先了解一下怎么去看火焰图。以下图为例:

f3f9188a-784a-4bc8-88ad-c42bbce58c5e.png

X 轴表示被抽样到的次数。理解 X 轴的含义,需先了解采样数据的原理。Perf 是在指定时间段内,每隔一段时间采集一次数据,被采集到的次数越多,说明该函数的执行总时间长,可能的原因有:调用次数多,或者单次执行时间长。因此,X 轴的宽度不能简单的认为是运行时长。Y 轴表示调用栈。

如何从火焰图看出性能的瓶颈在哪里?最有理由怀疑的地方,顶层的“平顶”。关于 perf 和火焰图使用方法可以参官网http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html。

下面是我们利用火焰图来定位问题的一次实战。

火焰图定位问题的实战

问题发生的场景是客户端向服务器发起 http 请求,服务器返回数据给客户端(这是一个非常简单的服务交互)。我们发现使用 JDK 8u74 的性能要远优于 JDK 8u202 的性能,下表中统计了 20 次服务器的响应时长。

d56fd956-f819-4f52-bbeb-ce9088c2dc81.png

从响应时间来看,8u202 相比 8u74 性能下降 13 倍之多,由于应用本身并未做任何修改,所以考虑使用火焰图来定位性能消耗的问题点。在 8u74 和 8u202 分别运行应用,并用 perf 的 record 抓取数据并生成火焰图。

火焰图定位

对比两张火焰图,使用 8u74 时 ClientHandshaker.processMessage 占比为 1.15%,而在 8u202 中这个函数占比为 23.98%,很明显在 ClientHandshaker.processMessage 带来了性能差异。

88436c32-8d74-4ca1-8be4-b9fc3f156e81.png

3cbddfb6-f4ec-4de9-abc2-e5d2701a9326.png

两者在这个 ClientHandshaker.processMessage 上的 cpu 消耗差异很大,继续分析这个函数找到根因。

void processMessage(byte handshakeType, int length) throws IOException {
    if(this.state >= handshakeType && handshakeType != 0) {
        //... 异常
    } else {
        label105:
        switch(handshakeType) {
        case 0://hello_request
            this.serverHelloRequest(new HelloRequest(this.input));
            break;
        //...
        case 2://sever_hello
            this.serverHello(new ServerHello(this.input, length));
            break;
        case 11:///certificate
            this.serverCertificate(new CertificateMsg(this.input));
            this.serverKey = this.session.getPeerCertificates()[0].getPublicKey();
            break;
        case 12://server_key_exchange 该消息并不是必须的,取决于协商出的key交换算法
            //...
        case 13: //certificate_request 客户端双向验证时需要
            //...
        case 14://server_hello_done
            this.serverHelloDone(new ServerHelloDone(this.input));
            break;
        case 20://finished
            this.serverFinished(new Finished(this.protocolVersion, this.input, this.cipherSuite));
        }
        if(this.state < handshakeType) {//握手状态
            this.state = handshakeType;
        }
    }
}

processMessage()主要是通过不同的信息类型进行不同的握手消息的处理。而在火焰图中可以看到,JDK8u74 图中,主要消耗在函数 serverFinished()和 serverHello()上,而 JDK8u202 主要消耗在函数 serverHelloDone()和 serverKeyExchange()。在介绍火焰图的时候,我们有提到,X 轴的长度是映射了被采样到的次数。因此需要进一步确定消耗:函数单次执行耗时过长而成为热点,还是因为频繁调用函数导致函数耗时过长而成为热点。可通过字节码插桩(通过 Instrument 技术实现对函数的计数,然后编译成 agent,执行应用时加载 agent,具体使用 Instrument 的方法可以参考官方文档)查看函数 serverHelloDone()的调用次数及执行时间。

JDK8u202 数据
Execute count : 253
Execute count : 258
Execute count : 649
Execute count : 661
serverHelloDone execute time [1881195 ns]
Execute count : 1223
Execute count : 1234
Execute count : 1843
Execute count : 1852
serverHelloDone execute time [1665012 ns]
Execute count : 2446
Execute count : 2456
serverHelloDone execute time [1686206 ns]
JDK8u74 数据
Execute count : 56
Execute count : 56
Execute count : 56
Execute count : 56
Execute count : 56
Execute count : 56

Execute time 是取了每 1000 次调用的平均值,Execute count 每 5000ms 输出一次总执行次数。很明显使用 JDK8u202 时在不断调用 serverHelloDone,而 74 在调用 56 次后没有再调用过这个函数。

初始化握手时,serverHelloDone 方法中,客户端会根据服务端返回加密套件决定加密方式,构造不同的 Client Key Exchange 消息;服务器如果允许重用该会话,则通过在 Server Hello 消息中设置相同的会话 ID 来应答。这样,客户端和服务器就可以利用原有会话的密钥和加密套件,不必重新协商,也就不再走 serverHelloDone 方法。从现象来看, JDK8u202 没有复用会话,而是建立的新的会话。

查看 JDK8u 161 的 release notes,添加了 TLS 会话散列和扩展主密钥扩展支持,找到引入的一个还未修复的 issue,对于带有身份验证的 TLS 的客户端,支持 UseExtendedMasterSecret 会破坏 TLS-Session 的恢复,导致不使用现有的 TLS-Session,而执行新的 Handshake。

JDK8u161 之后的版本(含 JDK8u161),若复用会话时不能成功恢复 Session,而是创建新的会话,会造成较大性能消耗,且积压的大量的不可复用的 session 造成 GC 压力变大;如果业务场景存在不变更证书密钥,需要复用会话,且对性能有要求,可通过添加参数-Djdk.tls.useExtendedMasterSecret=false 来解决这个问题。

如果遇到相关技术问题(包括不限于毕昇 JDK),可以通过毕昇 JDK 社区求助。毕昇 JDK 社区每双周周二举行技术例会,同时有一个技术交流群讨论 GCC、LLVM 和 JDK 等相关编译技术,感兴趣的同学可以添加如下微信小助手入群(请备注:Complier)。

6354e67b-9752-434f-85b2-5d435e29378a.png

本文分享自微信公众号 - openEuler(openEulercommunity)。
如有侵权,请联系 [email protected] 删除。
本文参与“OSC源创计划”,欢迎正在阅读的你也加入,一起分享。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK