doc: P1.2 сделан — результаты, найденный дефект (утечка per-queue блокировки) и прогоны тестов
This commit is contained in:
Repinoid
@@ -0,0 +1,111 @@
|
||||
# История правок shared-sqs — 2026-10-07 (P1.2 + фикс утечки блокировки)
|
||||
|
||||
> Запись по требованию «документировать всё, включая собственные ошибки».
|
||||
> Предыдущие записи: `doc/thinking/*-2026-10-0[56].md`, `HISTORY/2026-08-1*-session-log.md`.
|
||||
|
||||
## 1. Задача
|
||||
|
||||
Пользователь: «доделать ПОЛНОСТЬЮ и протестировать SQS». Незакрытым по плану
|
||||
`plan-for-flash-2026-10-05.md` оставался единственный пункт — **P1.2
|
||||
(индексация сообщений)**, отложенный 2026-10-06 с обоснованием.
|
||||
|
||||
## 2. Что сделано
|
||||
|
||||
### 2.1. Дизайн (коммит `b58e958`)
|
||||
|
||||
`doc/thinking/p1.2-message-index-design-2026-10-07.md`.
|
||||
|
||||
Ключевое решение: **tombstone + индексы + амортизированная компакция**.
|
||||
Удаление не сдвигает срез (O(1)), поэтому индексы `receipt→index` и `uuid→index`
|
||||
остаются валидными. Физическая чистка — `Compact`/`CompactIfNeeded` в `processQueueTick`.
|
||||
Redis-схема не меняется (сообщения и так лежат в per-message HASH).
|
||||
|
||||
### 2.2. Код (коммит `22e9bc8`)
|
||||
|
||||
- `models.Queue`: `deadIdx`, `receiptIdx`, `uuidIdx`, `liveCount`, `deadCount` (все `json:"-"`)
|
||||
+ примитивы: `AppendMessage`, `RemoveIndex`, `Compact`, `CompactIfNeeded`, `Reset`,
|
||||
`EnsureIndexes`/`RebuildIndexes`, `IndexOfReceipt`, `IndexOfUUID`, `MarkInFlight`,
|
||||
`ClearInFlight`, `InFlightIndexes`, `IsDead`, `LiveCount`.
|
||||
- `DeleteMessage` / `ChangeMessageVisibility(±Batch)` — поиск по индексу вместо скана среза;
|
||||
удаление без сдвига остатка.
|
||||
- `DeleteMessageBatch` — tombstone вместо полной пересборки среза.
|
||||
- `processQueueTick` — visibility/DLQ по индексу in-flight (O(in-flight)), retention — через
|
||||
tombstone, в конце — `CompactIfNeeded`.
|
||||
- send-пути — `AppendMessage`/`LiveCount`; admin/metrics/persistence — учёт живых сообщений;
|
||||
`LoadAllQueues` — `RebuildIndexes` после загрузки.
|
||||
|
||||
### 2.3. Тесты (коммиты `e05af04`, `5b3fb51`)
|
||||
|
||||
- `app/models/message_index_test.go` — 6 тестов примитивов (tombstone, компакция, индексы, Reset, порог).
|
||||
- `app/gosqs/delete_middle_test.go` — удаление СЕРЕДИНЫ очереди через API: остальные не теряются,
|
||||
удалённое не возвращается.
|
||||
- `app/gosqs/tenant_flow_test.go` — существующие тесты переведены на `LiveCount()`; добавлен
|
||||
`TestReceiveEmptyQueue_DoesNotLeakLock`.
|
||||
|
||||
## 3. НАЙДЕННЫЙ ДЕФЕКТ (моя регрессия) — утечка per-queue блокировки
|
||||
|
||||
### 3.1. Проявление
|
||||
|
||||
Стресс (2000 сообщений × циклы): `ReadTimeout`, всплеск 1.9 с на `delete_batch`,
|
||||
дальше — зависание сервиса (health при этом отвечает).
|
||||
|
||||
### 3.2. Диагностика (факты, не догадки)
|
||||
|
||||
- Снят стек горутин по `SIGQUIT`: десятки горутин в `sync.RWMutex.RLock`
|
||||
(`models.go:101 Queue.RLockMu`), включая `metrics.updateGauges` (ждала 15 минут)
|
||||
и HTTP-хендлеры `GetQueueAttributesV1`.
|
||||
- Аудит всех `GetLocked`/`GetRLocked`: дефект ровно один.
|
||||
- `receive_message.go`:
|
||||
```go
|
||||
queue := models.SyncQueues.GetLocked(key) // Lock взят
|
||||
if queue == nil || queue.LiveCount() == 0 {
|
||||
return nil, false // ← возврат БЕЗ Unlock
|
||||
}
|
||||
defer queue.UnlockMu()
|
||||
```
|
||||
|
||||
### 3.3. Причина и почему проявилось именно сейчас
|
||||
|
||||
Возврат до `defer` оставлял `queue.mu` захваченным навсегда (в Go мьютекс не
|
||||
освобождается при выходе из функции). Прежнее условие `len(queue.Messages) == 0`
|
||||
срабатывало только на полностью пустой очереди; после перехода на tombstone
|
||||
появился новый случай `LiveCount()==0` при `len(Messages)>0` (все сообщения удалены,
|
||||
компакция ещё не прошла) — типовой для последовательных циклов «залить → выгрести».
|
||||
|
||||
### 3.4. Фикс
|
||||
|
||||
`defer queue.UnlockMu()` — до любой проверки/возврата. Регрессионный тест
|
||||
`TestReceiveEmptyQueue_DoesNotLeakLock` проверен на дефекте (падает за 2 с)
|
||||
и на фиксе (зелёный).
|
||||
|
||||
## 4. Результаты проверок (после фикса)
|
||||
|
||||
| Проверка | Результат |
|
||||
|---|---|
|
||||
| `go build ./...`, `go vet ./...` | OK |
|
||||
| `go test -race ./app/...` | зелёные |
|
||||
| `tests/api_test.sh` (aws CLI, локальный сервис) | PASS=22 FAIL=0 |
|
||||
| `tests/sdk_test.py` (boto3 1.43.108) | PASS=15 FAIL=0 |
|
||||
| `tests/fifo_dlq_probe.py` | fifo_order / fifo_dedup / dlq = PASS |
|
||||
| Стресс 3×2000 (send-batch → receive → delete-batch) | send ≈0.6 с, drain ≈1.2 с на цикл, `left=0/0`, вызовов >0.5 с нет |
|
||||
|
||||
## 5. Инфраструктурные заметки (для повторного прогона)
|
||||
|
||||
- Локальный сервис: `SHARED_SQS_SEED_DEMO=true /tmp/shared-sqs --admin-token=... --port=4100`
|
||||
(memory-only без `REDIS_ADDR`; креды демо-тенанта печатаются в лог при старте).
|
||||
- `boto3` в системе НЕ установлен (PEP 668) и `python3.12-venv` отсутствует →
|
||||
wheels скачаны через `pip download` и распакованы в `/tmp/sqlibs_unpacked`,
|
||||
запуск с `PYTHONPATH=/tmp/sqlibs_unpacked`.
|
||||
- Лимит очередей тенанта — 10: падавшие скрипты оставляют очереди, перед прогоном
|
||||
чистить (`aws sqs delete-queue`).
|
||||
- `ENDPOINT` (api_test.sh) и `ENDPOINT_URL` (python-тесты) — разные имена переменных.
|
||||
|
||||
## 6. Уроки
|
||||
|
||||
1. Стресс-проверка обязательна: api/sdk/fifo проходили и с дефектом, он проявлялся
|
||||
только на циклах полного опустошения очереди.
|
||||
2. `SIGQUIT` — быстрый и точный способ найти зависание (кто держит мьютекс), дешевле догадок.
|
||||
3. При замене условия на новый критерий (`len` → `LiveCount`) надо перечитывать
|
||||
весь блок, включая порядок `defer` — старый код содержал латентную утечку лока,
|
||||
которую новый критерий сделал массовой.
|
||||
4. Не запускать сервис с `| head` — SIGPIPE убивает процесс на середине теста.
|
||||
@@ -77,3 +77,12 @@ O(1): удаление из середины среза сдвигает все
|
||||
затрагивает сериализацию и все пути — крупная рискованная правка с маргинальной
|
||||
выгодой на текущих объёмах. Отложено до появления реальной нагрузки/лимитов.
|
||||
|
||||
## P1.2 — СДЕЛАНО (2026-10-07)
|
||||
|
||||
Возврат к пункту по прямому указанию. Решение — tombstone + receipt/uuid-индексы
|
||||
+ амортизированная компакция (удаление НЕ сдвигает срез → индексы стабильны,
|
||||
O(1)-удаление без смены контейнера и без изменения Redis-схемы).
|
||||
Дизайн и результаты: `p1.2-message-index-design-2026-10-07.md`.
|
||||
По ходу найден и исправлен дефект утечки per-queue блокировки в receive
|
||||
(возврат до `defer UnlockMu`) — см. там же, раздел 6.
|
||||
|
||||
|
||||
@@ -95,3 +95,60 @@ get_queue_attributes}.go`, `app/admin/admin.go`, `app/metrics/gauge_updater.go`,
|
||||
2. visibility-перерасчёт в тике идёт по числу in-flight, не по размеру очереди.
|
||||
3. Все существующие тесты зелёные; добавлены тесты на tombstone/компакцию.
|
||||
4. Redis-схема не изменилась; рестарт не «воскрешает» удалённые сообщения.
|
||||
|
||||
## 6. РЕАЛИЗОВАНО (2026-10-07) — и найденный по ходу дефект
|
||||
|
||||
Коммиты: `22e9bc8` (код), `e05af04` (тесты примитивов), `5b3fb51` (фикс ниже).
|
||||
|
||||
### 6.1. Найденный дефект (МОЯ РЕГРЕССИЯ) — утечка per-queue блокировки
|
||||
|
||||
При переводе `receiveMessagesUnderLock` на `LiveCount()` я сохранил исходный
|
||||
порядок строк:
|
||||
|
||||
```go
|
||||
queue := models.SyncQueues.GetLocked(key) // взяли Lock
|
||||
if queue == nil || queue.LiveCount() == 0 {
|
||||
return nil, false // ← возврат БЕЗ Unlock
|
||||
}
|
||||
defer queue.UnlockMu()
|
||||
```
|
||||
|
||||
Возврат на «пустой» очереди оставлял `queue.mu` захваченным НАВСЕГДА: любой
|
||||
последующий `Lock`/`RLock` этой очереди ждал вечно (в Go мьютекс не
|
||||
освобождается при выходе из функции).
|
||||
|
||||
Почему стало заметно именно сейчас: раньше условие было `len(queue.Messages) == 0`
|
||||
и срабатывало только на полностью пустой очереди; после перехода на tombstone
|
||||
добавился новый случай — «все сообщения удалены, но срез ещё не компактирован»
|
||||
(`LiveCount()==0` при `len(Messages)>0`), который в стресс-сценарии возникает
|
||||
на каждом цикле.
|
||||
|
||||
Диагностика (без гаданий):
|
||||
- симптом: `ReadTimeout` при нагрузке 2000 сообщений, единичные всплески ~1.9 с на `delete_batch`;
|
||||
- снят стек горутин по `SIGQUIT` → десятки горутин в `sync.RWMutex.RLock` на `Queue.RLockMu`
|
||||
(`models.go:101`), включая `metrics.updateGauges`; HTTP-хендлеры `GetQueueAttributesV1` — там же.
|
||||
- аудит всех `GetLocked`/`GetRLocked` показал: дефект ровно один — в `receive_message.go`.
|
||||
|
||||
Фикс (`5b3fb51`): `defer queue.UnlockMu()` — ДО любой проверки/возврата.
|
||||
Регрессионный тест `TestReceiveEmptyQueue_DoesNotLeakLock` (на дефекте падает
|
||||
за 2 с, на фиксе — зелёный).
|
||||
|
||||
### 6.2. Результаты проверок
|
||||
|
||||
| Проверка | Результат |
|
||||
|---|---|
|
||||
| `go build ./...`, `go vet ./...` | OK |
|
||||
| `go test -race ./app/...` | зелёные (admin, models, gosqs) |
|
||||
| `tests/api_test.sh` (aws CLI, локальный сервис) | **PASS=22 FAIL=0** |
|
||||
| `tests/sdk_test.py` (boto3) | **PASS=15 FAIL=0** |
|
||||
| `tests/fifo_dlq_probe.py` | **fifo_order/fifo_dedup/dlq = PASS** |
|
||||
| Стресс 3×2000 сообщений (send-batch → receive → delete-batch) | send ≈0.6 с, drain ≈1.2 с на цикл; `left=0/0`; ни одного вызова >0.5 с |
|
||||
|
||||
Стресс подтверждает и отсутствие «протечки» tombstone: после каждого цикла
|
||||
очередь возвращается к 0 живых (`CompactIfNeeded` в тике работает).
|
||||
|
||||
### 6.3. Замечание
|
||||
|
||||
В первом прогоне api/sdk/fifo уже проходили (22/22, 15/15, PASS×3) — то есть
|
||||
дефект проявлялся не на каждом сценарии, а на последовательных циклах полного
|
||||
опустошения очереди. Поэтому стресс-проверка была обязательной.
|
||||
|
||||
Reference in New Issue
Block a user