分类
uncategorized

一次Druid crash问题分析

记录一次生产环境Druid崩溃问题分析。

问题的表现是: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多少个内存区块。按照这个思路进行调查:

  1. 当前服务器vm.max_map_count参数值
cat /proc/sys/vm/max_map_count 
65530
  1. 在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了任务,最终表现为大面积构建任务失败的现象。

至此问题分析结束。

处理措施

问题已经很清楚了,问题处理方式也很明显:

  1. 调高maxRowsPerSegment参数,我们设置为1000w
  2. 调高Druid节点的vm.max_map_count参数,我们设置为655300

参考文档:

发表回复

您的电子邮箱地址不会被公开。 必填项已用*标注