Я делаю 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

// Та самая функция из gdb
pub 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_socket
pub 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 проектов сэкономить кучу времени и нервов.

Нагрузочный тест Sockudo: два бага в чужом Rust‑коде, которые кладут сервис на ровном месте