问题的表现是:Overlord上所有的任务全部失败。
Druid日志分析
通过观察失败的任务执行日志发现,日志结尾有很多等待Handoff完成的日志,并且等待半个小时后任务退出,除此之外没有发现其它明显异常信息。
Still waiting for Handoff for Segments ...
Still waiting for Handoff for Segments ...
Still waiting for Handoff for Segments ...
...
在Druid中Handoff表示Historical从deep-storage中拉取segment。Handoff是由Coordinator节点调度完成的,所以我们查看Coordinator日志,发现如下异常:
org.apache.druid.server.coordinator.helper.DruidCoordinatorRuleRunner - Uh... I have no servers. Not assigning anything...
经过调查代码发现”I have no servers”中的servers指的是Historical节点,也就是说Coordinator找不到Historical节点了。
在Druid中overlord节点负责调度任务,因为是任务失败,所以我们调查overlord日志。发现有大量的overlord主动kill任务的日志,看来是overlord主动kill了任务,这是任务全部失败的最直接原因。至于为什么overlord主动kill了任务,姑且先搁置,后文会回答。
org.apache.druid.indexing.kafka.supervisor.KafkaSupervisor - Killing task[index_kafka_browser_anr_kv_event_bd898e42ff88d7e_egidmcno] in the task group
hs_err_pid.log分析
通过上边Druid日志分析,发现Coordinator找不到Historical节点了。进而观察Historical节点情况,发现所有的Historical进程都异常退出。好在有JVM进程的hs_err_pid.log日志,接下来分析hs_err_pid.log,来以定位进程崩溃的具体原因。
首先是hs_err_pid.log日志的header部分,该部分总结了进程崩溃的原因,可以看到是因为内存不足。
#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 262144 bytes for committing reserved memory.
# Possible reasons:
# The system is out of physical RAM or swap space
# In 32 bit mode, the process size limit was hit
...
但是具体是JVM内存不足,还是操作系统内存不足呢?看hs_err_pid.log最后的操作系统内存信息部分,发现进程崩溃是还有大概35GB空闲内存,所以排除了操作系统内存不足的原因。
Memory: 4k page, physical 131489932k(35941924k free), swap 0k(0k free)
接下来调查JVM内存情况,通过看hs_err_pid.log的GC部分,可以看到进程崩溃前的JVM内存的一些信息。
Event: 48.851 GC heap before
{Heap before GC invocations=15 (full 5):
PSYoungGen total 12104192K, used 800K [0x00007f6797b00000, 0x00007f6aed000000, 0x00007f6aed000000)
eden space 10208256K, 0% used [0x00007f6797b00000,0x00007f6797b00000,0x00007f6a06c00000)
from space 1895936K, 0% used [0x00007f6a79480000,0x00007f6a79548000,0x00007f6aed000000)
to space 1876480K, 0% used [0x00007f6a06c00000,0x00007f6a06c00000,0x00007f6a79480000)
ParOldGen total 9509888K, used 2561944K [0x00007f60ed000000, 0x00007f6331700000, 0x00007f6797b00000)
object space 9509888K, 26% used [0x00007f60ed000000,0x00007f61895e60f0,0x00007f6331700000)
Metaspace used 62706K, capacity 64074K, committed 64512K, reserved 65536K
Event: 50.753 GC heap after
Heap after GC invocations=15 (full 5):
PSYoungGen total 12104192K, used 0K [0x00007f6797b00000, 0x00007f6aed000000, 0x00007f6aed000000)
eden space 10208256K, 0% used [0x00007f6797b00000,0x00007f6797b00000,0x00007f6a06c00000)
from space 1895936K, 0% used [0x00007f6a79480000,0x00007f6a79480000,0x00007f6aed000000)
to space 1876480K, 0% used [0x00007f6a06c00000,0x00007f6a06c00000,0x00007f6a79480000)
ParOldGen total 9509888K, used 2557628K [0x00007f60ed000000, 0x00007f6331700000, 0x00007f6797b00000)
object space 9509888K, 26% used [0x00007f60ed000000,0x00007f61891af160,0x00007f6331700000)
Metaspace used 62706K, capacity 64074K, committed 64512K, reserved 65536K
}
可见在GC前后JVM内存都没有短缺的情况,同时在Historical日志中也没有发现OOM异常。通过这两点可以确认,JVM内存不是导致Historical进程崩溃的原因。
直接原因
通过hs_err_pid.log得出的进程崩溃是由于内存不足导致的,这个结论是不会错的。不是内存的物理限制,也不是JVM限制,想到还有一种可能性就是操作系统限制了进程的内存。因为即便是我们自己编写的程序都会对资源的使用进行限制,按照这样的思路,操作系统大概率会对进程内存进行限制。经调查发现这么一个参数vm.max_map_count,它表示一个进程最大能mmap多少个内存区块。按照这个思路进行调查:
- 当前服务器vm.max_map_count参数值
cat /proc/sys/vm/max_map_count
65530
- 在hs_err_pid.log文件中,统计崩溃前进程mmap内存块的数量
# 注:hs_err_pid.log_bak文件只保留了hs_err_pid.log的mmap部分
wc -l hs_err_pid.log_bak
65533 hs_err_pid.log_bak
可以看到已经达到了最大限制,至此得出了进程崩溃的直接原因,Historical进程mmap超过了操作系统限制。
进一步原因
接下来看看Historical进程mmap了什么东西,通过观察统计hs_err_pid.log_bak,发现绝大部分是browser_iflow_abtest_common这个datasource的相关文件,总共有5w多。
grep "/var/druid/segment-cache/browser_iflow_abtest_common" hs_err_pid.log | wc -l
52162
继续查看到browser_iflow_abtest_common这个datasource在一个小时内就生成了2000多的小segment,显然这是不合理的。进一步调查产生小segment的原因,发现browser_iflow_abtest_common的“maxRowsPerSegment“参数设置为了50000,对于一个一天有100亿级别数据量的datasource来说显然是极其不合理的。
将上边一连串的分析总结如下:由于datasource参数“maxRowsPerSegment”的不当设置,导致产生了大量的小segment,因为查询涉及到了这些segment,导致服务器mmap count达到限制,进而导致了Historical挂掉。
Historical挂掉导致新的构建任务的segment Handoff一直不能完成,当任务达到超时时间时,Overlord就主动kill了任务,最终表现为大面积构建任务失败的现象。
至此问题分析结束。
处理措施
问题已经很清楚了,问题处理方式也很明显:
- 调高maxRowsPerSegment参数,我们设置为1000w
- 调高Druid节点的vm.max_map_count参数,我们设置为655300
3 replies on “一次Druid crash问题分析”
You got a very great website, Gladiola I discovered it through google. https://glaucomamedi.com buy glaucoma threatment
Today, considering the fast way of life that everyone leads, credit cards have a huge demand in the economy. Persons throughout every area are using the credit card and people who are not using the card have arranged to apply for 1. Thanks for discussing your ideas on credit cards. https://psoriasismedi.com plaque psoriasis treatment
I’m commenting to let you be aware of of the beneficial discovery my child developed browsing the blog. She came to find a good number of details, including how it is like to have a great coaching character to get certain people completely comprehend a number of complex issues. You actually did more than her desires. I appreciate you for coming up with such effective, dependable, edifying and cool guidance on that topic to Emily.