| … | … | @@ -0,0 +1,227 @@ |
| 1 | # Post-mortem — 2026-08-11 near-death memory spike (tabertron) |
| 2 | |
| 3 | **Status:** diagnosed, root cause confirmed against source. **No fix applied yet.** |
| 4 | **Session ended for machine shutdown.** |
| 5 | |
| 6 | Every number below traces to a command actually run on the box. Items marked |
| 7 | INFERRED were not directly measured. |
| 8 | |
| 9 | --- |
| 10 | |
| 11 | ## 1. What happened |
| 12 | |
| 13 | At **19:13:04–19:14:31** the machine became unresponsive. It did **not** OOM — |
| 14 | `dmesg` contains no `Out of memory` / `Killed process` entries anywhere. Nothing |
| 15 | was killed. The box simply thrashed swap until userspace could not make progress. |
| 16 | |
| 17 | Evidence from the journal, in the window: |
| 18 | |
| 19 | ``` |
| 20 | 19:13:41 dbus-daemon: Failed to activate service 'org.freedesktop.nm_dispatcher': |
| 21 | timed out (service_start_timeout=25000ms) |
| 22 | 19:13:48 Started getty@tty2.service <- TTY switch, consistent with frozen desktop |
| 23 | 19:14:31 NetworkManager-dispatcher.service: Consumed 9.705s CPU time |
| 24 | ``` |
| 25 | |
| 26 | A dispatcher that normally completes in milliseconds burned 9.7 s of CPU and blew |
| 27 | a 25-second dbus activation timeout. Load average measured at 19:16:51 was |
| 28 | **16.14 / 25.90 / 13.46** — the 5-minute figure of 26 is the spike, already receding. |
| 29 | |
| 30 | ### Why it tipped over |
| 31 | |
| 32 | Resident baseline *before* any build, measured directly: |
| 33 | |
| 34 | | Consumer | RSS | |
| 35 | |---|---| |
| 36 | | cogserver | 7.39 GB (+1.1 GB swapped) | |
| 37 | | bare P2P daemons | 6.99 GB (pgh-sidecar alone 5.0 GB) | |
| 38 | | firefox (23 procs) | 2.91 GB | |
| 39 | | 4 concurrent Claude sessions | 1.91 GB | |
| 40 | | Keet + other | 1.24 GB | |
| 41 | | **Total** | **≈ 20.5 GB of 31 GB** | |
| 42 | |
| 43 | At **19:10:11** — three minutes before the freeze — a .NET build round started |
| 44 | (VBCSCompiler PID 1821215, since exited). I measured the equivalent `ifsrenderer-linux` |
| 45 | pear-git CI round that fired at 19:39: **3.1 GB across 8 processes** (testhost alone |
| 46 | 1.45 GB), collapsing back to 0.67 GB within a minute. |
| 47 | |
| 48 | ~20.5 GB resident + ~3 GB transient build + page cache for build I/O against a |
| 49 | 2.6 GB `.git` left nothing. The kernel pushed **1.8 GB into a 2 GB swapfile** and |
| 50 | thrashed. No single process was large enough to trip the OOM killer, which is |
| 51 | precisely why it froze instead of recovering by killing something. |
| 52 | |
| 53 | **INFERRED:** the exact trigger being the 19:10 build specifically. The build's |
| 54 | existence and timing are measured; that it was the final straw is inference from |
| 55 | the 3-minute gap and the measured footprint of the identical 19:39 round. |
| 56 | |
| 57 | --- |
| 58 | |
| 59 | ## 2. Root cause of the largest consumer: cogserver leaks a thread stack per connection |
| 60 | |
| 61 | cogserver was the single biggest consumer at 7.4 GB. **~5.3 GB of that was pure leak.** |
| 62 | |
| 63 | ### The defect, in source |
| 64 | |
| 65 | `opencog-kb/repos/cogserver/opencog/network/NetworkServer.cc:169`, in the accept loop: |
| 66 | |
| 67 | ```cpp |
| 68 | // Create handler thread and track it for proper cleanup. |
| 69 | std::thread* handler_thread = new std::thread(&ServerSocket::handle_connection, ss); |
| 70 | { |
| 71 | std::lock_guard<std::mutex> lock(_handler_threads_mtx); |
| 72 | _handler_threads.push_back(handler_thread); |
| 73 | } |
| 74 | ``` |
| 75 | |
| 76 | Every accepted connection gets a fresh `std::thread`. It is **never detached**, and |
| 77 | is pushed onto `_handler_threads`, an unbounded `std::list<std::thread*>`. The only |
| 78 | code that drains that list is `join_threads()` (line 103), whose own comment states |
| 79 | it exists "to ensure complete shutdown … before serverLoop() returns" — it runs at |
| 80 | **shutdown only**. |
| 81 | |
| 82 | So per connection: |
| 83 | |
| 84 | 1. `new std::thread` → glibc mmaps an **8 MB stack + guard page** (2 VMAs). |
| 85 | 2. `handle_connection()` runs, ends in `delete this` (ServerSocket.cc:450), returns. |
| 86 | 3. Nobody ever joins the thread. glibc **cannot** unmap the stack — `struct pthread` |
| 87 | lives at the top of that very stack and must survive a possible future `pthread_join`. |
| 88 | 4. The kernel task is reaped, so `/proc/<pid>/task` looks normal, but the mapping |
| 89 | stays for the life of the process. |
| 90 | |
| 91 | This is why the process looked self-contradictory: **22 threads, ~345,000 stacks.** |
| 92 | |
| 93 | ### Measured cost per connection |
| 94 | |
| 95 | 100 connect/close cycles against port 17001, sending nothing: |
| 96 | |
| 97 | ``` |
| 98 | VMAs leaked : +192 = 1.92 per connection |
| 99 | RSS leaked : +1.6 MB = 15.9 KB per connection |
| 100 | VSZ leaked : +0.75 GB = 7.68 MB per connection |
| 101 | threads : 22 -> 22 (all handler threads exited) |
| 102 | ``` |
| 103 | |
| 104 | Nothing was reclaimed after settling. Scaled to the 703,009 VMAs the old instance |
| 105 | had reached: ~351,000 leaked stacks → **~5.3 GB of its 7.5 GB RSS**, and a 2.6 TB |
| 106 | VSZ that is 345,000 × 8 MB of untouched stack reservation. |
| 107 | |
| 108 | VMA composition confirmed the shape independently: 340,133 `rw-p` regions averaging |
| 109 | 7.81 MB, each paired with a `---p` guard, 680,468 of 680,512 VMAs adjacent — the |
| 110 | textbook pthread-stack signature. |
| 111 | |
| 112 | --- |
| 113 | |
| 114 | ## 3. What drives the connection rate: knowledge-ratchet |
| 115 | |
| 116 | `knowledge-ratchet/atomspace/cogserver.js` opens a **new TCP connection per Scheme |
| 117 | expression**. `evalScheme()` connects, sends one expression, `sock.destroy()`. No |
| 118 | pooling. Two amplifiers: |
| 119 | |
| 120 | - **`isCogServerUp()` burns an extra connection** as a liveness probe before the real |
| 121 | work, so every caller pays double. |
| 122 | - **Callers loop it.** `query.js` fires 3–5 separate `evalScheme` calls per record |
| 123 | (lines 313–315, 468–475); `ingest.js` and `contrast-rules.js` call it per batch. |
| 124 | |
| 125 | These run from hooks on `SessionStart`, `UserPromptSubmit`, `PostToolUse` and `Stop` |
| 126 | (`.claude/settings.json`), across **4 concurrent Claude sessions**. |
| 127 | |
| 128 | Coupling confirmed empirically: VMA count is **perfectly flat for 42 s inside a |
| 129 | single long tool call** (no hooks firing), then jumps by thousands at each tool-call |
| 130 | boundary. Average over the old instance's life: 345,000 connections / 39,000 s ≈ |
| 131 | **9 connections/second**. |
| 132 | |
| 133 | --- |
| 134 | |
| 135 | ## 4. It is already recurring |
| 136 | |
| 137 | The old cogserver (PID 10580, up since 09:00:35, 703,009 VMAs) **was restarted |
| 138 | independently at 21:02:36** — not by me, and not by any action in this session. |
| 139 | The replacement is PID 2098931, PPid 1, with **no systemd unit** found. |
| 140 | |
| 141 | 65 minutes later that new instance had already reached **27,447 VMAs (~3.5 conn/s)** |
| 142 | and 532 MB RSS. The leak reaccumulates from zero on every restart. Restarting is |
| 143 | symptom relief with a ~10-hour half-life, not a fix. |
| 144 | |
| 145 | --- |
| 146 | |
| 147 | ## 5. Unrelated risks surfaced along the way |
| 148 | |
| 149 | - **AtomSpace has no persistence.** `(cog-get-atoms (quote StorageNode) #t)` returns |
| 150 | `()`. 39,127 atoms live in RAM only. The `RocksStorageNode` type is not even |
| 151 | registered, so the rocks module is not loaded. **The deletion story is unanswered:** |
| 152 | any restart — including the one that already happened at 21:02 — silently discards |
| 153 | the graph, and it is only repopulated because hooks re-ingest. |
| 154 | - **`vm.max_map_count` = 1,048,576.** The old instance reached 703,009 (67%). On |
| 155 | hitting the ceiling cogserver cannot create threads or mmap at all. |
| 156 | - **Swap is undersized.** 2 GB on a 31 GB machine, `swappiness=60`, no zram. As of |
| 157 | the end of this session swap was **100% full (47 MB free)** with 2.4 GB RAM free. |
| 158 | - **pgh-sidecar** carries `VmPeak` 48.3 GB against 5.0 GB current RSS. |
| 159 | |
| 160 | --- |
| 161 | |
| 162 | ## 6. State of the tree |
| 163 | |
| 164 | **One file added, nothing else touched:** |
| 165 | |
| 166 | - `knowledge-ratchet/atomspace/test/connection-reuse.test.js` — new, currently **RED** |
| 167 | by design. Asserts (a) concurrent `evalScheme()` calls each receive their own |
| 168 | correct answer, and (b) a burst of 10 evals costs the server ≤ 6 VMAs. Current |
| 169 | result: **57 VMAs leaked (~29.7 connections), correctness passes.** It is written |
| 170 | test-first against the unfixed client and will go green when pooling lands. |
| 171 | |
| 172 | Not done: no change to `cogserver.js`, no change to `NetworkServer.cc`, no rebuild, |
| 173 | no restart performed by me. |
| 174 | |
| 175 | --- |
| 176 | |
| 177 | ## 7. Next steps, in order of leverage |
| 178 | |
| 179 | ### 1. Pool the client connection (no rebuild, biggest win) |
| 180 | Rewrite `knowledge-ratchet/atomspace/cogserver.js` to hold **one persistent connection |
| 181 | per process** instead of one per expression, and drop the `isCogServerUp()` probe socket. |
| 182 | |
| 183 | **Design constraint that must not be missed:** with a shared socket, requests |
| 184 | **must be serialized through a FIFO queue**. Callers use `Promise.all([...])` |
| 185 | (`query.js:313-315`, `query.js:468-475`); today that accidentally works because each |
| 186 | call gets its own socket. Interleaving them on one socket would scramble replies — |
| 187 | which is exactly what the correctness half of the new test guards. |
| 188 | |
| 189 | Also: `sock.unref()` so hook processes still exit; tear the connection down on |
| 190 | timeout so late data cannot bleed into the next request; preserve the exported API |
| 191 | (`isCogServerUp`, `evalScheme`, `evalSchemeBatch`, `evalSchemeVoid`) and the exact |
| 192 | return-string shaping, since ~20 scripts depend on it. |
| 193 | |
| 194 | Verify with: `node atomspace/test/connection-reuse.test.js` → PASS. |
| 195 | |
| 196 | ### 2. Reap handler threads in cogserver |
| 197 | `NetworkServer.cc:169`. Minimal fix is `handler_thread->detach()`, which lets glibc |
| 198 | recycle stacks immediately but forfeits the shutdown join. Tidier: keep the list but |
| 199 | reap finished threads in the accept loop so shutdown semantics survive. |
| 200 | |
| 201 | Build is cmake, `opencog-kb/repos/cogserver/build/` exists with a `CMakeCache.txt` |
| 202 | from 2026-02-01; installed binary is `/usr/local/bin/cogserver` (root-owned, same date). |
| 203 | Requires rebuild + reinstall + restart, so sequence this **after** step 3. |
| 204 | |
| 205 | This is a genuine upstream bug and worth reporting to opencog/cogserver. |
| 206 | |
| 207 | ### 3. Answer the AtomSpace deletion story |
| 208 | Before any further restart, either attach a real `RocksStorageNode` (so restarts stop |
| 209 | being lossy at all — the right fix) or export the graph and verify the dump. Do not |
| 210 | treat "hooks will re-ingest it" as persistence. |
| 211 | |
| 212 | ### 4. Resize swap / add zram |
| 213 | 2 GB of swap is what turned a memory shortfall into a 90-second freeze. This is the |
| 214 | cheapest change that converts the next occurrence from a hang into a slowdown. |
| 215 | |
| 216 | ### 5. Find what restarts cogserver |
| 217 | PPid 1, no systemd unit, restarted at 21:02:36 unattended. Unknown supervisor is its |
| 218 | own risk — it means nobody notices the graph being discarded. |
| 219 | |
| 220 | --- |
| 221 | |
| 222 | ## 8. One-line summary |
| 223 | |
| 224 | A routine `ifsrenderer-linux` .NET CI build landed on a box with no headroom, because |
| 225 | cogserver had silently consumed ~5.3 GB in leaked pthread stacks — one 8 MB stack per |
| 226 | TCP connection, never unmapped, driven at ~9 connections/second by knowledge-ratchet |
| 227 | hooks that open a fresh connection for every Scheme expression. |