今天有一个索引慢日志,
[2020-02-12T15:52:37,418][WARN ][i.i.s.index ] [node-1] [company/KTngnM6ASD-_KdU0FFAWRA] took[22.7s], took_millis[22703], type[_doc], id[20080943028], routing[], source[{...}]
然后检查gc.log
找出原因,
[2020-02-12T07:52:37.417+0000][22539][safepoint ] Total time for which application threads were stopped: 0.0004935 seconds, Stopping threads took: 0.0001389 seconds
[2020-02-12T07:52:37.586+0000][22539][safepoint ] Application time: 0.1682439 seconds
[2020-02-12T07:52:37.586+0000][22539][safepoint ] Entering safepoint region: GenCollectForAllocation
[2020-02-12T07:52:37.586+0000][22539][gc,start ] GC(315124) Pause Young (Allocation Failure)
[2020-02-12T07:52:37.586+0000][22539][gc,task ] GC(315124) Using 8 workers of 8 for evacuation
[2020-02-12T07:52:37.641+0000][22539][gc,age ] GC(315124) Desired survivor size 34865152 bytes, new threshold 3 (max threshold 6)
[2020-02-12T07:52:37.641+0000][22539][gc,age ] GC(315124) Age table with threshold 3 (max threshold 6)
[2020-02-12T07:52:37.641+0000][22539][gc,age ] GC(315124) - age 1: 22998672 bytes, 22998672 total
[2020-02-12T07:52:37.641+0000][22539][gc,age ] GC(315124) - age 2: 4966112 bytes, 27964784 total
[2020-02-12T07:52:37.641+0000][22539][gc,age ] GC(315124) - age 3: 10219520 bytes, 38184304 total
[2020-02-12T07:52:37.641+0000][22539][gc,age ] GC(315124) - age 4: 4875304 bytes, 43059608 total
[2020-02-12T07:52:37.641+0000][22539][gc,heap ] GC(315124) ParNew: 597611K->52614K(613440K)
[2020-02-12T07:52:37.641+0000][22539][gc,heap ] GC(315124) CMS: 4992477K->4998973K(16095680K)
[2020-02-12T07:52:37.641+0000][22539][gc,metaspace ] GC(315124) Metaspace: 103488K->103488K(1144832K)
[2020-02-12T07:52:37.641+0000][22539][gc ] GC(315124) Pause Young (Allocation Failure) 5459M->4933M(16317M) 54.724ms
[2020-02-12T07:52:37.641+0000][22539][gc,cpu ] GC(315124) User=0.35s Sys=0.00s Real=0.06s
[2020-02-12T07:52:37.641+0000][22539][safepoint ] Leaving safepoint region
似乎GC还可以,但是有些日志无法理解,例如
Entering safepoint region: Cleanup
Entering safepoint region: RevokeBias
Entering safepoint region: GenCollectForAllocation
Cleanup
、RevokeBias
、GenCollectForAllocation
是什么意思?Application time
是什么意思?为什么如此不同?
Application time: 0.1382641 seconds
Application time: 13.2106552 seconds
Application time: 106.3031188 seconds
有趣的是,你提到了一些事情,但没有为它们提供日志。无论如何:
RevokeBias
是当发生撤销偏置锁定或偏置锁定的"胖"锁放气时。
GenCollectForAllocation
- 这就是触发安全点的原因。您可以将其读作:"分配失败的代际收集器"。仅供参考,还有许多其他原因。
Cleanup
是任何安全点清理任务。
AFAIK,如果需要更多详细信息,则需要启用跟踪日志级别。