Skip to content

Commit d49735b

Browse files
shumvgoloveshumvgolove
committed
smp-server: analyze slow queries
1 parent 2012236 commit d49735b

File tree

1 file changed

+187
-0
lines changed

1 file changed

+187
-0
lines changed

‎plans/slow-queries-analysis.md‎

Lines changed: 187 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,187 @@
1+
# SMP Server Postgres: Slow Query Analysis
2+
3+
Data from three production servers (A, B, C) over a multi-day observation window.
4+
5+
## Verified fixes
6+
7+
### 1. getEntityCounts: replace ③④ with SUM(queue_count)
8+
9+
**Query** (`QueueStore/Postgres.hs:160-167`):
10+
11+
```sql
12+
SELECT
13+
(SELECT COUNT(1) FROM msg_queues WHERE deleted_at IS NULL) AS queue_count, -- full scan
14+
(SELECT COUNT(1) FROM msg_queues WHERE deleted_at IS NULL AND notifier_id IS NOT NULL) AS notifier_count, -- full scan
15+
(SELECT COUNT(1) FROM services WHERE service_role = ?) AS rcv_service_count, -- trivial (<10 rows)
16+
(SELECT COUNT(1) FROM services WHERE service_role = ?) AS ntf_service_count, -- trivial (<10 rows)
17+
(SELECT COUNT(1) FROM msg_queues WHERE rcv_service_id IS NOT NULL AND deleted_at IS NULL) AS rcv_service_queues_count, -- ③ full scan
18+
(SELECT COUNT(1) FROM msg_queues WHERE ntf_service_id IS NOT NULL AND deleted_at IS NULL) AS ntf_service_queues_count -- ④ full scan
19+
```
20+
21+
**Performance**: ~315ms avg, ~2s max, ~2500 calls. #1 slow query by total time (~800s).
22+
23+
**Problem**: 4 full scans of `msg_queues`. No index covers `rcv_service_id IS NOT NULL` or
24+
`ntf_service_id IS NOT NULL` combined with `deleted_at IS NULL`.
25+
26+
**Fix**: Replace ③ and ④:
27+
28+
```sql
29+
COALESCE((SELECT SUM(queue_count) FROM services WHERE service_role = 'M'), 0) AS rcv_service_queues_count,
30+
COALESCE((SELECT SUM(queue_count) FROM services WHERE service_role = 'N'), 0) AS ntf_service_queues_count
31+
```
32+
33+
**Verification**:
34+
- Trigger logic traced for all transitions (NULL→set, change, soft-delete, physical delete) — correct.
35+
- FK `rcv_service_id REFERENCES services(service_id)` guarantees every non-NULL value maps to a row.
36+
- `queue_count + p_change` is atomic under READ COMMITTED — concurrent-safe.
37+
- `update_all_aggregates()` exists as repair mechanism.
38+
- `services` table has <10 rows — SUM is O(1) vs full table scan.
39+
40+
**Savings**: Eliminates 2 of 4 msg_queues scans. Exact per-subquery cost needs `EXPLAIN ANALYZE`.
41+
42+
---
43+
44+
### 2. expire_old_messages: remove trailing COUNTs
45+
46+
**Stored procedure** (`Migrations.hs`), at the end of `expire_old_messages`:
47+
48+
```sql
49+
r_expired_msgs_count := total_deleted;
50+
r_stored_msgs_count := (SELECT COUNT(1) FROM messages); -- 0.7-1.1s per call
51+
r_stored_queues := (SELECT COUNT(1) FROM msg_queues WHERE deleted_at IS NULL); -- 5-7s per call
52+
```
53+
54+
**Performance**: 10 calls per observation window. These two COUNTs add **5.7-8.1s per call**
55+
to a procedure that takes 7-12s total — they're 50-80% of the cost.
56+
57+
**How results are used** (`Server.hs:485-488`):
58+
59+
```haskell
60+
Right msgStats@MessageStats {storedMsgsCount = stored, expiredMsgsCount = expired} -> do
61+
atomicWriteIORef (msgCount stats) stored -- resets msgCount from storedMsgsCount
62+
atomicModifyIORef'_ (msgExpired stats) (+ expired)
63+
printMessageStats "STORE: messages" msgStats -- logs all three fields
64+
```
65+
66+
- `expiredMsgsCount` — computed incrementally in the loop. **Needed, already cheap.**
67+
- `storedMsgsCount` — used to reset `msgCount` stat. But `msgCount` is also maintained
68+
incrementally (`+1` on send at line 1963, `-1` on ACK at line 1916). The reset corrects drift.
69+
- `storedQueues` — **used only for logging**. Same value available from `getEntityCounts`
70+
which runs every ~60s via Prometheus.
71+
72+
**Fix**: Remove both COUNTs from the stored procedure. Return only `r_expired_msgs_count`.
73+
74+
For `storedMsgsCount`: either trust the incremental `msgCount` counter, or query
75+
`SELECT COUNT(1) FROM messages` separately (in parallel, not blocking the procedure).
76+
77+
For `storedQueues`: use the value from the most recent `getEntityCounts` call.
78+
79+
**Verification**: Traced all usages of `MessageStats` fields from `expireOldMessages` in
80+
`Server.hs`. `storedQueues` is only logged. `storedMsgsCount` resets a counter that's already
81+
maintained incrementally — removing the reset means potential drift, but the counter is
82+
corrected on next server restart anyway.
83+
84+
**Savings**: 5.7-8.1s per expiration cycle × 10 cycles = **57-81s total**.
85+
86+
---
87+
88+
### 3. Trigger WHEN clause: skip function call for non-service updates
89+
90+
**Current trigger** (`Migrations.hs:566-568`):
91+
92+
```sql
93+
CREATE TRIGGER tr_queue_update
94+
AFTER UPDATE ON msg_queues
95+
FOR EACH ROW EXECUTE PROCEDURE on_queue_update();
96+
```
97+
98+
Fires on **every UPDATE** to `msg_queues`. From Server C data, ~1.2M updates per observation
99+
window, but only ~105K (8.7%) actually change service-related fields:
100+
101+
| UPDATE pattern | Calls | Changes service fields? |
102+
|---|---|---|
103+
| SET updated_at | ~427K | No |
104+
| SET msg_can_write/size/expire (write_message) | ~336K | No |
105+
| SET msg_can_write/size/expire (try_del_*) | ~196K | No |
106+
| SET msg_can_write/size/expire (delete_expired) | ~136K | No |
107+
| SET sender_key | ~8K | No |
108+
| SET status | ~2K | No |
109+
| **SET rcv_service_id** | **~101K** | **Yes** |
110+
| **SET deleted_at** | **~5K** | **Yes** |
111+
112+
The `on_queue_update()` PL/pgSQL function evaluates 8-12 boolean conditions on every call,
113+
then returns without calling `update_aggregates` for 91% of invocations.
114+
115+
**Fix**: Add a `WHEN` clause to the trigger definition. PostgreSQL evaluates `WHEN` in C code
116+
before calling the PL/pgSQL function — no function entry overhead at all:
117+
118+
```sql
119+
CREATE TRIGGER tr_queue_update
120+
AFTER UPDATE ON msg_queues
121+
FOR EACH ROW
122+
WHEN (
123+
OLD.deleted_at IS DISTINCT FROM NEW.deleted_at
124+
OR OLD.rcv_service_id IS DISTINCT FROM NEW.rcv_service_id
125+
OR OLD.ntf_service_id IS DISTINCT FROM NEW.ntf_service_id
126+
OR OLD.notifier_id IS DISTINCT FROM NEW.notifier_id
127+
)
128+
EXECUTE PROCEDURE on_queue_update();
129+
```
130+
131+
**Verification**:
132+
- PostgreSQL supports `OLD`/`NEW` in `WHEN` clauses for `AFTER UPDATE` triggers.
133+
- The 4 conditions match exactly the fields checked inside `on_queue_update()`.
134+
- When WHEN is false, the function is **never called** — zero PL/pgSQL overhead.
135+
- When WHEN is true, the function runs identically to today.
136+
- Behavioral change: **none** — same aggregates updated in same cases.
137+
138+
**Savings**: ~1.1M PL/pgSQL function calls avoided. Each call has fixed overhead
139+
(function entry, OLD/NEW row extraction, condition evaluation, return). Exact savings
140+
need measurement, but function call overhead is non-trivial at this volume.
141+
142+
---
143+
144+
## Fixes that need EXPLAIN ANALYZE
145+
146+
### 4. Partial indexes for getEntityCounts ① and ②
147+
148+
Subqueries ① (queue_count) and ② (notifier_count) still do full msg_queues scans.
149+
No existing index covers `deleted_at IS NULL` alone, or combined with `notifier_id IS NOT NULL`.
150+
151+
Candidate indexes:
152+
153+
```sql
154+
-- For ① queue_count: enables index-only COUNT
155+
CREATE INDEX idx_msg_queues_live ON msg_queues ((1)) WHERE deleted_at IS NULL;
156+
157+
-- For ② notifier_count: enables index-only COUNT
158+
CREATE INDEX idx_msg_queues_live_notifier ON msg_queues ((1)) WHERE deleted_at IS NULL AND notifier_id IS NOT NULL;
159+
```
160+
161+
**Trade-off**: Each index adds write overhead on every INSERT/UPDATE/DELETE touching the
162+
filtered columns. Need `EXPLAIN ANALYZE` to confirm the COUNT actually uses the index
163+
(PostgreSQL may choose seq scan if the partial index covers most rows).
164+
165+
---
166+
167+
## Not fixable (architectural)
168+
169+
- **write_message / try_del_peek_msg max times (490-523ms)**: Lock contention on
170+
`FOR UPDATE` of the same `recipient_id` row. Inherent to concurrent queue access — cannot
171+
use `SKIP LOCKED` because these operations require the lock for correctness.
172+
173+
- **UPDATE msg_queues SET updated_at (~430K calls, 83-90s total, 0.20ms avg)**: Per-call cost
174+
is already minimal. Trigger does zero aggregate work for this pattern (verified — all
175+
IS DISTINCT FROM checks fail, no `update_aggregates` called). Fix #3 eliminates even
176+
the function call overhead.
177+
178+
---
179+
180+
## Summary
181+
182+
| # | Fix | Before | After | Verified |
183+
|---|-----|--------|-------|----------|
184+
| 1 | getEntityCounts ③④ → `SUM(queue_count)` | ~315ms/call (4 full scans) | ~160-215ms/call (2 full scans + 2 trivial) | Yes |
185+
| 2 | Remove trailing COUNTs from expire_old_messages | 7-12s/call (50-80% is COUNTs) | 1.5-4s/call (actual expiration work only) | Yes |
186+
| 3 | Add WHEN clause to tr_queue_update | ~1.2M PL/pgSQL calls (91% no-op) | ~105K PL/pgSQL calls (only when needed) | Yes |
187+
| 4 | Partial indexes for ①② | ~160-215ms/call (2 full scans remain) | Needs EXPLAIN ANALYZE | No |

0 commit comments

Comments
 (0)