HarperFast / HarperFast/harper

RocksDB read snapshot leaks permanently: registry holds a strong ref to TransactionHandle, GC finalizer never calls close(), and DatabaseTransaction.abort() cannot release a save()-created transaction

Open
#2,107 11 comments 0 reactions 0 assignees View on GitHub
Dominant language
JavaScript
Stars
89
Forks
10
Avg merge
2d 6h
Merged PRs (30d)
200

Description

## Summary

`oldestSnapshotTime` never advances past process start, so RocksDB is never permitted to discard
obsolete row versions. Compaction runs — it just can't drop anything. On a high-churn table this
reaches **~4 keys per live row in ~5 days**, and a range-scan iterator then spends its time
reseeking past dead versions: **43,647 reseeks vs 51** on a freshly-restarted node, degrading
bounded range scans **21×**. A process restart is the only reclamation path.

Point reads and primary-key scans are unaffected, so this hides until something latency-sensitive
does a secondary-index range scan.

**Version:** `harperfast/harper-pro:5.1.26` (Fabric, 4-node production cluster running the
`@harperfast/prerender` component). Not yet verified against v5.2.0.

## The smoking gun

`oldestSnapshotTime` equals process start on **every** node in the cluster:

| node | uptime | oldestSnapshotTime age |
| ---- | ------ | ---------------------- |
| A (aged) | 4d19h | **4.76 days** |
| B (aged) | 4d21h | ~4.9 days |
| C (fresh) | 4h | **3.9 hours** |
| D (fresh) | 3h | ~3h |

Something takes a snapshot at startup and holds it for the life of the process.

## Consequences, measured

Table: `RenderSchedule` — PK `cacheKey: String`, indexed `nextRenderTime: Long`. **Every write
updates the indexed attribute** (it carries both the next-run time and a claim lease), at a
measured **7–8 writes/sec/node**.

`system_information.attributes=["metrics"]`, aged node vs freshly-restarted node:

| metric | node A (4d19h) | node C (4h) | ratio |
| ------ | -------------- | ----------- | ----- |
| `estimateNumKeys` | 1,901,091 | 513,897 | — |
| live rows owned | ~490,000 | ~420,000 | — |
| → **keys per live row** | **3.9** | 1.22 | |
| `numberReseeksIteration` | **43,647** | 51 | **856×** |
| `sstReadMicros` (count) | 5,283,389,458 | 27,836,970 | 190× |
| `dbSeekMicros` (median) | **256 ms** | 35 ms | 7.4× |
| `liveSstFilesSize` | 362 MB | 98 MB | 3.7× |
| blockCache miss rate | 98.3% | 90.8% | |

~1.4M retained dead versions on a table with ~490k live rows.

## Reproduction / how to observe

Bounded range scan on the indexed attribute, `limit 20`, timed on-node over the ops UDS:

```
search_by_conditions render_schedule.RenderSchedule
conditions: [{ nextRenderTime, less_than_equal, }]
limit: 20
```

| node | scan (limit 20) | point read | PK range scan | low-churn secondary index |
| ---- | --------------- | ---------- | ------------- | ------------------------- |
| A (aged, 4d19h) | **525 ms** | 1.4 ms | 2.5 ms | 1.5 ms |
| B (aged, 4d21h) | **703 ms** | 1.1 ms | 2.5 ms | 1.5 ms |
| C (fresh, 4h) | 33 ms | 1.0 ms | 2.6 ms | 2.6 ms |
| D (fresh, 3h) | 109 ms | 1.4 ms | — | — |

Note the control columns: **same table, same aged store, primary key → identical to fresh**. A
*low-churn* secondary index (`Target.state`) → also identical. So it is neither the store nor
secondary indexes generally; it is specifically the high-churn index.

### Two facts that pin the mechanism

**1. The cost is independent of `limit`.** 20 rows and 200 rows both cost ~712ms on node B, and
the 200-row result set was clean (200 distinct rows, 0 duplicates, 0 stale). So the cost is
traversal, not retrieval.

**2. The cost lives in a key range that contains no live rows.** Mapping it by lower bound on
node B, whose oldest *live* overdue row is 8.2h old:

| lower bound | scan | | lower bound | scan |
| ----------- | ---- |-| ----------- | ---- |
| none / `>= 0` | 710 ms | | `now-24h` | 136 ms |
| `now-365d` | 700 ms | | `now-12h` | 37 ms |
| `now-30d` | 720 ms | | `now-9h` | 12 ms |
| `now-7d` | 710 ms | | `now-4h` | **1.7 ms** |

The range `now-7d … now-9h` holds **zero live rows** yet accounts for ~570ms of the 710ms. The
dead region's extent tracks uptime — node C at 4h is flat at 33ms all the way down to `now-9h`.

This also explains why repeated identical scans never warm up: there is nothing to cache, the
iterator redoes the skipping every time.

## Same-node before/after restart

Node B, restarted mid-investigation, with predictions registered beforehand:

| | before | after (10 min uptime) |
| - | ------ | --------------------- |
| scan (limit 20) | 703 ms | **88 ms** |
| point read | 1.1 ms | 1.6 ms (unchanged, as predicted) |
| `render_schedule` on disk | 675 MB | **377 MB** |
| `estimateNumKeys` | 1.9M (node A ref) | **557,587** (1.33/row) |
| `numberReseeksIteration` | 43,647 (node A ref) | **18** |
| `liveSstFilesSize` | 362 MB (node A ref) | **111 MB** |

(Before-values for `estimateNumKeys`/reseeks/`liveSstFilesSize` are from the sibling aged node —
we didn't capture node B's own metrics pre-restart. Scan time and on-disk size are same-node.)

## Impact

On this deployment the degraded scan is on the hot path of a job-claim query that is serialized
behind a mutex and polled at a fixed ~4/sec/node. At 700ms service time utilisation exceeds 1, the
claim queue backs up (p95 reached **15–24 s**), and requests sharing those workers see multi-second
latency. Cache-hit latency spiked **only** in buckets where the claim path spiked — 357 calm
buckets had a max of 8.4ms; 4 spiking buckets had a median of 8,368ms.

Render throughput was *not* affected (flat ~11,800/hr/node across a 30× range of claim latency), so
the damage here is tail latency, not capacity.

More generally: any deployment with a hot table plus a secondary-index range scan will degrade on a
~5-day clock with restart as the only remedy, and will most likely be misdiagnosed. We spent
several hours on memory pressure, swap, and compaction before finding this.

## Ruled out along the way

- **Swap / memory pressure** — the node with the fleet's highest swap-in rate (677 MB/h, ~25 major
faults/sec) had **zero** slow buckets.
- **RocksDB compaction as a stall cause** — no flush or compaction anywhere near the latency
spikes; the one positively-timed compaction produced no stall. `stallMicros = 0`,
`estimatePendingCompactionBytes = 0`, `dbWriteStall` count 0 on all nodes.
- **Observer tooling** — `list_metrics` takes ~6 s but demonstrably does not perturb the request
path.
- **Long-open read transactions** — zero `open too long` warnings in 24h on any node, so whatever
pins the snapshot is not being reported by that check.

## Ask

1. What takes a snapshot at process start, and why is it never released or advanced?
2. Should `oldestSnapshotTime` advance as transactions complete? If it's a long-lived internal
reader (replication? txn-log replay? a change-feed?), can it be periodically renewed so
reclamation can proceed?
3. Is this already fixed in v5.2.0? Happy to verify on this cluster if so.

Related: HarperFast/harper-pro#659 (blob replication receive side unbounded) — separate issue, also found on this
cluster, also only recoverable by restart.

Happy to provide the cluster and node identifiers, raw metric dumps, or to re-run any probe.

Contributor guide

Open the contributing guide

Research direction

Trace the TransactionHandle registry, its GC finalizer and close path, then inspect how DatabaseTransaction.abort() handles transactions created by save(). Reproduce the snapshot age and range-scan metrics described in the issue before and after transaction cleanup. Done means the retained snapshot is released or renewed and RocksDB reclamation and scan behavior no longer require a process restart.

Written by the indexing model from the issue text.

Assessment

Tech stack
javascript, nodejs
Domain
databases, performance
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Quiet
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.