test(perf): document relay timeout evidence and concurrent read coverage

Record production loopback, proxy and cross-host probes alongside the
controlled latency and retry regressions so reviewers can distinguish
confirmed server defects from client cancellation and transfer costs.

Add an opt-in LMDB read benchmark at 1, 4, 16 and 32 concurrent readers.
Each reader must receive complete event batches and EOSE within a bounded
deadline. Production measurements remain read-only; private journals and
metrics are not included, and no deployment or client policy change is made.

Validation: 3,034 workspace test executions pass with zero failures and
16 ignored tests; both explicit performance benchmarks pass. Formatting,
whitespace and workspace/all-target Clippy checks pass. The final checkpoint
test refinement also passes its two focused regressions.
This commit is contained in:
DanConwayDev
2026-09-12 14:54:19 +00:00
parent 28daae2a85
commit 8698d9943b
2 changed files with 369 additions and 0 deletions
@@ -0,0 +1,303 @@
# GRASP relay timeout investigation
The investigation found five server defects or latency hazards: discovery-only
relay connections lost their retry history during cleanup; accepted sockets
left Nagle enabled; incomplete discovery fetches could be reported as successful;
periodic checkpoints performed blocking storage work on an asynchronous worker;
and metrics requests performed synchronous filesystem scans on that executor.
The accompanying changes address each independently. The clearest controlled
latency improvement is a 25-query small-response benchmark: approximately
1.050 seconds before disabling Nagle and 15 milliseconds afterward.[^1]
The evidence does **not** establish that these five changes explain every
historical seven-second client timeout. In production measurements, the same
repository history that sometimes took seconds to download from the coding VM
completed in 22–75 milliseconds over the servers' loopback connections. A
three-minute backend monitor found no seven-second pauses. The ngit client also
has a specific policy that can cancel all repository relays after unrelated
auxiliary relays finish; its timeout message describes the final grace period,
not necessarily the duration of the operation. This policy and the amount of
history transferred are essential to interpreting the reported symptom.[^2][^3]
**Scope and deployment state.** Measurements were taken on 12 September 2026,
with journal samples around 13:59–14:18 UTC, direct probes around 14:23–14:24,
backend monitoring around 14:27–14:30, and a repeat public-history probe at
14:39. Operator SSH access worked on both fi1 and de1. The investigation used
read-only HTTP/WebSocket requests, service state, metrics and journals; no
production services were restarted or changed. Tests that publish events ran
against isolated local relay fixtures. No changes in this branch are deployed.
The supplied historical failure has no accompanying timestamp, exact command,
repository coordinate or packet trace, so retrospective attribution remains
limited.[^2][^4]
| Instance | Observed runtime | Backend | Observed host resources |
| --- | --- | --- | --- |
| fi1: gitnostr.com | ngit-grasp 3.0.0, running since 31 August | loopback 7449 | 12 logical CPUs, approximately 62 GiB RAM |
| fi1: ngit.danconwaydev.com | ngit-grasp 3.0.0, running since 31 August | loopback 8082 | shared host; approximately 31 GiB available at capture |
| de1: relay.ngit.dev | ngit-grasp 3.0.1, running since 10 September | loopback 7443 | 12 logical CPUs, approximately 62 GiB RAM; 54 GiB available |
The runtime paths and neighboring NixOS repository pins agreed. The changes
were developed against repository base
`3a6de13568e4df5be9bdd5c1c1767bfc633c7e5f`, whose package version is 3.0.2.
The dependency behavior discussed below was inspected in the exact
`nostr-sdk` 0.45.0 source selected by Cargo.lock, rather than assuming that
current online SDK documentation describes the deployed version.[^4][^5]
**Discovery retry ownership — confirmed defect with production evidence.**
NIP-65 author and mailbox discovery can require a relay connection even when
that relay has no persistent repository subscription. Several disconnect and
cleanup paths treated only persistent subscriptions as ownership. Consequently,
a failed discovery-only connection could be retired, removing its health state,
and then reintroduced from the still-required mailbox inventory. Its next
failure started backoff again instead of retaining the accumulated history.
This both wastes connection work and weakens the intended protection against
unreachable relays.[^6]
One public, unreachable endpoint was registered 45 times and retired 46 times
in the approximately 18-minute de1 journal extract. In the approximately
seven-minute fi1 extract, covering two processes, the same endpoint was
registered 107 times and retired 109 times. Other failing endpoints repeatedly
returned to the first five-second backoff. These are bounded journal extracts,
not counts over the full process lifetime. They support an actual retry/cleanup
loop rather than a claim that ordinary client traffic overloaded the boxes.[^7]
The fix includes author sources, mailbox roots and repository sources, and
in-flight discovery work in connection ownership. Disconnect detection,
retries and cleanup now use that ownership consistently. Idle cleanup preserves
failure/backoff state and lets queued unexpected disconnects be classified
before deciding whether a source is genuinely idle. Removing a source from
actual discovery scope still allows retirement; the fix does not add permanent
subscriptions to every mailbox relay.[^6]
A regression uses an isolated flapping mailbox relay reached through NIP-65
index discovery. It waits for repeated connections and an observable retry
record demonstrating retained failure history. A unit test covers ownership
across retry deadlines and in-flight removal. The integration regression failed
during development until both disconnect paths and idle cleanup were corrected;
it then passed in approximately 6.45 seconds. This demonstrates the repaired
lifecycle, but no production before/after CPU measurement exists because the
change has not been deployed.[^1][^6]
**Small-response TCP latency — reproduced and fixed.** The HTTP accept loop
passed its sockets into Hyper without setting TCP_NODELAY. The relay sends
individual EVENT and EOSE frames, and a peer using delayed acknowledgements can
leave a later small write waiting behind an unacknowledged segment. A local
reverse proxy is still a TCP peer, so colocating Caddy does not eliminate this
mechanism. Tokio documents TCP_NODELAY as controlling Nagle's algorithm.[^8]
Production loopback-proxy probes showed recurring approximately 33–39 ms gaps,
consistent with this mechanism. That timing alone is not a packet-level proof.
The controlled regression supplies the stronger evidence: it explicitly turns
off TCP_QUICKACK on a Linux client, then waits for two EVENT messages and EOSE
for each of 25 requests. The original server took 1.049627784 seconds; the
patched server took 15.170770 milliseconds, with a separate repeat at
13.985321 milliseconds. Accepted sockets now enable TCP_NODELAY before handling
HTTP or upgrading to WebSocket.[^1][^2]
This benchmark deliberately tests sensitivity to delayed ACKs. It is opt-in,
because host scheduling can distort wall-clock assertions on shared CI workers.
It does not prove that every event experiences a 40 ms delay or that disabling
Nagle by itself cures a seven-second complete-history download. Larger TCP
transfers, packet sizes, RTT and downstream proxy behavior still matter.
**Incomplete fetch completion — reproduced and fixed.** The server's small
control-plane fetch helper previously relied on SDK `fetch_events` returning
`Ok(events)`. In the locked SDK, a stream can terminate on timeout or disconnect
without an error, leaving that API to return the events collected so far.
Discovery can then confuse partial history, or an empty interrupted result,
with a completed answer. This is a correctness defect that also undermines
retry accounting and can leave discovery using incomplete inputs.[^5][^9]
The replacement observes EOSE for the exact subscription while retaining the
SDK's validated event stream. Success requires both EOSE and draining the data
stream; the full collection has a deadline and retains the prior 10,000-event
buffer cap. Disconnect or expiry without complete EOSE produces an error.
Dropping the SDK stream uses its existing cancellation cleanup. The change
preserves SDK authentication handling instead of accepting raw unvalidated
notification events. EOSE is the protocol marker separating stored results
from subsequently received events; a successful WebSocket connection is not a
substitute for it.[^5][^9][^10]
The regression server sends a valid matching event, then either closes the
connection or remains silent without EOSE. The original helper returned a
successful partial result; the fixed helper rejects both cases. Existing
successful-fetch tests also pass. The independently observed notification
stream is bounded by the SDK; if an EOSE notification is lost under extreme
notification lag, this helper fails closed at the deadline rather than claiming
completion. It does not promise delivery from a malfunctioning remote relay.
**Checkpoint executor blocking — confirmed code hazard, historical impact
unproven.** Every 60 seconds the service checkpointed purgatory and rejected
state from an asynchronous task. Serialization, temporary-file writes, fsync
and rename are synchronous operations. Rejected-index read locks also remained
held through serialization and storage I/O, so a slow filesystem could delay
writers in addition to occupying an executor thread.[^11]
Periodic saves now run on a blocking worker. They are serialized, with the next
interval beginning after completion so slow storage cannot accumulate catch-up
jobs. Shutdown signals the scheduler and joins any running checkpoint before
writing the final snapshot. This ordering is necessary because an already
running Tokio blocking task cannot simply be aborted: an old snapshot must not
finish later and overwrite shutdown state. The rejected-index guards are
released after taking the owned snapshot, before serialization or disk I/O.
Startup and final shutdown persistence retain their existing behavior.[^11][^12]
A current-thread runtime test stalls a checkpoint on a bounded blocking I/O
surrogate, verifies that the runtime remains able to release it, and checks that
shutdown joins it. Another test checks shutdown before the initial deadline.
These establish executor separation and shutdown ordering. The production
monitor crossed multiple checkpoint periods without observing a long pause;
therefore checkpointing is a fixed latency hazard, not a measured explanation
of the supplied historical timeout.
**Metrics executor blocking — confirmed code hazard, historical impact
unproven.** Rendering `/metrics` refreshes the repository count by traversing
the filesystem. Previously this happened directly inside the HTTP request
future. The asynchronous rendering path now acquires a shared permit before
spawning blocking work. The worker retains the permit even if its HTTP caller
is cancelled, so concurrent scrapes cannot create overlapping filesystem
scans. Rendering failures return an HTTP error; metric names and repository
count semantics are unchanged.[^13]
The test checks that a scrape waiting for capacity yields on a single-threaded
runtime, returns the expected metrics after capacity becomes available, and
releases its permit. Production spot measurements of metrics requests were
approximately 5.9–19.4 ms. Those measurements do not show a seven-second metrics
stall; the fix protects request handling when filesystem latency is worse than
in this sample. There is no claim that metrics scanning currently dominates
CPU usage.
**Client cancellation and transfer volume.** The inspected ngit client uses a
45-second long timeout and a seven-second grace period once at least half of
all attempted relays have succeeded. The counter includes auxiliary/index
relays, not just repository relays. With five repository relays and five quick
auxiliary relays, the latter can satisfy the threshold while every repository
relay is still fetching. The timer encloses the complete fetch future, including
multiple query rounds and local processing, and its final message prints the
seven-second grace duration. Timed-out relays are subsequently skipped for the
session. Thus five identical messages do not establish five simultaneous
network outages or five seven-second server query stalls.[^3]
This is directly compatible with the reported five-failure/five-success pattern,
but reproducing the historical command would be needed to establish its exact
trigger. The client also builds history filters without `since` for repository
roots and related events. Local cache comparison determines whether received
events are new after transfer; a successful "no new events" result therefore
does not imply an empty network response. The public ngit-grasp history probe
returned roughly 161 core events and 400 descendants, about 0.85 MB. The ngit
probe returned roughly 281 core events and 650–654 descendants, about 2.09 MB.
Five parallel repository downloads multiply that traffic before considering
extra client query rounds or processing.[^2][^3]
The raw probes intentionally resemble repository-history reads but are not an
instrumented replay of ngit's full cache and signature-processing pipeline.
They cannot assign a measured fraction of the original timeout to client CPU,
network throughput or the server. Changing the client's redundancy policy or
introducing incremental history synchronization requires separate client
semantics and correctness tests; this server branch does neither. A productive
repository relay can still exceed the client deadline after these server fixes.
| Read-only measurement | Results | Interpretation |
| --- | --- | --- |
| 72 public connections across five GRASP relays and nos.lol | All empty-ID, announcement, recent-Git queries and ping checks succeeded; largest individual query 2.166 s | No general inability to accept or answer lightweight requests during capture |
| Full repository probes against three local service ports | ngit-grasp approximately 22–23 ms; ngit approximately 34–75 ms, including connection and both query rounds | Indexed backend reads were fast in these samples |
| Own public hostname from the hosting box | Approximately 0.13–0.28 s | Includes TLS/proxy setup and small-response gaps |
| fi1 ↔ de1 full-history probes | Approximately 0.49–0.53 s | Cross-host path remained responsive |
| fi1 → git.shakespeare.diy | Approximately 1.49–1.80 s | Longer remote path still completed both history rounds |
| fi1 → git.nostrhub.io | Approximately 2.13–2.45 s | Same qualification; not proof of remote server processing time |
| Repeated parallel public probes from the VM, 14:39 | ngit-grasp 1.38–2.99 s; ngit 3.94–5.55 s | Large response transfer takes appreciable time despite fast localhost reads |
Initial parallel VM history probes took 2.96–10.10 seconds for ngit-grasp and
7.18–21.00 seconds for ngit. Those runs overlapped dependency downloads and
other VM build activity. They are **confounded measurements**, not evidence
that a production backend spent 21 seconds answering. A separate isolated-relay
attempt during the same busy period is subject to the same limitation. The
later repeat without those dependency downloads was substantially faster.
The server-originated probes provide an independent vantage point and prevent
misattributing the VM's shared path to all remote boxes.[^2]
| Three-minute localhost monitor | Requests | Median | Maximum | Errors |
| --- | ---: | ---: | ---: | ---: |
| de1 empty ID | 180 | 0.228 ms | 0.657 ms | 0 |
| de1 repository roots | 36 | 7.042 ms | 47.607 ms | 0 |
| fi1 personal instance empty ID | 180 | 0.297 ms | 4.315 ms | 0 |
| fi1 personal instance repository roots | 36 | 8.800 ms | 11.734 ms | 0 |
The monitor used one empty-ID query each second and a repository-root query
every fifth sample. It is a low-rate observational check, not a production
stress test. No test published events to production or intentionally exhausted
its connection, request or storage capacity.[^2]
**Other investigated explanations.** Neither host had a CPU quota on the
examined service units. de1 had ample memory, no swap use and near-zero CPU
pressure; fi1 had swap allocated but no sampled memory pressure and modest CPU
pressure. Swap allocation alone does not establish active thrashing. The fi1
personal service accumulated appreciable background CPU, roughly 70% of one
core averaged over its uptime, despite modest end-user traffic. de1's metrics
showed hundreds of tracked relay connections. Mailbox discovery and descendant
fallback are substantial background workloads; "few users" is not a complete
measure of relay work.[^4]
Journals showed remote subscription limits and rate limiting from other relays.
Those messages concern outbound synchronization and must not be treated as
proof of inbound query stalls. Auxiliary coverage filters sort their inputs
before chunking, and reconciliation compares desired filter sets: an
unsubstantiated hypothesis that arbitrary HashSet order continuously replaces
coverage was not confirmed. The inspected LMDB backend already moves database
queries onto blocking workers. No global database lock or Caddy timeout was
identified as the cause of a seven-second backend stall in the measured reads.
The reported pnpm/package warning is separate output, with no evidence linking
it to WebSocket completion.[^4][^5][^6]
**Validation and practical limits.** All five fixes are in separate behavior
commits with regression tests and architecture documentation. The local load
benchmark seeds an LMDB-backed relay with 32 signed, 8 KiB events, then runs
1, 4, 16 and 32 simultaneous readers, each requesting three complete batches.
All batches returned exactly 32 events and EOSE. Maximum reader durations in
one run were 56.8, 123.3, 536.9 and 587.7 ms respectively. This is a bounded
concurrency test of the corrected server, not an estimate of production maximum
capacity or a simulation of its full outbound relay graph.[^1]
Run the explicit performance regressions on an otherwise idle Linux worker:
```bash
nix develop -c cargo test --test relay_response_latency -- --ignored --nocapture
```
Run the normal workspace suite:
```bash
nix develop -c cargo test --workspace --locked
```
The complete workspace run passed: **3,034 test executions, zero failures,
16 ignored tests**, across 50 suite results. This includes 907 server-library
tests and the production-shaped REQ/negentropy concurrency integration tests.
Shared fixture unit tests run in several integration binaries, so 3,034 is an
execution count, not a claim of 3,034 distinct scenarios. The explicit two-test
performance run passed separately; those two opt-in tests are included among
the normal run's ignored tests. Formatting, whitespace and workspace/all-target Clippy checks also passed.
A future production rollout should compare the same local and external queries,
retry-history progression, CPU usage and completion rates before and after the
new binary, without relying solely on the client timeout string. The remaining
historical uncertainty can only be resolved by capturing the exact failing
client command with per-relay connection, first-event and EOSE timings alongside
local processing time. This investigation establishes reproducible server
fixes and bounds competing explanations; it does not warrant a guarantee that
all intermittent faults have been eliminated on machines still running older
binaries.
[^1]: Local regression evidence, 12 September 2026: `work/timeout-investigation/nodelay-before.log`, `nodelay-after.log`, `incomplete-fetch-before.log`, `incomplete-fetch-after.log`, `discovery-test.log`, `discovery-unit.log`, `local-load.log` and `workspace-tests.log`. Private working records, not published logs. Reproducible fixtures: [relay response latency](../../tests/relay_response_latency.rs), [reconnect backoff](../../tests/sync/reconnect_backoff.rs), [checkpoint tests](../../src/checkpoint.rs) and [connection helper tests](../../src/sync/relay_connection.rs).
[^2]: Read-only probe records, 12 September 2026: `public-probes.jsonl`, `repo-probes.jsonl`, `repo-probes-repeat.jsonl`, `de1-wire-probes.jsonl`, `fi1-wire-probes.jsonl`, `vm-wire-probes.jsonl`, `de1-monitor.jsonl`, `fi1-monitor.jsonl` and `measurement-summary.json`, under `work/timeout-investigation/`. Private working records. Probe implementations are retained there as `probe.py`, `repo-probe.py`, `wire-probe.py` and `monitor.py`. Failed SSH-forwarding attempts are excluded from performance results because forwarding was administratively prohibited.
[^3]: Local ngit source, inspected 12 September 2026, checkout HEAD `3e9b26d0`: `../ngit/src/lib/client.rs`, fetch coordinator around lines 1000–1090, `SUCCESS_THRESHOLD`, `short_timeout`, `long_timeout`, and `get_fetch_filters` around line 3441. These are source observations; the exact build and command that emitted the historical message were not supplied.
[^4]: Production service/resource evidence, 12 September 2026: `fi1-state.txt`, `de1-state.txt`, `de1-restart-limits.txt`, `de1-metrics.txt`, `fi1-personal-metrics.txt`, and the fi1/de1 deployment configuration checkouts. Private working records under `work/timeout-investigation/`; raw metrics and journals are intentionally not published with this report.
[^5]: rust-nostr, `nostr-sdk` 0.45.0 source selected by [Cargo.lock](../../Cargo.lock), especially `src/relay/api/fetch_events.rs`, `src/relay/api/stream_events.rs`, `src/local_relay/local/session.rs`, and `src/stream.rs`; `nostr-lmdb` 0.45.0 query implementation. Sources inspected in the local Cargo registry. Published version: [nostr-sdk 0.45.0](https://docs.rs/crate/nostr-sdk/0.45.0).
[^6]: ngit-grasp [sync manager](../../src/sync/mod.rs), particularly `Nip65DiscoveryState::connection_targets`, `check_disconnects`, `retry_disconnected_relays`, `handle_disconnect`, `retire_idle_nip65_discovery_source`, and `reconcile_descendant_mode`; [filter construction](../../src/sync/filters.rs).
[^7]: Production journal extracts `de1-journal.txt` and `fi1-journal.txt`, 12 September 2026, under `work/timeout-investigation/`, capped at 16,000 lines each. Registration/retirement counts refer to the same public endpoint in each file; fi1 includes two service processes. Private records.
[^8]: Tokio, [TcpStream::set_nodelay](https://docs.rs/tokio/latest/tokio/net/struct.TcpStream.html#method.set_nodelay), accessed 12 September 2026; ngit-grasp [HTTP accept loop](../../src/http/mod.rs).
[^9]: ngit-grasp [RelayConnection::fetch_events](../../src/sync/relay_connection.rs) and its `fetch_events_requires_eose_after_partial_delivery` regression.
[^10]: Nostr protocol, [NIP-01: Basic protocol flow description](https://github.com/nostr-protocol/nips/blob/master/01.md), relay-to-client EOSE message definition, accessed 12 September 2026.
[^11]: ngit-grasp [checkpoint scheduler](../../src/checkpoint.rs), [server lifecycle](../../src/server.rs) and [rejected-index persistence](../../src/sync/rejected_index.rs).
[^12]: Tokio, [spawn_blocking](https://docs.rs/tokio/latest/tokio/task/fn.spawn_blocking.html), task cancellation and worker limits, accessed 12 September 2026.
[^13]: ngit-grasp [metrics rendering and repository counting](../../src/metrics/mod.rs) and [HTTP metrics handler](../../src/http/mod.rs).
+66
View File
@@ -2,6 +2,72 @@
mod common;
#[tokio::test]
#[ignore = "local load benchmark; run explicitly with --nocapture"]
async fn concurrent_lmdb_read_batches_reach_eose() {
use common::{TestClient, TestRelay};
use futures_util::{SinkExt, StreamExt};
use nostr_sdk::prelude::*;
use std::time::{Duration, Instant};
use tokio_tungstenite::tungstenite::Message;
let relay = TestRelay::start_with_lmdb().await;
let keys = relay.owner_keys().clone();
let client = TestClient::new(relay.url(), keys.clone()).await.unwrap();
for index in 0..32 {
let event = EventBuilder::new(Kind::TextNote, format!("{index}:{}", "x".repeat(8192)))
.finalize(&keys)
.unwrap();
client.send_event(&event).await.unwrap();
}
for concurrency in [1, 4, 16, 32] {
let url = relay.url().to_string();
let reads = (0..concurrency).map(|_| {
let url = url.clone();
async move {
let (mut stream, _) = tokio_tungstenite::connect_async(url).await.unwrap();
let started = Instant::now();
for _ in 0..3 {
stream
.send(Message::Text(r#"["REQ","load",{"kinds":[1]}]"#.into()))
.await
.unwrap();
let mut events = 0;
loop {
let frame = stream.next().await.unwrap().unwrap();
if !frame.is_text() {
continue;
}
let message: serde_json::Value =
serde_json::from_str(frame.to_text().unwrap()).unwrap();
match message[0].as_str() {
Some("EVENT") => events += 1,
Some("EOSE") => break,
other => panic!("unexpected reply: {other:?}"),
}
}
assert_eq!(events, 32);
}
let elapsed = started.elapsed();
stream.close(None).await.unwrap();
elapsed
}
});
let times = tokio::time::timeout(
Duration::from_secs(30),
futures_util::future::join_all(reads),
)
.await
.expect("all readers must reach EOSE under local load");
eprintln!(
"{concurrency} concurrent LMDB readers, three 32-event batches each: max {:?}",
times.iter().max().unwrap()
);
}
client.disconnect().await;
relay.stop().await;
}
#[cfg(target_os = "linux")]
#[tokio::test]
#[ignore = "socket latency benchmark; run explicitly on an otherwise idle worker"]