一次Druid crash问题分析

问题的表现是：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

参考文档：

• Maximum number of mmap()’ed ranges and how to set it on Linux?
• Analysis of JVM Fatal Error Log

本作品采用 知识共享署名 4.0 国际许可协议 进行许可， 转载时请注明原文链接。