Tubi 是一个流媒体服务平台，有成千上万的用户每天通过这个平台免费观看他们喜爱的电影、电视剧。每当一位用户按下「播放」按钮，Tubi 的视频播放器就会向一个内部服务发送 API 请求以获取视频的 manifest 文件。这个内部服务会从 AWS S3 抓取 manifest 文件，并基于当前的请求参数对文件内容做一定的修改，最终将修改好的文件返回给视频播放器。
显然，这个 API 请求对用户的观看体验来说是至关重要的，我们希望保证这个 API 的性能。根据我们的内部数据，这个 API 服务的 P99 一直在 400 毫秒上下浮动。由于对文件的修改逻辑相对简单，我们怀疑这个 API 的性能瓶颈是发向 AWS S3 的网络请求（这个假设也被我们在本地开发机上的 benchmark 验证过了）。
因此，我们决定给这个服务加上一层 Redis Cache。
但是，当我们部署好 Redis，并为 50% 的访问流量启用了 Redis Cache 之后，P99 并没有如我们期望的那样降低，反而还升高了 100 毫秒。这显然不符合我们的预期，于是我们开始进一步研究。最终，我们修复了一个潜藏在 Elixir 代码库里 7 年的性能问题，将 API 的 P99 从 500 毫秒减少到了 10 毫秒。
这篇文章，就是对这一次有趣的 debug 经历的总结。从中你能了解到我们逐步定位到问题的过程、所用的工具、以及最终的解决方案。
深入调查
一开始，我们以为是 CPU 使用率的升高导致了 P99 升高。因为在我们 Cache 实现里，缓存的内容会在存储/读取时进行压缩/解压操作，以减少 Redis 的存储开销。这里我们在写入 Redis 时用到了 Erlang 的 :erlang.term_to_binary/2 函数，并传入 :compressed 参数进行压缩；在读取 Redis 时使用 :erlang.binary_to_term/1 自动解压。这个小技巧我们在之前的服务中就曾成功使用过。这些操作理论上是会消耗更多的 CPU 资源。而且我们也确实观察到 CPU 的使用率在启用 Cache 后从 ~30% 升高到了 ~40%。但是即使有 10% 的 CPU 损耗，以 BEAM 虚拟机强大的并发能力，我们依然不相信这就是导致 P99 升高 100 毫秒的原因。因此，我们继续探索其他的原因。
接下来，我们注意到一个很特别的现象：虽然请求延迟的 P99 和平均值增大了，但是延迟的中位数（P50）却减小了。这意味着在启用 Cache 之后，之前本就能快速处理的请求变快了，而之前处理速度慢的请求变得更慢了。这意味着请求 AWS S3 可能并不是我们服务的瓶颈，而是别的环节。
为了定位这个隐藏着的瓶颈，我们又做了一次测量分析。这一次，我们在有着真实请求的生产服务器上跑了一次eprof[1]。以下是这次测量的结果：
从这个结果我们可以看出：有 89.60% 的 CPU 时间都花在了这个 Regex.precompile_replacement/1 函数上。而且在每个 Erlang 进程的分析结果中， Regex.precompile_replacement/1 总是花费 CPU 时间最多的那个函数，占比从 30%~90% 不等。研究 Elixir 的 Regex 模块之后，我们发现这个函数只在 Regex.replace/4 里调用，而这也正是我们用来更新 manifest 文件内容的函数。
至此，P99 延迟和平均延迟升高，但中位数降低的谜团终于解开了：对某些不需要更新 manifest 文件内容的请求，它们并不用调用 Regex.replace/4 函数，因此 S3 的网络请求确实是它们的性能瓶颈。启用 Redis Cache 能够提高这些「快」请求的性能，降低延迟。而对某些需要更新 manifest 文件内容的请求，更新文件内容的时间远高于 S3 网络请求的时间，因此它们的性能瓶颈实则是对文件内容的更新操作。而启用 Redis Cache 导致了更新一些大文件内容的性能变慢了 100 毫秒，比 AWS S3 网络请求的几十毫秒多了一个量级，因此导致了 P99 和平均延迟的升高。
追根溯源
确定了 Regex.replace/4 正是慢请求的瓶颈之后，我们又开始了新一轮的优化。此时的我们还不知道，真正的性能问题藏在 Elixir 的 Regex 模块里。出于对 Elixir 项目本身的信任，我们以为 Regex.replace/4 的调用本身就是一个耗时的操作。因此，我们还只是打算通过其他的方式重写修改 manifest 文件内容的逻辑，避免调用 Regex.replace/4，以此达到优化性能的目的。
我们首先用Benchee [2] 配置了一个 benchmark 脚本。这个脚本会用不同版本的实现去处理同一个 manifest 大文件，对比判断不同版本的性能优化效果。原始的版本 P99 大约为 100 毫秒。但巧合的是，我们第一次选取的 manifest 大文件中并没有任何需要替换更新的内容。按理说我们只需要遍历读取一个 40KB 的文本文件，不应该花费 100 毫秒。因此，一个很自然的优化就是在调用 Regex.replace/4 之前先调用 Regex.match?/2 确认是否存在需要替换的内容。仅仅应用了这个优化，我们就将这个函数的性能提高了几乎 100 毫秒。而对那些约有 50% 内容需要替换的 manifest 文件，性能提高了大约 50 毫秒。
至此，我们的优化之旅就算告一段落了。我们本打算用更复杂的解决方案（比如nimble_parsec [3]） 来解析、更新 manifest 文件。但是一个简单的 Regex.match?/2 检查就让这个 API 的性能达到了我们的预期，这些复杂的方案也就显得有点得不偿失了。
但还是有一些问题困扰着我们：为什么 Elixir 的 Regex 模块没有自带这个显而易见的优化呢？Erlang re 模块中的 :re.replace 函数会有类似的问题吗？于是我们又用 :re.replace 将相同的逻辑实现了一遍，其结果和带有 Regex.match?/2 优化的 Elixir 版本相同。也就是说 Elixir 的 Regex.replace/4 函数确实存在着性能问题，在不需要替换内容时会花费不必要的 CPU 时间。
研究了 Elixir 源码之后，我们发现 Elixir 确实检查了是否存在需要替换的内容。但是在检查之前，Elixir 又调用了 Regex.precompile_replacement/1[4] 这个函数，导致了不必要的 CPU 资源浪费。这跟我们使用 eprof 测量的结果是一致的。
而 Erlang 的 re 模块则没有类似 precompile_replacement 的逻辑 [5]。在没有需要替换的内容时，:re.replace 就不会做任何额外的操作消耗 CPU 时间。
在确认了这确实是一个 Elixir 的 bug 之后，我们马上提交了一个 PR 修复这个问题：Speed up Regex.replace/4 when there is no match by dsdshcym · Pull Request #10500 · elixir-lang/elixir [6].
（注意到这个 PR 在 10 分钟之内就被 merge 了。）
总结回顾
虽然最后的解决方案非常简单，但我们依然从这次有趣的 debug 经历中学到了很多：
在真实环境下用真实的数据测试得到的结果才是最可靠的我们最初测试这个 API 的性能时用的是我的 MacBook Pro。结果确实印证了我们一开始的假设：AWS S3 的网络请求是瓶颈。但是生产环境的情况和我本地的情况完全不同。如果我们没有在真实的服务器上跑 eprof 测试，我们很难发现性能问题的真正瓶颈。 真正的瓶颈往往要用最大的数据来测试才能发现我在本地测试时犯的第二个错误是使用了一个简单的 manifest 文件测试。而正如我们在 debug 过程中发现的：其实有两类请求，一类是 CPU 密集型，而另一类才是 I/O 密集型。真正的瓶颈藏在 CPU 密集型请求（复杂大文件）中。后期使用大文件配合 Benchee 来测试帮助我们迅速找到了问题所在。 贡献回上游的开源社区回到这个略显“标题党”的题目来说，这个 Regex.replace/4 的性能问题在这个函数被引进之初就存在了，也就是 7 年之前。我们也好奇为什么这个问题一直没有被修复。我们的猜测是还没有人在这样一个量级调用过 Regex.replace/4：在一次 API 请求周期里反复调用上千次。这就更说明了将这些发现、修复贡献回上游开源社区的重要性：其他人今后就不会被相同的问题影响到。而且，向 Elixir 贡献 PR 可能是一个开发者能享受到的最好的开源体验：10 分钟不到，你的代码就被合并进主干分支了。
如果使用 Elixir 去处理上千 QPS 的业务逻辑让你心动了，那就赶快加入 Tubi 吧！在 Tubi，你将和我们一起使用 Elixir 去保证千万用户的在线视频体验！
作者：Yiming Chen, Tubi Senior Tech Lead
加入 Tubi 和 Yiming 做同事吧！
精彩链接
发表评论