Я делаю NotiBox — Pusher‑совместимый сервис realtime уведомлений. Под капотом я использую Sockudo — WebSocket сервер на Rust. Прежде чем показывать реальным пользователям, я решил проверить, на сколько Sockudo на самом деле «blazingly fast».
Я ожидал, что это будет лёгкая прогулка, типичное тестирование нагрузки. Даёшь мало ресурсов серверу, запускаешь бенчмарк, видишь что он захлёбывается запросами в какой‑то момент, и фиксируешь показатели.
Идеальный сценарий — полная загрузка процессора, памяти или сети, тогда ты реально нашёл предел ресурсов. Проверяешь масштабируемость и готово.
Другой сценарий — ничего не перегружено, но новые соединения/запросы не проходят, растёт задержка ответов. Это тоже ожидаемо и понятно как чинить: смотришь на TIME WAIT сокеты, max open files, и другие «предохранители».
А что делать, если там тоже всё по нулям? Вот тут начинается настоящее приключение.
Почему Sockudo?
Я рассматривал несколько вариантов:
-
Centrifugo — хорошее решение, но у них свой протокол.
-
Socket.IO — пришлось бы писать обёртку и JS далеко не такой эффективный по ресурсам сервера как Rust.
-
Yandex Cloud — можно собрать Serverless WebSocket сервис, но там куча подводных камней, которые тянут на отдельную статью.
-
Sockudo — написан на Rust, поддерживает Pusher API.
Я делаю именно Pusher‑совместимый сервис, чтобы можно было использовать готовые библиотеки и примеры кода, поэтому решил использовать Sockudo.
Как тестировал?
Я написал бенчмарк‑клиент на go, который постепенно увеличивал количество соединений за несколько волн нагрузки. В каждой волне сначала устанавливались все соединения последовательно с заданной скоростью. Потом в каждом соединении отправлялось фиксированное количество запросов в минуту с рандомным смещением по времени.
Sockudo вместе с моим сервисом были запущены на сервере с 1 vCPU и 2 GB RAM. Хотелось понять как себя поведёт система с небольшими ресурсами и сколько ресурсов тратится на одно соединение.
Первый баг
Я ожидал, что сервер сможет без проблем выдержать 5000 соединений, поэтому запустил такой бенчмарк просто для проверки системы в целом:
./bench -app-id APP_ID \ -app-key APP_KEY \ -app-secret APP_SECRET \ -host ws.notibox.ru \ -tls=true \ -steps 10,50,100,500,1000,5000 \ -step-dur 3m \ -conn-rate 100 \ -pub-interval 60s
Здесь:
-
app-id,app-key,app-secret— ключи приложения, к которому подключается бенчмарк -
steps— количество подключений на каждом шаге нагрузки -
step-dur— длительность каждого шага -
conn-rate— количество устанавливаемых в секунду подключений при старте нового шага -
pub-interval— задержка между отправкой сообщений внутри каждого соединения
По началу всё было хорошо, но потом, без явных проблем с нагрузкой, новые сообщения просто перестали проходить. Обратите внимание на колонку recv:
══ Step 2: 10 → 50 pairs ══[11:49:51] step 2 target=50 active=50 dropped=0 pub=42 recv=42 (100%) lat p50=14ms p95=14ms p99=14ms[11:50:06] step 2 target=50 active=50 dropped=0 pub=46 recv=46 (100%) lat p50=14ms p95=16ms p99=16ms[11:50:21] step 2 target=50 active=50 dropped=0 pub=48 recv=48 (100%) lat p50=14ms p95=16ms p99=16ms[11:50:36] step 2 target=50 active=50 dropped=0 pub=50 recv=50 (100%) lat p50=14ms p95=16ms p99=16ms[11:50:51] step 2 target=50 active=50 dropped=0 pub=60 recv=60 (100%) lat p50=14ms p95=16ms p99=16ms[11:51:06] step 2 target=50 active=50 dropped=0 pub=77 recv=77 (100%) lat p50=14ms p95=15ms p99=16ms[11:51:21] step 2 target=50 active=50 dropped=0 pub=88 recv=88 (100%) lat p50=14ms p95=15ms p99=16ms[11:51:36] step 2 target=50 active=50 dropped=0 pub=100 recv=100 (100%) lat p50=14ms p95=15ms p99=16ms[11:51:51] step 2 target=50 active=50 dropped=0 pub=110 recv=110 (100%) lat p50=14ms p95=15ms p99=16ms[11:52:06] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:52:21] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:52:36] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:52:51] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:53:06] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:53:21] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:53:36] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:53:51] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:54:06] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:54:21] step 2 target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms[11:54:36] step 2 end target=50 active=50 dropped=0 pub=125 recv=125 (100%) lat p50=14ms p95=15ms p99=16ms error rate this step: 0.0% ✓ passed
На строчке [11:52:06] счётчик сообщений завис на совсем, но никаких ошибок не было. Оказывается в бенчмарке был баг, я забыл залогировать ошибки при отправке сообщений, так что пришлось чинить и запускать заново. После перезапуска стало понятно, что срабатывает rate limiter в Sockudo:
══ Step 2: 10 → 50 pairs ══[12:34:18] step 2 target=50 active=50 dropped=0 pub=42 pubErr=0 recv=42 (100%) lat p50=14ms p95=14ms p99=14ms...[12:36:18] step 2 target=50 active=50 dropped=0 pub=108 pubErr=0 recv=108 (100%) lat p50=14ms p95=15ms p99=23ms ERR: publish err (id=38): [HTTP 429] body="{\"error\":\"Too Many Requests\",\"message\":\"Rate limit exceeded. Please try again later.\"}" ERR: publish err (id=39): [HTTP 429] body="{\"message\":\"Rate limit exceeded. Please try again later.\",\"error\":\"Too Many Requests\"}" ERR: publish err (id=5): [HTTP 429] body="{\"error\":\"Too Many Requests\",\"message\":\"Rate limit exceeded. Please try again later.\"}"...[12:39:03] step 2 end target=50 active=50 dropped=0 pub=121 pubErr=129 recv=121 (48%) lat p50=14ms p95=15ms p99=23ms error rate this step: 51.6%⚠ Error rate 51.6% ≥ threshold 5% at 50 pairs — this is the limit.
Но это было очень странно для rate limiter, потому что сообщения вообще перестали проходить на всё оставшееся время бенчмарка. И математика не сходилась. Стандартное ограничение должно быть 100 сообщений за минуту со скользящим окном. У меня на втором шаге бенчмарка было всего 50 соединений, каждое с 1 сообщением в минуту = всего 50 запросов в минуту, половина лимита.
Тогда я начал тестировать limiter, чтобы «прощупать» его реальную модель работы. Попробовал сделать 1 сообщение в секунду на соединение, чтобы превысить лимит уже на первом шаге. Я ожидал что limiter остановит меня уже на десятой секунде (10 соединений * 10 секунд = 100 сообщений = лимит), но на удивление бенчмарк проработал примерно 100 секунд без проблем:
══ Step 1: 0 → 10 pairs ══[13:00:47] step 1 target=10 active=10 dropped=0 pub=141 pubErr=0 recv=141 (100%) lat p50=14ms p95=17ms p99=133ms[13:01:02] step 1 target=10 active=10 dropped=0 pub=291 pubErr=0 recv=291 (100%) lat p50=14ms p95=18ms p99=22ms[13:01:17] step 1 target=10 active=10 dropped=0 pub=441 pubErr=0 recv=441 (100%) lat p50=14ms p95=18ms p99=21ms[13:01:32] step 1 target=10 active=10 dropped=0 pub=591 pubErr=0 recv=591 (100%) lat p50=14ms p95=18ms p99=21ms[13:01:47] step 1 target=10 active=10 dropped=0 pub=741 pubErr=0 recv=741 (100%) lat p50=14ms p95=18ms p99=21ms[13:02:02] step 1 target=10 active=10 dropped=0 pub=891 pubErr=0 recv=891 (100%) lat p50=14ms p95=18ms p99=21ms ERR: publish err (id=4): [HTTP 429] body="{\"message\":\"Rate limit exceeded. Please try again later.\",\"error\":\"Too Many Requests\"}" ERR: publish err (id=8): [HTTP 429] body="{\"error\":\"Too Many Requests\",\"message\":\"Rate limit exceeded. Please try again later.\"}"
100 секунд? 100 запросов в минуту лимит? Что‑то тут не так. Я пошёл читать исходники Sockudo. Нашёл, где реализован RedisRateLimiter:
async fn run_sliding_window_check( &self, key: &str, increment: bool,) -> Result<RateLimitResult> { let redis_key = self.get_key(key); ... let _: () = conn .zrevrangebyscore(&redis_key, 0, window_start as i64) .await .map_err(|e| Error::Redis(format!("Failed to clean up Redis sorted set: {e}")))?; ... if increment && allowed { let _: () = conn .zadd(&redis_key, now, now) .await .map_err(|e| Error::Redis(format!("Failed to increment Redis counter: {e}")))?; } ...}
Sockudo использует множества (Sorted Sets) в Redis для сохранения последних запросов, чтобы потом их посчитать и понять, превышен ли лимит. Пока не очень понятно в чём проблема, посмотрим что есть в Redis в то время, когда запущен бенчмарк:
# смотрим какие ключи есть в Redis> redis-cli --scan --pattern '*' "sockudo_rl::rl:api:127.0.0.1" # похоже на наш rate limiter"sockudo_rl::rl:websocket_connect:127.0.0.1"# смотрим что в нём лежит> redis-cli ZRANGE 'sockudo_rl::rl:api:127.0.0.1' 0 -1 1) "1785927842" # таймштампы? 2) "1785927843" 3) "1785927844" 4) "1785927845"... 98) "1785927939" 99) "1785927940"100) "1785927941" # 100 последних секунд?
И тут я понял, Sockudo сохраняет не уникальный ID запроса или что‑то подобное, а текущий таймштамп в секундах. Поэтому не важно, много запросов или мало. Если они скучковались в последние 100 секунд и закрыли все секундные слоты, то новые запросы больше не пройдут. Кроме этого, они не исчезали из Redis, видимо в очистке тоже есть баги.
Я более внимательно посмотрел на код и нашёл ровно эти два бага. Первый баг ломает очистку скользящего окна, из‑за чего лимиты накапливаются вечно, пока не сработает EXPIRE. Используется zrevrangebyscore(&redis_key, 0, window_start as i64), а должен использоваться скорее всего zremrangebyscore. Разница в одной букве, наверно опечатка.
Второй баг ломает запись запроса в лимитирующее скользящее окно, потому что пишет zadd(&redis_key, now, now) вместо ID запроса, что уже было видно в логах. Тоже похоже на обычную опечатку.
Создал issues один и два. Мейнтейнер сделал фикс. Потом стало интересно, как этот баг вообще появился, поискал по истории. Самое смешное что в гите есть фикс для одного из багов, но он был перетёрт другим большим комитом. Будьте осторожны с комитами на 44 тысячи изменений:)
Второй баг
Я думал, что осталось только прогнать мои 5000 соединений заново и всё будет работать. К этому моменту у меня уже был дашбоард, где можно было посмотреть на красивые графики нагрузки, что я и делал пока тестировал. Я запустил бенчмарк и увидел такую картину:
На скриншоте каналы и сообщения в реальном времени за последние 30 минут. По графикам видно, что первые два шага прошли отлично: никаких просадок, стабильный поток сообщений. Но на третьем шаге почему‑то всё упало в ноль. А вот что было в бенчмарке:
══ Step 3: 50 → 100 pairs ══[19:20:26] step 3 target=100 active=100 dropped=0 pub=19451 pubErr=0 recv=19451 (100%) lat p50=13ms p95=14ms p99=16ms[19:20:41] step 3 target=100 active=100 dropped=0 pub=20951 pubErr=0 recv=20951 (100%) lat p50=13ms p95=14ms p99=16ms[19:20:56] step 3 target=100 active=100 dropped=0 pub=22451 pubErr=0 recv=22451 (100%) lat p50=13ms p95=14ms p99=16ms[19:21:11] step 3 target=100 active=100 dropped=0 pub=23951 pubErr=731 recv=23220 (51%) lat p50=13ms p95=14ms p99=16ms ERR: dial err (id=101): websocket: bad handshake [HTTP 502] ERR: dial err (id=103): websocket: bad handshake [HTTP 502] ERR: dial err (id=106): websocket: bad handshake [HTTP 502] ERR: dial err (id=104): websocket: bad handshake [HTTP 502]... ERR: read_subscribed err (id=87): read tcp 192.168.1.104:58896->80.78.254.29:443: i/o timeout ERR: read_established err (id=64): read tcp 192.168.1.104:58852->80.78.254.29:443: i/o timeout ERR: read_established err (id=84): read tcp 192.168.1.104:58944->80.78.254.29:443: i/o timeout ERR: read_established err (id=92): read tcp 192.168.1.104:58866->80.78.254.29:443: i/o timeout
Всё намертво встало. Нагрузки на процессор ноль, новые соединения не устанавливаются. Нулевая статистика в дашборде — это на самом деле невозможность получить данные от Sockudo. Сервер умер? Нет, SSH работает. Опять rate limiter? Нет, ошибки другие. Sockudo завис? Похоже на то, к нему вообще не достучаться. Не сработала даже стандартная перезагрузка сервиса через systemctl, пришлось убивать процесс. Какой‑то дедлок?
Почему это происходит так легко именно у меня? Sockudo ведь тестировали? Тестировали, да? Похоже именно мой способ использования как‑то ломает сервер.
Подключаем gdb, чтобы собрать информацию о состоянии потоков в момент зависания. Запускаем бенчмарк ещё раз. Зависает примерно на том же месте, смотрим gdb:
gdb -p 36475 -batch -ex 'set pagination off' -ex 'thread apply all bt' -ex 'detach'
Thread 4 (Thread 0x74d8dedaf6c0 (LWP 36477) "tokio-rt-worker"):#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38#1 0x000056a31ae68099 in dashmap::lock::RawRwLock::lock_exclusive_slow ()#2 0x000056a31b1c948a in <sockudo_adapter::local_adapter::LocalAdapter as sockudo_adapter::connection_manager::ConnectionManager>::add_socket::{{closure}} ()...Thread 3 (Thread 0x74d8de9ad6c0 (LWP 36481) "sockudo-rate-li"):#0 0x000074d91f0ecadf in __GI___clock_nanosleep (clock_id=1, flags=0, req=0x74d8de9aca08, rem=0x74d8de9aca08) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:78#1 0x000056a31b6f51f5 in sockudo_rate_limiter::memory_limiter::SharedLimiterCleanup::spawn_worker::{{closure}} ()...Thread 2 (Thread 0x74d8de3aa6c0 (LWP 43527) "sockudo-adapter"):#0 0x000074d91f0ecadf in __GI___clock_nanosleep (clock_id=1, flags=0, req=0x74d8de3a9a08, rem=0x74d8de3a9a08) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:78#1 0x000056a31b2d7af5 in sockudo_adapter::memory_rate_limiter::SharedLimiterCleanup::spawn_worker::{{closure}} ()...Thread 1 (Thread 0x74d91f997a40 (LWP 36475) "sockudo"):#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38#1 0x000056a31af1e679 in parking_lot::condvar::Condvar::wait_until_internal ()#2 0x000056a31b811990 in tokio::runtime::park::Inner::park ()#3 0x000056a31ab514b0 in sockudo::main ()...
Нас интересует Thread 4. Я сделал несколько трейсов, во всех после зависания повторяется dashmap::lock::RawRwLock::lock_exclusive_slow — наш кандидат на дедлок. Смотрим связанный с ним код:
// namespace.rs// Та самая функция из gdbpub async fn add_socket( &self, socket_id: SocketId, socket_writer: WebSocketWriter, app_manager: Arc<dyn AppManager + Send + Sync>, init: SocketInitOptions,) -> Result<WebSocketRef> { ... self.sockets.insert(socket_id, websocket_ref.clone()); ...}// Описание sockets куда мы делаем вставку в add_socketpub struct Namespace { pub app_id: String, pub sockets: DashMap<SocketId, WebSocketRef>, pub channels: DashMap<String, DashSet<SocketId>>, wildcard_channels: DashSet<String>, pub users: DashMap<String, DashSet<WebSocketRef>>,}
Зависание происходит на структуре DashMap — это ассоциативный массив (HashMap) с безопасным и конкурентным доступом из нескольких потоков. Он разбивает записи на шарды. Каждый шард блокируется независимо.
Но почему происходит дедлок? Кто‑то пытается читать эту же структуру пока add_socket туда пишет? Здесь интересно, что DashMap использует блокировки системных потоков, а большая часть Sockudo использует «легковесные» Tokio потоки. Возможно какой‑то конфликт двух систем асинхронности. Попробуем найти какие‑то места, где есть использование sockets вперемешку с async/await. Оказывается такое есть только в двух почти идентичных местах:
// http_handler.rs/// GET /stats#[instrument(skip(handler), fields(service = "stats"))]pub async fn stats( State(handler): State<Arc<ConnectionHandler>>,) -> Result<impl IntoResponse, AppError> { ... // Read блокировка sockets на всё время итерации for socket in namespace.sockets.iter() { // await блокировка внутри итерации 1 if socket.value().get_user_id().await.is_some() { app_stat.authenticated_connections += 1; } // await блокировка внутри итерации 2 if socket.value().get_connection_meta().await.is_some() { app_stat.connections_with_meta += 1; } } ...}/// GET /apps/:app_id/stats#[instrument(skip(handler), fields(service = "app_stats"))]pub async fn app_stats( State(handler): State<Arc<ConnectionHandler>>, Path(app_id): Path<String>,) -> Result<impl IntoResponse, AppError> { ... // Такое же место в другом обработчике for socket in namespace.sockets.iter() { if socket.value().get_user_id().await.is_some() { app_stat.authenticated_connections += 1; } if socket.value().get_connection_meta().await.is_some() { app_stat.connections_with_meta += 1; } } ...}
Когда цикл идёт по структуре sockets, он постепенно берёт read‑блокировку на каждый шард DashMap и не отпускает его до завершения цикла. А внутри цикла есть await, который может уснуть и отдать управление Tokio. Состояние цикла сохранится в Future вместе с guard‑ом, то есть блокировка не снимется на время сна.
В этот момент может придти новое соединение в add_socket, которое захочет добавиться в sockets, то есть взять write‑блокировку. Мне «повезло», что я тестировал это на 1 vCPU, а значит у Tokio был всего один runtime поток. Получается единственный поток зависнет на системной блокировке и уже никогда не разбудит цикл чтения sockets из app_stats. Это и есть наш дедлок.
Это как раз то место, которое отличает мой способ взаимодействия с Sockudo от большинства других приложений. Мне нужно собирать статистику для дашборда пользователей. Видимо это не самый частый кейс, поэтому плохо протестирован «в бою».
Отключаем чтение статистики — дедлок уходит. Возвращаем, разделяем чтение на два цикла: копирование указателей и чтение вне блокировки — дедлок по прежнему не повторяется. Отправляем pull request в Sockudo.
И наконец‑то любуемся чистым запуском бенчмарка на 5000 соединений:
Заключение
Вместо запланированного вечера с бенчмарками и красивыми графиками получилась пара недель плотной работы: два фикса в Sockudo и вот эта статья. Если бы мне в самом начале сказали, что «лёгкая прогулка» обернётся именно так — не поверил бы. Но ровно поэтому об этом стоит писать.
Баги не всегда в вашем коде, иногда «проверенная» инфраструктура тоже содержит баги. Sockudo — это живой, активно поддерживаемый проект, с тестами и гордым «blazingly fast» в описании. Тем не менее оба найденных бага были самыми настоящими, стабильно воспроизводимыми, и до меня их никто не репортил. Популярность и активная разработка не равны «протестировано именно под ваш паттерн нагрузки». Это стоит перепроверять самому, а не принимать на веру.
Не пихайте костыли, доходите до первопричины. В обоих случаях был огромный соблазн обойти симптом, не разбираясь: поднять лимиты повыше, дёргать /stats пореже, докинуть vCPU или просто перезапускать сервис по таймеру через systemd. Вместо этого пришлось лезть в исходники:
-
До опечатки в одной букве (zremrangebyscore вместо zrevrangebyscore) и неуникального поля в команде zadd (таймштамп вместо ID) в первом баге rate limiter’а.
-
До конфликта блокировок DashMap в двух обработчиках статистики во втором баге.
Оба фикса заняли буквально несколько строк кода и уже смержены в апстрим. Да, разбираться в чужом Rust‑коде дольше, чем накостылить обходной путь у себя локально. Зато так вы поможете всем остальным пользователям open‑source проектов сэкономить кучу времени и нервов.
ссылка на оригинал статьи https://habr.com/ru/articles/1068142/