您现在的位置是：首页 > 网络趣梗网络趣梗

jdk下载速度慢正常吗(javajdk下载慢)

2022-08-23 20:39:18网络趣梗0人已围观

简介　　jdk下载速度慢正常吗(javajdk下载慢)，新营销网红网本栏目通过数据整理汇集了jdk下载速度慢正常吗(javajdk下载慢)相关信息，下面一起看看

　　jdk下载速度慢正常吗(javajdk下载慢)，新营销网红网本栏目通过数据整理汇集了jdk下载速度慢正常吗(javajdk下载慢)相关信息，下面一起看看。

　　简介：

　　为了解决一个JDK的性能问题，从栈分析，到GC分析，再到Safepoint原因分析，作者最终发现问题的根本原因与使用的JDK版本有关。并写下来与所有Java相关开发的同学分享这个经验。

　　 01问题来了。

　　最近笔者在工作中遇到了这样一个问题：一个客户新推出了一个Elasticsearch应用，但是运行一段时间后变得异常缓慢，甚至查询超时。重启后，服务恢复，但问题每3 ~ 4小时重复出现一次。

　　针对这个问题，我身边的同事也帮忙做了一个简单的分析，发现有大量的合并线程。我该怎么办？根据我之前定位问题的经验，可以通过线程转储日志分析找到问题原因的正确方向，进而分析出问题不断重复的原因。按照这个思路，问题分析起来应该不复杂。但是，后来，剧情出现了波折。

　　 02混乱的堆栈日志

　　由于网络隔离，线程转储日志只能在客户的配合下获取。并向客户强调了获取线程转储日志的技巧。每个节点每隔几秒钟获取一次，并输出到一个独立的文件中。集群涉及三个节点，我们暂且称之为39，158，211。问题再次出现后，我拿到了第一批线程转储文件：

　　从文件大小不难看出，39节点大概率是问题节点，其线程转储日志明显要大很多：查询缓慢或卡死，这通常说明有大量工作线程繁忙，即活动线程数明显增加。但是在ES(Elasticsearch，以下简称ES)的默认查询行为下，只要一个节点出现问题，整个查询都会受到影响。

　　然后，让我们首先比较一个可选线程转储文件在三个节点中的总体线程情况：

　　节点名称39158211线程总数366341282 Runnable 264221162 Waiting 64892 Time _ Waiting 283228 Blocked 1000然后按照线程池分类统计：

　　节点名39158211 Lucene合并线程7700 http _ server _ worker 646464 search 4949 transport _ client _ boss 286430 bulk 323232 generic 1564 transport _ server _ worker 275529 ref resh 10510 Management 523 Warmer 555 Flush 555 Others 495451可以发现，节点39上明显有更多的Lucene合并线程，而其他两个节点没有任何合并线程。

　　进一步深入分析39个节点的线程转储文件，发现的异常点总结如下：

　　 1.Lucene合并线程有77个，一个线程的调用栈如下：

　　 2.有8个线程竞争锁定ExpiringCache:

　　 3.有8个线程都在进行HashMap #哈希计算：

　　现象1中提到有77个线程同时在做合并，但无法确定这些合并任务是同时触发的，还是因为系统处理太慢，逐渐累积成这样的状态。无论如何，这似乎是一个重要的线索。考虑到这是一个新的在线应用，对环境信息的研究与使用姿势同样重要：

　　集群中有3个节点，目前有500个索引。每个节点上具有活动写入的片的数量约为70。根据租户创建指数，每个租户每天创建3个指数。在线初期，写入吞吐量较低。每个索引每分钟刷新到KB和MB之间段中。我开始怀疑这种特殊用法了：集群中有很多写活动的索引，但是每分钟的写量很小，从KB到MB不等。这意味着可以周期性地触发刷新，而不是在超过预设阈值之后。这种写法会导致大量的小文件。在对几个索引中新生成的段文件进行采样后，确实每个生成的文件都很小。

　　关于第二个现象，我仔细看了java.io.UnixFileSystem的源代码：

　　在UnixFileSystem中，新文件的路径需要根据操作系统标准进行标准化。标准化的结果存储在ExpiringCache对象中。很多线程都在竞争调用ExpiringCache#put操作，这反映了文件列表的高频变化，说明系统中存在高频的刷新和合并操作。

　　这加剧了我对使用姿势的怀疑：“毛毛雨”写作，它被动地引发潮红。如果周期相同，则意味着同时冲洗，同时合并多个Shard的概率变大。

　　因此，我开始在测试环境中模拟这种用法，创建类似数量的切片并控制写入频率。计划运行测试程序至少一天，看看这个问题是否可以重现。当程序运行时，我继续研究线程转储日志。

　　第三种现象，只做一次哈希计算，但是速度极慢。如果把这三种现象结合起来，可以发现所有的调用点都在做CPU的计算。按理说，CPU应该是极其忙碌的。

　　现场再次出现问题时，客户帮忙获取了CPU利用率和负载信息，结果显示CPU资源非常闲置。之前同事也研究过IO资源，很闲。这排除了系统资源的影响。这时还发现，每个递归节点都是随机的，与机器无关。

　　一天后，在本地测试环境中，问题未能再次出现。虽然使用

　　姿势不优雅，但却不像是问题的症结所在。

　　03 诡异的STW中断

　　通过jstack命令获取Thread Dump日志时，需要让JVM进程进入Safepoint，相当于整个进程先被挂起。获取到的Thread Dump日志，也恰恰是进程挂起时每个线程的瞬间状态。

　　所有忙碌的线程都刚好在做CPU计算，但CPU并不忙碌。这提示需要进一步调查GC日志。

　　现场应用并未开启GC日志。考虑到问题当前尚未复现，通过jstat工具来查看GC次数与GC统计时间的意义不太大。让现场人员在jvm.options中手动添加了如下参数来开启GC日志：

　　 8:-XX:+PrintGCDetails8:-XX:+PrintGCDateStamps8:-XX:+PrintTenuringDistribution8:-XX:+PrintGCApplicationStoppedTime8:-Xloggc:logs/gc.log8:-XX:+UseGCLogFileRotation8:-XX:NumberOfGCLogFiles=328:-XX:GCLogFileSize=32m

　　添加PrintGCApplicationStoppedTime是为了将每一次JVM进程发生的STW(Stop-The-World)中断记录在GC日志中。通常，此类STW中断都是因GC引起，也可能与偏向锁有关。

　　刚刚重启，现场人员把GC日志tail的结果发了过来，这是为了确认配置已生效。诡异的是，刚刚重启的进程居然在不停的打印STW日志：

　　关于STW日志(”…Total time for which application threads were stopped…”)，这里有必要简单解释一下：

　　JVM有时需要执行一些全局操作，典型如GC、偏向锁回收，此时需要暂停所有正在运行的Thread，这需要依赖于JVM的Safepoint机制，Safepoint就好比一条大马路上设置的红灯。JVM每一次进入STW（Stop-The-World）阶段，都会打印这样的一行日志：

　　2020-09-10T13:59:43.210+0800: 73032.559: Total time for which application threads were stopped: 0.0002853 seconds, Stopping threads took: 0.0000217 seconds

　　在这行日志中，提示了STW阶段持续的时间为0.0002853秒，而叫停所有的线程(Stopping threads)花费了0.0000217秒，前者包含了后者。通常，Stopping threads的时间占比极小，如果过长的话可能与代码实现细节有关，这里不过多展开。

　　回到问题，一开始就打印大量的STW日志，容易想到与偏向锁回收有关。直到问题再次复现时，拿到了3个节点的完整的GC日志，发现无论是YGC还是FGC，触发的频次都很低，这排除了GC方面的影响。

　　出现的大量STW日志，使我意识到该现象极不合理。有同学提出怀疑，每一次中断时间很短啊？写了一个简单的工具，对每一分钟的STW中断频次、中断总时间做了统计：

　　统计结果显示：

　　正常每分钟都有5秒左右的中断。在11:29～11:30之间，中断频次陡增，这恰恰是问题现象开始出现的时间段。每分钟的中断总时间甚至高达20～30秒。

　　这就好比，一段1公里的马路上，正常是遇不见任何红绿灯的，现在突然增加了几十个红绿灯，实在是让人崩溃。这些中断很好的解释了“所有的线程都在做CPU计算，然而CPU资源很闲”的现象。

　　04 关于Safepoint的调查

　　Safepoint有多种类型，为了确认Safepoint的具体类型，继续让现场同学协助，在jvm.options中添加如下参数，打开JVM日志：

　　-XX:+PrintSafepointStatistics-XX:PrintSafepointStatisticsCount=10-XX:+UnlockDiagnosticVMOptions-XX:-DisplayVMOutput-XX:+LogVMOutput-XX:LogFile= vm_log_path

　　等待问题再次复现的过程中，我基于ES运行日志中统计了每一分钟的读写请求频次：

　　读写请求次数是相对平稳的，这排除了用户请求陡增方面的原因。

　　拿到JVM日志时，看到大量的Safepoint类型为ForceSafepoint：

　　而偏向锁回收相关的Safepoint却应该是长这样的：

　　这让我疑惑了。开始在网上搜索ForceSafepoint的触发原因，结果，一无所获。

　　查看hotspot的源码，发现至少有5种相关场景：

　　可见，ForceSafepoint是一个“杂烩”，就像统计图中的“Others”一项。从这里开始，我将JDK加入到了“重点嫌疑人”清单中。

　　继续分析JVM日志。在每一条Safepoint日志中，同时记录了当时的线程总数(threads: total一列)：

　　回顾一下，出现问题时，三个节点的线程总数有明显出入，问题发生后，线程总数是增多的，尤其是Lucene Merge Threads。

　　“多个Lucene Merge任务”与“陡增的ForceSafepoint/STW中断”，哪个是“因”哪个是“果”？

　　依据JVM日志中统计了每一分钟的ForceSafepoint次数，以及线程总数的变化。将两条曲线叠加在一起，得到下图：

　　从图中来看，似乎是ForceSafepoint逐步增多在先，后面的线程才逐步增多。也就是说，STW中断变多在先，然后多个Merge任务线程才开始逐步积累，就好比，一条目录上突然增设了多个红绿灯，然后这条目录逐步变得拥堵。

　　此时，开始请教Kona JDK团队的同学，我把GC日志以及thread dump日志分享给了他，并把我目前为止的发现都告诉了他，最大的怀疑点就是这些不正常的ForceSafepoints，我需要了解ForceSafepoints的原因。

　　过了一段时间后，他回复我：这个是arm版本的jdk。因缺乏arm编译机应急柜，暂时没法给我提供一个debug版本的arm jdk。

　　突然明白，我犯了”先入为主”的错误，尽管一开始就意识到需要对环境进行调查。

　　难怪在本地X86环境中始终无法复现。难怪网上搜索ForceSafepoint时一无所获。

　　接下来和客户会议沟通时，获知：

　　类似的业务，在另外一套X86环境中，没有发现此类问题。在这套arm环境中，还有另外一个Elasticsearch集群，请求量更低，但没有发现此类问题。环境中使用的arm jdk是从网上下载的，背后支持的厂商未知。

　　关于第2点提到的这套环境中的另外一个Elasticsearch集群，我更关心的是它的GC日志中是否存在类似的现象。至于没有发生此类问题，容易理解，因为这类问题往往是业务负载特点与环境多重因素叠加下的系统性问题。现场同学配合打开了这个Elasticsearch集群的GC与JVM日志，现象同在，只是ForceSafepoint的频次低于出问题的集群。

　　至此，问题原因清晰的指向了arm环境与JDK版本。

　　后来，微服务平台TSF团队的臧琳同学介入，他提供了一个添加了debug信息的Kona JDK版本，尽管这个版本比正常版本慢了许多，更换以后，我们发现问题重现的周期明显变长。

　　拿到最新的JVM日志后，臧琳同学分析这些ForceSafepoint都与Inline Cache Buffer有关。当然，这可能是arm环境下所有JDK版本的共性问题，也可能仅仅是之前下载的JDK版本存在问题。

　　接下来，我们将环境中的JDK版本替换成正式Release的Kona JDK。再后来，问题始终没有复现。也就是说，替换成Kona JDK后，问题解决了。

　　我统计了一下使用KonaJ DK后的STW中断次数与中断时间，发现有数量级的提升：

　　原JDK版本：每分钟STW中断5000次～18000次，每分钟中断总数据可能达到10秒～30秒。Kona JDK：每分钟STW中断在个位数，每分钟中断总时间在100～200ms之间。

　　可见，Kona JDK比原来的问题JDK版本在性能上有了数量级的提升。

　　05 总结回顾

　　我们再来梳理一下整个问题的分析思路：

　　1. 通过堆栈分析，发现大量的线程都在做CPU计算，但 CPU资源较闲。关于大量Merge Threads的现象带有一定的迷惑性，但它是问题的“果”而非“因”。

　　2. 通过GC日志分析，发现GC频次与GC时间都很低，但GC日志中存在大量的STW相关日志，需要确认关联的Safepoint类型。

　　3. 通过VM/Safepoint日志分析，确认了Safepoint的类型为ForceSafepoint。通过不同环境与不同集群的现象对比，开始怀疑JDK版本存在问题。