引言:
文中创作者为处理一个JDK特性问题,从局部变量剖析,到GC分析,再到Safepoint根本原因,最后精准定位到问题根因与常用的JDK版本号相关。并梳理成文,与全部Java有关研发的同学们共享本次工作经验。
01 那么问题来了
小编最近在工作上碰到那样一个问题:某用户新上线一个Elasticsearch运用,但运转一段时间后就变的尤其慢,乃至查看请求超时。重新启动后服务项目修复,但每过3~4小时后问题再现。
对于这个问题,我周围的朋友也帮助进行了简易剖析,发觉出现很多Merge的线程,该怎么办呢?依据我以前精准定位的工作经验,一般通过Thread Dump日志剖析,就能寻找问题缘故的前进方向,随后再剖析该问题不停反复的缘故。依照这一构思,问题分析起來应当算不上繁杂。But,之后故事情节或是发生了曲折。
02 疑惑的局部变量日志
因互联网防护缘故,只有由顾客相互配合获得Thread Dump日志。并跟顾客注重了获得Thread Dump日志的方法,每一个节点每过几秒获得一次,輸出到一个单独的文件中。群集牵涉到三个节点,大家姑且将这三个节点称作39,158, 211。问题重现后,取得了第一批Thread Dump文件:
从文件的尺寸,可随便看得出39节点大概率是一个问题节点,它的Thread Dump日志显著大出很多:查看减缓或是卡住,通常体现为很多的Worker Thread繁忙,换句话说,活跃性线程总数明显增加。而在ES(Elasticsearch,下称为ES)的默认设置查看个人行为下,只需有一个节点发生问题,便会让全部查看受牵累。
那麼大家先向三个节点随意选择的1个Thread Dump文件的线程整体状况完成比照:
节点名字 | 39 | 158 | 211 |
线程数量 | 366 | 341 | 282 |
RUNNABLE | 264 | 221 | 162 |
WAITING | 64 | 88 | 92 |
TIME_WAITING | 28 | 32 | 28 |
BLOCKED | 10 | 0 | 0 |
再按线程池开展归类统计分析:
节点名字 | 39 | 158 | 211 |
Lucene Merge Thread | 77 | 0 | 0 |
http_server_worker | 64 | 64 | 64 |
search | 49 | 49 | 49 |
transport_client_boss | 28 | 64 | 30 |
bulk | 32 | 32 | 32 |
generic | 15 | 6 | 4 |
transport_server_worker | 27 | 55 | 29 |
refresh | 10 | 5 | 10 |
management | 5 | 2 | 3 |
warmer | 5 | 5 | 5 |
flush | 5 | 5 | 5 |
others | 49 | 54 | 51 |
可以发觉:39节点上的Lucene Merge Thread显著偏多,而其他2个节点没有Merge的线程。
再对39节点的Thread Dump文件开展详细分析,发觉的出现异常点汇总如下所示:
1. Lucene Merge Thread做到77个,在其中一个线程的启用栈如下所示所显示:
2. 有8个线程在市场竞争锁住ExpiringCache:
3. 有8个线程都是在做HashMap#hash测算:
状况1中提及了有77个与此同时在做Merge的线程,但没法明确这种Merge每日任务是与此同时被开启的,或是由于系统软件解决太慢逐渐堆积成那样的情况。不管怎样这好像一条关键案件线索。再充分考虑这是一个新上架的运用,关于环境信息内容与应用姿态的调查一样关键:
- 群集一共有3个节点,现阶段一共有500 个Indices。每一个节点上写活跃性的分块数在70个上下。
- 按租赁户建立Index,每一个租赁户每日建立3个Indices。发布前期,载入货运量较低。每一个数据库索引在每分Flush成的Segment在KB~数MB中间。
我逐渐开始猜疑这类独特的应用方法:群集中出现好几个写活跃性的数据库索引,但每分的载入量都偏小,在KB至数MB级别。这代表着,Flush很有可能全是规律性开启,而不是超出预置阀值后开启。这类载入方法,会致使造成很多的小文件。取样观查了好多个数据库索引中澳出现的Segment文件,确实每一次转化成的文件都特别小。
有关第2点状况,我用心阅读文章了java.io.UnixFileSystem的源代码:
- UnixFileSystem中要对一个新文件的途径依照电脑操作系统规范开展规范化。
- 标准化的結果储放在ExpiringCache目标中。
好几个线程都是在竞相启用ExpiringCache#put实际操作,这侧边体现了文件目录的高频率转变,这表明系统软件中具有高频率的Flush和Merge实际操作。
这加重了我有关应用姿态的猜疑:”春雨绵绵”式的载入,处于被动开启Flush,假如周期时间同样,代表着与此同时Flush,好几个Shard与此同时Merge的几率增大。
因此,我逐渐在接口测试中仿真模拟这类应用方法,建立相近的分块总数,操纵载入頻率。方案让测试代码最少运作一天的時间,观查是不是可以重现此问题。在程序执行的与此同时,我继续调研Thread Dump日志。
第3点状况中,只是是做一次hash测算,却体现出尤其慢的模样。假如将这三点状况综合性起來,可以发觉任何的启用点都是在做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: PrintGCDetails
8:-XX: PrintGCDateStamps
8:-XX: PrintTenuringDistribution
8:-XX: PrintGCApplicationStoppedTime
8:-Xloggc:logs/gc.log
8:-XX: UseGCLogFileRotation
8:-XX:NumberOfGCLogFiles=32
8:-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版本存在的问题。
4. 拆换Kona JDK后,ForceSafepoints次数由每分钟5000多次减少到个位,解决问题。
根据此次问题的剖析,获得一个经验教训:问题分析前期应当用心调查群集自然环境。自然,较大的经验教训是:千万别乱下载JDK啊!
版权声明:本文内容由互联网用户自发贡献,该文观点仅代表作者本人。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如发现本站有涉嫌抄袭侵权/违法违规的内容, 请发送邮件至 举报,一经查实,本站将立刻删除。