可遇不可求的经历,月更素材不请自来

0x00.前言

早上被前辈敲门叫醒,一看手机客户在wx群里说服务器SSH登不上去,叫我们赶紧过去

0x01.问题确认

去了一看SSH是可以登录的,只不过服务端回显特别慢,凭经验看有点像内存或硬盘爆满的现象
因为速度实在是太慢了于是放弃SSH,登录到CIMC(相当于VNC)的界面,一看一整页的OOM Killer已经开始制裁(第一个是java,后面的都是python3
那么问题已经确认,是系统发生了OOM,路上还在各种猜测比如是硬盘炸了之类的……
emmm,想了一下可能是自己昨天从多线程切换到了多进程所导致的,进入top再按C键,然后一整屏的python3 collector.py,粗略估算首屏就有二三十个了
而且所占内存巨大,物理机128G内存,平常基本浮动在64G左右,这时候free -m的整机内存所剩无几

下注:现网真实复现数据

1
2
3
4
5
6
7
[root@node1 ]# free -m
total used free shared buff/cache available
Mem: 128406 127181 396 59 828 370
Swap: 51199 8086 43113
[root@node1 ]# ps -ef | grep collector
root 16065 113930 3 15:09 ? 00:00:18 -venv/bin/python3 collector.py
首屏非全部,省略后续`49+`行……

0x02.恢复服务

也很纳闷,早在前一天下午就讨论到了使用多进程有OOM风险,也只开了max_workers4的进程池,怎么就会爆内存了呢?
但是首先还是要恢复服务,把ps -ef出的collector进程全都kill掉,并且用supervisorctl把对应的子服务关闭,内存算是回到了正常水平
然后就是各种第三方组件的恢复,最后Kafka一直启动不能,messages里也一直有error报错,临时删掉data再启动也终于恢复了

0x03.等待复现

这时候还没换回多线程,准备先跑着看看会不会还有问题……结果果不其然,下午做完核酸检测回来的时候前辈说复现了,现场还在,正准备开始kill
操作巨卡无比已是在意料之中,上来就free -m一看果然内存又基本跑满,再通过top看有非常多的python3,都得翻到第二页才能看完
虽然没来得及手动kill,不过赶巧等了一会儿这些进程都结束了,翻日志发现刚刚写入了一个含7850484条记录的索引,耗时490.36
先不说其他的,7850484应该是遇到的每小时级别最大的键了,其实这个键的写入操作本来是应该在半夜3点后的定时任务里去完成的
结果半夜直接OOM一直没有完成,拖到了下午3点又开始跑定时任务的时候就复现了

0x04.溯源分析

是时候贴一下关键函数的源码了,这一个函数里就写了俩bug简直了

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
def bulk_load_to_es_by_pool_executor(df_content, timestamp, index_name_type):
"""
Refer to
https://web.archive.org/web/20210323141917/https://discuss.elastic.co/t/helpers-parallel-bulk-in-python-not-working/39498
https://web.archive.org/web/20210720072749/https://www.jianshu.com/p/b9b3d66aa0be
"""
try:
s_t = time.time()

flows_split_size = CFG.config.get('flows_split_size')
use_thread_pool = CFG.config.get('use_thread_pool')
thread_pool_max_workers = CFG.config.get('thread_pool_max_workers')

content = generate_all_content(df_content, timestamp, index_name_type)
LOG.debug(f'generate_all_content completed in {str(time.time() - s_t)}s')

content_list = split_all_content(content, flows_split_size)
# LOG.debug(f'content_list completed in {str(time.time() - s_t)}s')

# 210803 change from ThreadPoolExecutor to ProcessPoolExecutor, bypass GIL
# https://docs.python.org/zh-cn/3/library/concurrent.futures.html#processpoolexecutor
if use_thread_pool:
executor = ThreadPoolExecutor(max_workers=int(thread_pool_max_workers))
else:
executor = ProcessPoolExecutor()
all_task = [executor.submit(bulk_in_thread, (each)) for each in content_list]

wait(all_task, return_when=ALL_COMPLETED)

LOG.info(f'bulk_load_to_es count {len(content)} completed in {str(time.time() - s_t)}s')
except Exception as err:
raise CollectorException('error occured when post raw flows to es, %s' % str(err))

1. content过大

没错,content就是那个含有7850484条记录的bulk的请求体,粗略估测不超过15MB * 66 = 990MB,也就是接近1G的大小
而创建ProcessPoolExecutor()content变量已经存在,multiprocessing启动进程的方法在Unix中的默认值是fork
也就是说fork出来的每一个进程都会拷贝一份content变量,造成不必要的内存开销

2. 未限制max_workers

翻阅了一下gitlab的历史,可以看出最开始用的ThreadPoolExecutor是有显式设定max_workers的,但是ProcessPoolExecutor却没有传入max_workers
想了下原因是,当初看到文档max_workers默认是机器的处理器个数,想着应该不需要手动设定数量吧,所以到头来代码里就一直没有给多进程设置max_workers的地方……
lab里测试环境的CPU16再不就是32,而现网环境是直接把CentOS装到了物理机上,也没有ESXi之类的虚拟化平台,CPU就是64……

以上两个原因,导致在处理7850484条记录时占用接近64G的内存,加上平常基本浮动在64G左右,合计就接近128G
半夜的时候超过128G导致OOM,而次日下午是刚恢复完其他服务没有占用过多内存才勉强运行完成

0x05.代码重构

1. content过大

未完待续……

2. 限制max_workers

executor = ProcessPoolExecutor(max_workers=int(thread_pool_max_workers))

0x06.后记

现网OOM有被吓到,本来都订了当晚回来的机票,被迫取消留用晚了一天才回来(

0x07.引用

Python 调用 elasticsearch 的 bulk 接口批量插入数据出现内存泄露,导致 OOM