2024-04-22 - Hub 故障事后分析

自2024年4月22日星期一上午8:45起，Hugging Face Hub 经历了长时间中断。此次事件持续到4月24日星期二上午10:03，服务才完全恢复。事件期间，Hugging Face 网站对于大多数用户来说速度缓慢或无法访问。

这篇博客文章描述了事件的时间线、故障原因以及我们为确保此类事件不再发生所做的更改。

除非另有明确说明，所有时间/日期均以欧洲中部时间（CET）为准。

背景

以下是 Hugging Face Hub 生产环境架构的简单示意图

以及一些相关组件的链接

• Gitaly
• AWS WAF
• MongoDB
• MongoDB Atlas

摘要

4月22日8:45，系统开始出现不稳定，并不断升级，直到4月22日9:30 Hub 变得无响应。

正如我们在 Atlas 指标中看到的，两个只读节点已下线；它们不断重启。

集群曾自动扩容一次，但我们不得不手动扩容到下一层级，这才使集群恢复到某种程度上正常的状态。来自支持案例：

在 24/04/22 - 07:04:24 AM UTC，集群层级开始从 tier 1 增加到 tier 2，集群升级并于 24/04/22 - 07:33:52 AM 恢复到 HEALTHY 状态。

另一次手动自动扩容在 24/04/22 - 12:46:48 PM UTC 触发，将集群提升到 tier 3。

我们注意到来自使用 Java/17 用户代理的内部源流量激增，因此我们在4月22日10:22添加了防火墙规则，以阻止所有使用该用户代理的请求，担心这是原因。虽然这缓解了负载，但并未解决根本问题。

4月22日10:44，我们屏蔽了 Hub 上的快速搜索功能。

Hub 仍然不稳定，尽管数据库看起来是健康的，所以我们尝试扩展 Hub 的 k8s 集群节点，因为我们有一个配置问题，而且它没有自动完成。

4月22日14:26，发布关于事件的推文

4月22日14:50 切换到维护模式并显示 503 页面。这停止了流量，以尝试缓解负载并恢复到正常状态。

4月22日15:00，将所有 Hub 的 pod 缩减到 0。

4月22日15:51，一切恢复正常。

4月23日21:30，Hub 下线

这次连接数和系统内存急剧增加，然后主节点内存溢出（OOMed）。接着，集群更改了主节点，但同样的事情再次发生，集群将原来的主节点选举为新的主节点。

4月23日21:56，我们决定将 Hub 切换到维护模式并阻止所有传入流量。这减轻了数据库上的负载，集群恢复到正常状态。

4月24日8:00，Hub 再次缓慢/无响应。我们看到了与前一晚相同的模式。

4月24日8:12 Hub 缩容到 0 并设置了维护页面。大约在4月24日8:18，我们解除了维护页面，因为一切都稳定了，一切恢复正常。

4月24日10:03，一个可疑的指标显示 Hub 再次宕机，因此我们决定设置一个激进的速率限制，这使得所有指标恢复正常，并且 Hub 没有再次宕机。

随后，流量保持稳定，我们正在清理旧的未使用索引，收集更多关于数据库的指标。以下工具和资源证明非常有用：

• keyhole
• https://github.com/simagix/keyhole/wiki/
• hatchet
• 使用 keyhole 专业查看您的 MongoDB 集群（第一部分）
• 使用 keyhole 专业查看您的 MongoDB 集群（第二部分）
• https://mongodb.ac.cn/community/forums/t/how-to-analyze-mongodb-ram-usage/12108/3

根本原因识别

我们已经检查了所有图表，试图找出问题，但一无所获。在最后一次尝试中，我们决定需要一个按调用 url 分解请求数量的图表，并构建了它。在查看2024年4月23日21:30的第二次崩溃时，我们观察到一个可疑的定时请求。

调用 https://huggingface.co/api/models/sentence-transformers/all-mpnet-base-v2/revision/main 时，我们可以观察到有300多个与该模型相关的空间列表。

在检查 Hub 的 MongoDB 数据库的所有日志和指标时，我们观察到 *_info_cache 集合过度使用：平均延迟很差，网络传出非常高。

请注意，由于停机期间观察到的延迟，响应时间存在偏差。此外，两张截图均来自不同的 MongoDB 副本。

这促使我们认为此调用实际上正在使用 space_info_cache（确实如此），并且可能是数据库过度使用的原因。因此，我们决定进一步调查：我们隔离了该特定请求的 URL，并且该端点流量的增加与数据库网络传出使用量的增加完美关联，而这正是某些崩溃的先兆。

我们最终决定尝试通过运行以下 k6 脚本来重现问题

import http from "k6/http";

export const options = {
  vus: 512,
  duration: '10m',
};

export default function() {
  const response = http.get("https://huggingface.co/api/models/sentence-transformers/all-mpnet-base-v2/revision/main");
}

$ k6 run kill_hub.js

这导致所有上述指标的增加，并且在尝试加载 huggingface.co 时，我们观察到速度变慢或完全无响应。因此我们停止运行脚本以避免破坏 MongoDB 集群。就是这样！

注意：我们运行了脚本3次，分别在4月24日18:05、18:15和最后一次约18:45。

根据我们的观察，第一次崩溃并非由对该 URL 的调用引起，并且在事件发生时查看按 URL 分解的数据时，我们可以看到其他可疑的查询。

在事件发生前，对该调用的请求量大幅增加，鉴于它具有上述调用的一些特性（它使用了 datasets_info_cache，这是对数据库造成显著压力的三个集合之一），我们可以得出结论，这是事件的触发因素。

我们难以通过调用 https://huggingface.co/api/datasets/lighteval/mmlu/revision/main 来重现问题，因为第二天早上 Hub 团队已经做了大量工作来缓解根本原因。

最后，在4月23日晚上的崩溃中，我们看到对同一端点的请求增加。

这些资源密集型请求使数据库处于降级状态。更糟糕的是，我们的 Hub 的 NodeJS 代码在用户取消请求时没有取消请求。这导致了雷暴问题，所有已进行的数据库请求都会继续运行直到完成，即使另一端没有人监听。例如，当页面响应缓慢时，我强制刷新页面，所有正在进行的连接都会继续运行。

所以——粗略估计——如果我们在周一早上有 10 个数据库请求和 5 万用户尝试做某事，并且他们在等待 30 秒后刷新了页面 3 次，那么 MongoDB 在那个时候会比平时多出 2 * 10 * 50000 个请求。这意味着如果我们的数据库状况不佳，即有人对其进行了猛烈冲击，事情就会像滚雪球一样恶化，最终导致崩溃。

缓解/解决方案

为了防止出现连锁反应，我们根据请求的通常完成时间添加了大量的超时。我们还搜索并优化了在事件期间响应时间过长或响应体过大的所有请求。

我们不会详细介绍具体修复了哪些内容，因为有大量的拉取请求已经通过！但简而言之，就是重新设计了设计不佳的数据库查询。

长期解决方案

• 将 *_info_cache 迁移到 Redis。
• 如果客户端中止其请求，则能够中止任何数据库请求。

进展顺利/不顺利之处？

顺利之处

• 提高了我们对系统的理解，使我们能够预测故障并在停机前主动解决问题。
• 我们清理了数据库，其中包括删除了旧索引，提高了效率。
• 我们对数据库的深入检查揭示了架构缺陷和瓶颈，例如一个集合中存在大量未使用的索引。
• 在事件期间构建了新的仪表板和监控指标，这将对未来的监控很有价值。
• 我们学会了哪些指标需要更密切地监控，以预测和防止系统崩溃。
• 许多团队成员参与其中，亲自动手尽快解决问题。

不顺利之处

• 长时间停机
• 花了2-3天时间才找出根本原因。
• 我们同时遭遇了不相关的系统故障，增加了恢复正常运行的压力和难度。

时间线