问题现象

公司项目通过tornado框架实现,依赖pymongo+motor作为数据库访问driver,实质通过docker部署的api应用出现稳定、缓慢的内存增长。在给予docker容器4G硬限的前提下,从开始运行起,经过2-7天出现进程因OOM被强制结束运行的问题。

问题原因:

  • 容器内运行镜像时硬限的语义和python中os.cpu_count()的语义不同问题 根据ref 1和2所提到的定义,当使用–cpus flag限制docker容器运行时使用的cpu时,其实质是限制了一个容器可以使用的cpu tick占一段时间内cpu tick的百分比。举例说明,如果一台机器cpu为4核,使用–cpus 1.5参数指定容器运行,则限制了该容器可以使用的cpu tick为1.5/4,即37.5%的cpu tick(等价为cpu算力)。出现问题的motor代码片段附加如下:
if 'MOTOR_MAX_WORKERS' in os.environ:
    max_workers = int(os.environ['MOTOR_MAX_WORKERS'])
else:
    max_workers = multiprocessing.cpu_count() * 5
​
_EXECUTOR = ThreadPoolExecutor(max_workers=max_workers)

易用python3 -c "import multiprocessing as mp; import os; print(os.cpu_count() is mp.cpu_count())"运行结果为True验证multiprocessing.cpu_count()os.cpu_count()为同一函数。os.cpu_count()进而使用如下的代码片段在linux运行环境下获得cpu核数:

ncpu = sysconf(_SC_NPROCESSORS_ONLN);

该系统调用会获取系统硬件有多少cpu核。docker命令限制的是cpu tick使用占比,不可能改变硬件层面上有多少cpu核在使用,故该python调用返回硬件层面上的cpu核数也是合理的。 回到上方motor启动时的代码片段。一般一台宿主机上会有很多cpu核,跑不同docker管理下下运行的容器。而启动代码里的multiprocessing.cpu_count()调用获取到的是宿主机的cpu核数,所以启动了远远超过期望的motor worker数量。

ref:

  1. https://stackoverflow.com/a/64616828/9188030
  2. https://docs.docker.com/config/containers/resource_constraints/#cpu
  3. https://www.796t.com/article.php?id=81347
  4. https://man7.org/linux/man-pages/man3/get_nprocs_conf.3.html
  • 使用motor为pymongo的driver时未分页导致单个worker内存占用过高的问题 在修正内存问题之前,取用mongo数据的伪代码如下:
cursor = TABLE.find({...})
# or cursor = TABLE.find({...}).sort(...)
return cursor.to_list(None)

cursor是lazy evaluated的。执行to_list后才会尝试从数据库中取数据,逐个放进返回的列表中,最后返回结果列表。伪代码所示的to_list用法没有限制一次读入数据的条数,故当一次筛选出大量数据后(典型例子如“问题现象出现时间”所提到的commit),则单个worker会在完成取用数据后缓存该次查询的结果,直到下一次由该worker进行该次条件的查询时,再刷新其缓存的数据。单个worker缓存了过大查询结果,和之前提到的worker数量过多的问题叠加,造成了api deployment规律性因OOM而被强制结束运行的问题。

ref:

  1. https://jira.mongodb.org/browse/MOTOR-800?jql=project%20in%20(PYTHON%2C%20MOTOR)%20ORDER%20BY%20created%20DESC

解决方案:

对cpu个数获取不正确的问题,决定之后版本中写死MOTOR_MAX_WORKERS环境变量,每一次更新api deployment时,若部署的cpu配置发生更改则对应地更改该环境变量。

对to_list导致过多缓存的问题,根据上文jira的建议修改为对大结果集查询,分batch取出结果。

定位过程:

通过观察grafana监控面板确认该问题规律性出现。

通过发送大请求把内存快速打满确认该问题和请求体有关系,但无法复现容器因OOM停止运行。

怀疑是日志系统问题,在线上环境下运行完全屏蔽logging handler的灰度版本,未解决问题。

之后寻找线上内存将要被撑满的机器,通过cat /proc/self/smaps确认实际占用内存(rss mem)的地址区间(区别于十几G占用的虚拟内存),找出rss mem占用较大(十几m到二十多m)的地址区间,之后通过gdb对该区间内存做dump,下载至本地,通过二进制查看器查看什么内容占用了如此多的内存。

通过查看后,对比代码中的字段,大致确认是pymongo读写缓存时产生的问题。但未能定位具体产生该问题的代码区段。

通过阅读motor相关的启动代码和issue提问,最终锁定问题原因。