蚁阅性能优化记录

蚁阅 是一个 RSS 阅读服务,使用 Python 实现, 已经上线运行近一年了。

前期主要在做功能开发,没有太多时间去研究性能问题,最近终于有时间做了一次性能优化。

这是优化前的状况:

CONTAINER ID        NAME                CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
c27c40739bbe        rssant-web          0.00%               1.887MiB / 200MiB     0.94%               360MB / 365MB       13.2MB / 4.1kB      2
69beb84e30cc        rssant-async-api    0.04%               86.95MiB / 750MiB     11.59%              160MB / 150MB       913kB / 0B          4
a1cade903c76        rssant-api          0.03%               385.5MiB / 500MiB     77.11%              214MB / 209MB       13MB / 0B           504
1dd2be833b3b        rssant-worker-2     78.59%              1227.8MiB / 1.465GiB  61.85%              24.3GB / 12.7GB     24.8MB / 0B         33
924b7a6cec7d        rssant-worker-1     75.07%              1256.8MiB / 1.465GiB  63.79%              24.2GB / 12.7GB     1.36MB / 0B         33
4caec7b41dbf        rssant-harbor-2     13.60%              465.2MiB / 750MiB     62.03%              56.1GB / 7.56GB     102kB / 0B          33
ede36c43decd        rssant-harbor-1     15.77%              437MiB / 750MiB       58.27%              56.8GB / 7.62GB     171MB / 20.5kB      33
ea467498ede5        rssant-scheduler    2.57%               87.75MiB / 500MiB     17.55%              328MB / 2.78GB      5.85MB / 0B         33
3a617ac14ad3        rssant-postgres     1.18%               39.31MiB / 500MiB     7.86%               19.8GB / 377GB      2.47TB / 89.2GB     24
6cb8c642ad1e        rssant-prometheus   0.05%               47.02MiB / 200MiB     23.51%              559GB / 6.07GB      190GB / 19.9GB      11
3ea7a652f116        rssant-grafana      0.03%               15.09MiB / 200MiB     7.54%               289MB / 187MB       812MB / 515MB       15

整个系统最繁忙的是 rssant-worker 这个组件,即耗CPU又吃内存,运行几周后偶尔还会OOM,本次优化的就是这个组件。 这个性能问题由来已久,从最早基于 Celery 的实现到现在自己做的 Actor 系统都有一样的问题。

相关业务和组件

各组件功能如下:

用户添加订阅之后,订阅信息会存到数据库,然后整个系统会定期检查并更新订阅。流程如下:

  1. scheduler 有个定时器,每分钟触发一次,触发后发消息让 harbor 检查订阅。
  2. harbor 收到消息后,去数据库中查询更新时间距现在超过1小时的订阅,把这些订阅的状态设为【更新中】, 然后将订阅的 ID 和 URL 发送给 worker,让 worker 去执行检查。
  3. worker 收到消息,把订阅内容抓下来,解析得到订阅基本信息和所有文章,把结果发给 harbor。
  4. harbor 收到结果,将每篇文章的链接及哈希值和数据库记录比对,将有变化的文章入库。

Worker 内部的流程:

  1. 使用 requests 请求订阅内容,会带上 ETag, Last-Modified 请求头以利用 HTTP 协商缓存。
  2. 订阅抓取之后,使用 feedparser 解析,得到初步结果。
  3. 对结果中的每篇文章内容,用 lxml 做清洗和图片链接替换,用 readability 提取摘要。
  4. 得到干净的内容之后,发送给 harbor 进行入库。
  5. 对一些只有摘要的文章,worker 还会用 aiohttp 重新抓取全文,结果也用 lxml 和 readability 处理。
  6. 对于文章中的图片链接,worker 会用 aiohttp 批量检测防盗链,如有防盗链则做链接替换。

内存性能优化

我很早就关注到内存的问题,也尝试使用 tracemalloc 和 objgraph 等工具去分析,没有太大收获。 结果类似下面这样,有个 FeedParserDict 类型有时增长很多,但很快会被 GC 掉,其他都是内置类型:

>>> objgraph.show_most_common_types(shortnames=False)
builtins.function                           27203
builtins.dict                               22782
builtins.tuple                              16488
builtins.weakref                            6806
builtins.list                               6505
builtins.cell                               5979
builtins.type                               3749
builtins.getset_descriptor                  3183
builtins.builtin_function_or_method         2524
builtins.property                           1852

>>> objgraph.show_growth(shortnames=False)
builtins.list                      8170      +967
builtins.dict                     24400      +625
builtins.tuple                    16926      +213
builtins.method                    1904      +140
feedparser.util.FeedParserDict      208      +139
builtins.Context                    757       +98
builtins.frame                      198       +87
builtins.coroutine                  109       +75
collections.deque                  1030       +60
builtins.weakref                   6955       +50

Worker 中用到了很多库,首先就怀疑 feedparser 有内存泄漏,但我没有证据,本地测试显示内存都回收干净了。

然后将其他模块中也频繁使用的库排除掉,主要有 Django 和 Actor 系统,requests 和 aiohttp 在其他模块也有用到,但使用没那么频繁。而底层的 ssl 因为出现过比较多内存泄漏问题,所有对它特别关注。

最终确定了 6 个嫌疑人: feedparser, lxml, readability, requests, aiohttp, ssl

Worker 中也有不少代码,这些代码也有嫌疑,因此我并不直接测试三方库,而是测 Worker 中与三方库相关的代码。如果测出问题,再排查是使用姿势不对还是三方库自身有问题。

测试步骤:

  1. 从蚁阅数据库导出 10K 个订阅链接,然后开线程池把内容下载保存到磁盘。
  2. 开线程池测试 requests,aiohttp 分别下载这些订阅。每秒钟记录一次内存占用。
  3. 开线程池测试 feedparser,lxml,readability,用本地磁盘的订阅内容作为输入。每秒钟记录一次内存占用。

测试跑完之后,用 Pandas 和 Matplotlib 分析内存占用,结果如下图(横轴时间,纵轴内存占用MB):

先看 3 个订阅解析相关的库,feedparser 有很多毛刺,但整体还是稳定的。

feedparser.png feed-lxml.png feed-readability.png

再看网络请求的库,requests 内存占用非常大,简直要上天。

aiohttp-ssl.png requests-ssl.png

检查一番代码以及 Google 搜了一圈之后,我将用到的 Session 和 Response 对象用完都手动 close 掉,结果如下。

requests-ssl-close-all.png

内存大幅下降,而且也保持稳定了。看来是 Requests 这个库使用姿势不太对。

修复代码,上线。我期待着内存明显下降,然而并没有,监控图表显示内存只降了一点

我仔细排查代码,想到搜索 Celery Memory Leak 时看到的文章提到:

Python不会主动把内存还给操作系统,如果程序执行使用了大量内存,待程序空闲之后 Python 会保留这部分释放的内存,预留给下次使用,所以程序的内存占用就是峰值时的内存占用。

这个表述不完全准确,有些情况 Python 还是会把内存还给操作系统, 这涉及到 Python 的内存管理和内存碎片问题,比较复杂。

对于 Celery,它有个 CELERYD_MAX_TASKS_PER_CHILD 配置项,让程序处理完指定数量的任务后就重启, 这个选项就是为了解决内存占用太大,但实际并没有内存泄漏,只是 Python 预留了内存导致看起来像内存泄漏。

所以要降低内存占用,就需要降低峰值时的内存占用。

我排查代码之后,做了一个优化,在一个大函数里提前释放一些内存:

del parsed, response, parsed_feed  # release memory
... # 下面是一些耗时操作

上线之后,内存又下降了一些,但降的不多。

总结下来,降低内存占用有两个要点:

  1. 减少内存分配,对于大文本,字节流等要避免复制,尽可能 Zero-Copy。
  2. 内存用完尽快回收,缩短对象的生命周期。

蚁阅中大部分内存都在三方库中分配和复制,目前能做的优化不多。

CPU性能优化

Worker 的 CPU 占用居高不下,主要是解析和处理订阅内容比较耗 CPU。

测试步骤:

  1. 使用 feedparser 解析 10K 个订阅,统计 feedparser 执行时间 (feedparser)。
  2. 使用 lxml 和 readability 处理文章内容,统计执行时间 (parse_found)。

测试结果如下,length 为订阅的大小,单位KB,另两列为执行时间,单位毫秒:

>>> print(df.quantile([0.5, 0.9, 0.99, 0.999]))
            length   feedparser  parse_found
0.500    39.429199    80.527544    39.163351
0.900   300.510742   599.925160   288.799524
0.990  1409.133887  3455.563748  1493.881977
0.999  4687.004390  9793.667774  4234.304533

其中 feedparser 占用时间最多,lxml + readability 时间也不少。 订阅体积越大,执行时间也越长。

接着分析 feedparser 的性能,用 pyinstrument 得到一个很直观的图,时间主要花在 resolve_relative_uris_sanitize_html 这两个函数上。

feedparser-performance

经过一番搜索,发现 feedparser 有参数可以禁用这两个函数。

feedparser.RESOLVE_RELATIVE_URIS = False
feedparser.SANITIZE_HTML = False

因为链接处理和 HTML 清洗在 parse_found 中也会做一遍(feedparser 做的不够好), 所以不需要 feedparser 做处理。

改完参数再测一遍,执行时间明显下降:

>>> print(df.quantile([0.5, 0.9, 0.99, 0.999]))
            length   feedparser  parse_found
0.500    39.273438    35.867929    37.057638
0.900   300.033984   135.883141   283.440208
0.990  1401.178672   915.256548  1466.076121
0.999  4695.528279  2557.008664  4030.596158

接下来分析 parse_found 的性能,这个函数会对每篇文章都做 HTML 清洗,链接处理,以及文本摘要。 执行时间 = 文章数量 * 每篇文章处理时间,文章数量在 10 到 100 之间,处理基本是调用 lxml API。

分析发现 lxml 的 fromstringtostring 方法在每一步清洗都会调用,耗时较多。 实际上 fromstring 只需要调用一次,得到 DOM 对象,然后各个清洗步骤都对 DOM 对象操作, 最后用 tostring 将 DOM 对象转成字符串。

另一方面,因为订阅的大部分文章都已经解析过,存在蚁阅数据库了,每次只会有少量文章需要更新。 如果比较哈希值,可以快速跳过没有变化的文章,大幅降低处理时间。

粗略估计,做完这两个优化可以把 parse_found P99 时间降到 100~200ms,而 feedparser 仍然会是瓶颈。

是否可以把 feedparser P99 时间也降到 100~200ms 呢?

花了一些时间把 feedparser 的代码过了一遍,感觉是很难:

  1. feedparser 底层使用 sgmllib 和 xml.sax,通过回调函数(各种 handler)处理 XML 标签。
  2. feedparser 是纯 Python 实现,而 sgmllib 是 C 拓展,这意味着需要频繁在 Python 和 C 之间状态切换。
  3. feedparser 和 sgmllib 都很老了,包含很多兼容性代码,对 Python 3 也没有做优化。

如果用 Golang 会怎么样呢?

我找到了 gofeed,然后选了一个 5MB 的超大订阅测试一下, 发现只要 100 多毫秒! 意味着 P999 是 100 多毫秒,P99 就更低了!

PS: 目前正在学习 Golang,等学好了再来更新!

业务逻辑优化

到目前为止,内存占用降低约 10%,CPU 处理时间降低约 50%。接下来考虑在业务上做优化了。

在前面的分析中可以看到,极少数(1%)订阅消耗了大量资源,可以降低这些超大订阅的检查更新频率。

>>> print(df.quantile([0.5, 0.9, 0.99, 0.999]))
            length   feedparser  parse_found
0.500    39.273438    35.867929    37.057638
0.900   300.033984   135.883141   283.440208
0.990  1401.178672   915.256548  1466.076121
0.999  4695.528279  2557.008664  4030.596158

另外对停更的订阅,更新不频繁的订阅,没人看的订阅,都可以降低检查更新频率。

这就是蚁阅的订阅冻结功能,动态调整检查更新频率,下面是目前的规则:

+------------+----------+------------+----------+
|   冻结时间  |  300k以下 | 300k~1500k | 1500k以上 |
+------------+----------+------------+----------+
|   资讯新闻  |    1H    |     1H     |    3H    |
|   周更博客  |    1H    |     2H     |    9H    |
|   月更博客  |    4H    |     8H     |    9H    |
+------------+----------+------------+----------+

优化效果

CPU性能优化:订阅处理时间缩短了一半。
业务优化:需要检查更新的订阅少了一半。
意外收获:因为业务优化和CPU性能优化,内存分配更少,回收更快,内存占用也大幅下降了。

Grafana 的图表,大约 20:00 上线的:

memory-usage execute-rate execute-time

阿里云的监控图表:

aliyun-monitor

注:凌晨4点的峰值是因为在定时做数据库备份。

(全文完)

Back

留言 - Github Issues | 主题 - The Plain