rays/ipx
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 18 Wiki Activity

Database connections kept open; a click's wait is measured (#241, #245, #246)

Browse Source 
#241: on production, All Subscriptions' query runs in 31 ms, unread oldest-first in 30, the
feed list's count in 5, generic plans included (EXPLAIN ANALYZE, BUFFERS, read only), against
0.3-1.6 s in ipx. A new Postgres connection takes 80-330 ms to open, and a page load asks for
more than are idle: four of six slow loads came as the pool grew (3 to 6, 2 to 6, 3 to 5, 6 to
8), and 20 requests at once took a median 414 ms while the pool grew from 8 to 20. The daemon
and the directory's server now keep their whole pool open (min = max); a command such as `ipx
status`, and the tests, which share the server's 100 connections, open as they need.

#246: the page reports list_shown, the ms from asking for a list to drawing it, with the view
and filter, under the click's trace; background refreshes are not timed. Timings skip report()'s
once-a-minute limit, which is for errors in a loop. A dashboard panel and table, and the prod
check, read it.

#245: the load test's browse scenario subscribes by OPML and leaves the Directory, which is
ipx-directory's since #204, to it.

CLAUDE.md records the owner's leave to EXPLAIN (ANALYZE, BUFFERS) any query on production,
read only.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Ray Slakinski
2026-10-15 14:52:14 +00:00
parent 8f19d88fc9
commit 62a3241139
16 changed files with 89 additions and 30 deletions
Download Patch File Download Diff File Expand all files Collapse all files

10
.claude/skills/ipx-prod-check/SKILL.md
View File

@@ -63,7 +63,7 @@ lines had no trace id, the access log's time was `ms`, and each event was logged
| `ipx::scan` | `ev` and the event's own: `feed`, `new`, `downloaded`, `failed`, `bytes`, `msg`, `url`, `feeds`, `reason`, `from`, `to`; on a failure `error.type` and, from an HTTP error, `http.response.status_code` | the daemon's events, one line each, in words; warnings are feed and download failures |
| `ipx::io` | `ev`, `feeds`, `pending`, `downloaded` on the `status` reply | commands arriving (`-> {...}`) and the healthcheck's answer |
| `ipx` | message, sometimes fields | start-up, shutdown, account and config messages |
| `ipx::client` | `ev`, `user`, `feed`, `enclosure`, `deadair`; `msg`, `src`, `line` on an error; `ms` on a timing | what the page reports from the browser (#190): `page_error`, `rejection` and `player_error` as warnings; `play_start` (ms from play to sound) and `stall` (ms waiting mid-play) as info. Lines carry the trace of the action in the page: its API requests send `traceparent`, one trace id per tap or key |
| `ipx::client` | `ev`, `user`, `feed`, `enclosure`, `deadair`; `msg`, `src`, `line` on an error; `ms` on a timing | what the page reports from the browser (#190): `page_error`, `rejection` and `player_error` as warnings; `play_start` (ms from play to sound), `stall` (ms waiting mid-play) and `list_shown` (ms from a click to its list drawn, with `feed` the view and `filter`, #246) as info. Lines carry the trace of the action in the page: its API requests send `traceparent`, one trace id per tap or key |
Events (`ev`): `feed_start`, `feed_done` (new, downloaded, failed, torrents), `feed_skip` (not due,
routine), `feed_error` (msg), `feed_moved` (from, to: a permanent redirect followed, the address
@@ -215,11 +215,12 @@ a count says something happened, the lines and traces say why.
```
$Q metric 'sum by (ev, msg) (count_over_time({container="iPX"} |= "\"target\":\"ipx::client\"" | json | __error__="" | level="WARN" [$range]))' 7d
$Q logs '{container="iPX"} |= "\"target\":\"ipx::client\"" | json | ev=~"play_start|stall" | line_format "{{.timestamp}} {{.user}} {{.ev}} {{.ms}}ms deadair={{.deadair}} {{.feed}}"' 24h
$Q metric 'quantile_over_time(0.95, {container="iPX"} |= "\"ev\":\"list_shown\"" | json | __error__="" | unwrap ms [$range]) by (feed, filter)' 24h
```
A `player_error` is playback that failed in front of someone: `hls.js: ...` is DeadAir's
playlist (its trace has the playlist and audio requests), `media error 4` a file the browser
cannot play. A `page_error` or `rejection` is a bug in the page; `src` and `line` point into
the minified `app.js`, so match the message to `web/src`. `play_start` over 2000 ms, or a
the minified `app.js`, so match the message to `web/src`. A `list_shown` over 1000 ms is a list someone waited for: its trace says whether the API or the network held it. `play_start` over 2000 ms, or a
`stall`, is worth a trace: was it the server, Cloudflare, or the network.
`docker logs --since 10m iPX 2>&1 | tail -5` shows the newest lines when Loki is behind.
@@ -349,8 +350,9 @@ container after a deploy.
## Rules
`docker logs` and `docker exec iPX ipx ...` are fine. Do not query production's Postgres
directly: ask the user if a question needs the database.
`docker logs` and `docker exec iPX ipx ...` are fine. On production's Postgres, `EXPLAIN (ANALYZE,
BUFFERS)` of any query is allowed, read only, as CLAUDE.md's "Production's database" shows; any
other query, ask the user first.
## What to do with what you find

19
CLAUDE.md
View File

@@ -222,6 +222,25 @@ seeking through files, a flood of wrong passwords. Things about them:
Non-trivial logic leaves one runnable check behind. Pure functions (`merge_policy`, `pick`,
`matches_keywords`, `parse_interval`) are the easiest place to put it.
## Production's database
The owner allows `EXPLAIN (ANALYZE, BUFFERS)` of any query against production's Postgres, to see
where a query's time goes; nothing else without asking. Run it read only, so nothing can change:
```sh
U=$(grep -E '^IPX_DATABASE_URL=' /mnt/fast/arcane/projects/ipx/ipx.env | cut -d= -f2- | tr -d '"')
psql "$U" -X -v ON_ERROR_STOP=1 <<'SQL'
BEGIN READ ONLY;
EXPLAIN (ANALYZE, BUFFERS) SELECT ...;
ROLLBACK;
SQL
```
Never print the URL: it carries the password. Write the query as ipx sends it (`$1` parameters
become `PREPARE`/`EXECUTE`, or values), for a real account. A query fast here and slow in ipx's
trace is time outside the query: on 2026-10-15 the feed list's count took 5 ms in Postgres and 366
ms in ipx, the difference being new connections, 80-330 ms each to open (#241).
## Things that are true and easy to get wrong
* **`enclosures.url` is globally UNIQUE.** It is the dedupe key and the reason one file serves every

1
crates/directory/CHANGELOG.md
View File

@@ -14,6 +14,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
- Each feed is checked every twelve hours instead of six (#243).
- Feeds are fetched accepting brotli and zstd as well as gzip (#244).
- On Postgres the server keeps all ten of its database connections open, so a request does not wait for a new one (#241).
## [1.1.1] - 2026-10-15

2
crates/directory/src/main.rs
View File

@@ -92,7 +92,7 @@ async fn serve(path: &std::path::Path) -> Result<()> {
.ok()
.filter(|u| !u.trim().is_empty())
.with_context(|| format!("{} is not set: the directory needs a database URL", cfg.database_url_env))?;
let store = Store::open(&url).await.context("opening the database")?;
let store = Store::open(&url, true).await.context("opening the database")?;
let dir = Directory::new(store, vec![])?;
let dropped = dir.set_tokens(tokens).await?;

12
crates/directory/src/store.rs
View File

@@ -99,7 +99,7 @@ impl Store {
pub async fn scratch() -> Self {
static N: std::sync::atomic::AtomicU32 = std::sync::atomic::AtomicU32::new(0);
let Some(url) = std::env::var("IPX_TEST_DATABASE_URL").ok().filter(|u| !u.is_empty()) else {
return Self::open("sqlite::memory:").await.unwrap();
return Self::open("sqlite::memory:", false).await.unwrap();
};
let (pid, n) = (std::process::id(), N.fetch_add(1, std::sync::atomic::Ordering::Relaxed));
// A bare connection: Store::open would make the tables in the public schema, and the
@@ -117,10 +117,11 @@ impl Store {
let schema = format!("ipxd_{pid}_{n}");
admin.db.execute_unprepared(&format!("CREATE SCHEMA {schema}")).await.unwrap();
let sep = if url.contains('?') { '&' } else { '?' };
Self::open(&format!("{url}{sep}options=-c%20search_path%3D{schema}%20-c%20client_min_messages%3Dwarning")).await.unwrap()
Self::open(&format!("{url}{sep}options=-c%20search_path%3D{schema}%20-c%20client_min_messages%3Dwarning"), false).await.unwrap()
}
pub async fn open(url: &str) -> Result<Self> {
/// `keep_open` for the server, which keeps its whole pool connected.
pub async fn open(url: &str, keep_open: bool) -> Result<Self> {
let mut url = url.to_owned();
if url.starts_with("postgres") && !url.contains("options=") {
// Postgres sends a notice for every CREATE ... IF NOT EXISTS on something that exists;
@@ -134,6 +135,11 @@ impl Store {
if url.contains(":memory:") {
opts.max_connections(1);
}
// The server keeps every connection open, as ipx's daemon does: a Postgres connection takes
// 80-330 ms to open (#241). Not a test, which would hold ten for one question.
if keep_open && url.starts_with("postgres") {
opts.max_connections(10).min_connections(10);
}
let db = sea_orm::Database::connect(opts).await?;
for sql in SCHEMA {
db.execute_unprepared(sql).await?;

5
crates/ipx/CHANGELOG.md
View File

@@ -16,6 +16,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
- A feed that sends the same body again, as Patreon and Substack do whatever they are asked, is taken as unchanged instead of read again, and, without a schedule of its own, checked less often the longer it stays the same, up to every four hours, back on schedule when it changes (#242).
- Feeds are fetched accepting brotli and zstd as well as gzip (#244).
- On Postgres the daemon keeps all twenty of its database connections open, so a page load no longer waits for new ones, 80-330 ms each: the feed list and item lists took 0.3-1.6 s now and then, where their queries take 5-30 ms (#241).
### Added
- The page's report of how long a list took to show after a click (`list_shown`, with the view and filter) is logged under that click's trace (#246).
## [1.2.0] - 2026-10-15

20
crates/ipx/src/db.rs
View File

@@ -154,7 +154,7 @@ fn is_postgres(location: &str) -> bool {
/// sqlx's defaults for SQLite are what ipx wants, foreign keys on and a five-second wait for a
/// lock, which is what rusqlite was set to, but for one.
async fn connect(location: &str) -> Result<sea_orm::DatabaseConnection> {
async fn connect(location: &str, keep_open: bool) -> Result<sea_orm::DatabaseConnection> {
let mut opts = sea_orm::ConnectOptions::new(url_for(location));
opts.sqlx_logging(false);
// NORMAL, SQLite's own advice for WAL: synced at checkpoints, not after every commit. FULL,
@@ -177,6 +177,13 @@ async fn connect(location: &str) -> Result<sea_orm::DatabaseConnection> {
// past. Postgres gets twenty, where sqlx's ten filled in bursts: a page load asks for dozens
// of covers at once, each with a lookup (#200). The server allows 100, shared with other apps.
opts.max_connections(if is_postgres(location) { 20 } else { 8 });
// The daemon keeps every connection open (#241): a Postgres connection takes 80-330 ms to
// open, its password exchange most of it, and a page load asked for more than were idle, so
// the feed list and item list waited on new ones, 300-900 ms where their queries took 5-30.
// Not a command such as `ipx status`, nor a test, which would hold twenty for one question.
if keep_open && is_postgres(location) {
opts.min_connections(20);
}
sea_orm::Database::connect(opts)
.await
.with_context(|| format!("opening {}", redact(location)))
@@ -307,13 +314,14 @@ pub struct FeedSummary {
impl Db {
/// Opens the database at `location` (see `location()`): a postgres:// URL, or a SQLite file.
pub async fn open(location: &str) -> Result<Self> {
/// `keep_open` for the daemon, which keeps its whole pool connected.
pub async fn open(location: &str, keep_open: bool) -> Result<Self> {
if !is_postgres(location)
&& let Some(dir) = Path::new(location).parent()
{
std::fs::create_dir_all(dir).with_context(|| format!("creating {}", dir.display()))?;
}
let orm = connect(location).await?;
let orm = connect(location, keep_open).await?;
if !is_postgres(location) {
// WAL, so the healthcheck's `ipx status` reads while the daemon writes. It is a
// setting of the file, kept once made, and making it takes a lock that cannot wait out
@@ -349,7 +357,7 @@ impl Db {
let n = N.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
let pid = std::process::id();
if let Some(url) = std::env::var("IPX_TEST_DATABASE_URL").ok().filter(|u| !u.is_empty()) {
let admin = connect(&url).await?;
let admin = connect(&url, false).await?;
// Schemas an earlier run left behind: anything of ours not made by this process.
let old = admin
.query_all_raw(Statement::from_string(
@@ -369,13 +377,13 @@ impl Db {
// Every connection in the pool starts in it, so each test sees only its own tables.
let sep = if url.contains('?') { '&' } else { '?' };
let orm =
connect(&format!("{url}{sep}options=-c%20search_path%3D{schema}%20-c%20client_min_messages%3Dwarning"))
connect(&format!("{url}{sep}options=-c%20search_path%3D{schema}%20-c%20client_min_messages%3Dwarning"), false)
.await?;
create_missing(&orm).await?;
return Ok(Self { orm, tmp: None });
}
let path = std::env::temp_dir().join(format!("ipx-test-{pid}-{n}.db"));
let orm = connect(&path.display().to_string()).await?;
let orm = connect(&path.display().to_string(), false).await?;
// As Db::open has it, so the tests' connections share the file as the daemon's do.
orm.execute_unprepared("PRAGMA journal_mode = WAL").await?;
create_missing(&orm).await?;

2
crates/ipx/src/main.rs
View File

@@ -306,7 +306,7 @@ async fn main() -> Result<()> {
let config_path = cli.config.clone().unwrap_or_else(config::config_path);
let cfg = config::Config::load(&config_path)?;
let db = db::Db::open(&db::location()).await?;
let db = db::Db::open(&db::location(), matches!(cli.command, Command::Daemon { .. })).await?;
// A daemon owns the state; don't have two processes downloading the same thing.
let wire_cmd = match &cli.command {

12
crates/ipx/src/web.rs
View File

@@ -1109,8 +1109,9 @@ mod tests {
let u = crate::db::User { id: 1, name: "dee".into(), pass_hash: None, is_admin: false, created: None, last_login: None };
let e = |ev: &str| ClientEvent {
ev: ev.into(), msg: Some("x".repeat(10_000)), src: None, line: None, feed: None, enclosure: None, deadair: None, ms: Some(5),
filter: Some("unread".into()),
};
for ev in ["page_error", "rejection", "player_error", "play_start", "stall"] {
for ev in ["page_error", "rejection", "player_error", "play_start", "stall", "list_shown"] {
assert_eq!(client_event(u.clone(), Json(e(ev))).await, StatusCode::NO_CONTENT, "{ev}");
}
assert_eq!(client_event(u, Json(e("anything"))).await, StatusCode::BAD_REQUEST);
@@ -2252,12 +2253,14 @@ struct ClientEvent {
enclosure: Option<i64>,
deadair: Option<bool>,
ms: Option<u64>,
/// The list's filter, for `list_shown`: all, unread, flagged.
filter: Option<String>,
}
async fn client_event(user: crate::db::User, Json(e): Json<ClientEvent>) -> StatusCode {
// From the browser: only the kinds the page sends, and nothing long enough to fill the log.
let cut = |s: &Option<String>| s.as_deref().map(|s| s.chars().take(500).collect::<String>());
let (msg, src, feed) = (cut(&e.msg), cut(&e.src), cut(&e.feed));
let (msg, src, feed, filter) = (cut(&e.msg), cut(&e.src), cut(&e.feed), cut(&e.filter));
let (ev, line, enclosure, deadair, ms, user) = (e.ev.as_str(), e.line, e.enclosure, e.deadair, e.ms, user.name.as_str());
match ev {
"page_error" | "rejection" | "player_error" => tracing::warn!(
@@ -2268,6 +2271,11 @@ async fn client_event(user: crate::db::User, Json(e): Json<ClientEvent>) -> Stat
target: "ipx::client", ev, ms, feed, enclosure, deadair, user,
"{user}'s page: {ev} {} ms", ms.unwrap_or(0)
),
// From a click to the list drawn (#246).
"list_shown" => tracing::info!(
target: "ipx::client", ev, ms, feed, filter, user,
"{user}'s page: list_shown {} ms", ms.unwrap_or(0)
),
_ => return StatusCode::BAD_REQUEST,
}
StatusCode::NO_CONTENT

9
grafana/dashboard.py
View File

@@ -185,6 +185,15 @@ ts("Page response time", [loki(f'quantile_over_time(0.95, {WEB} | unwrap duratio
loki(f'max_over_time({WEB} | unwrap duration [$__interval]) by ()', ref="B", legend="slowest")],
16, w=8, unit="s", desc="A page waits on ipx's /api/page-check before it is sent.")
y += 8
# What the person waits for, from the page itself (#246): a click to the list drawn.
LIST = SEL + ' |= "\\"ev\\":\\"list_shown\\"" | json | __error__=""'
ts("A click to the list shown", [loki(f'quantile_over_time(0.95, {LIST} | unwrap ms [$__interval]) by ()', legend="95th percentile"),
loki(f'quantile_over_time(0.5, {LIST} | unwrap ms [$__interval]) by ()', ref="B", legend="median"),
loki(f'max_over_time({LIST} | unwrap ms [$__interval]) by ()', ref="C", legend="slowest")],
0, w=12, unit="ms", desc="Measured in the browser, network and drawing included. The API's part is in the click's trace.")
table("Slowest lists by view", [loki(f'topk(10, max_over_time({LIST} | unwrap ms [$__range]) by (feed, filter))', instant=True)],
12, rename={"feed": "View", "filter": "Filter", "Value": "Slowest (ms)"}, sort=[{"displayName": "Slowest (ms)", "desc": True}])
y += 8
# ---- ipx: the API it answers behind ipx-web
row("ipx: API")

8
tests/load/browse.js
View File

@@ -23,8 +23,6 @@ export const options = {
'http_req_duration{name:all-entries}': p95(50, 100),
'http_req_duration{name:feed-entries}': p95(50, 100),
'http_req_duration{name:search}': p95(60, 100),
'http_req_duration{name:directory}': p95(250, 200),
'http_req_duration{name:listed}': p95(300, 200),
},
};
@@ -44,11 +42,7 @@ export default function () {
const found = http.get(`${BASE}/api/entries?q=weather&limit=50`, as(u, 'search'));
check(found, { 'a search of everything you read': r => r.status === 200 && r.json().total === 30 * ITEMS });
const dir = http.get(`${BASE}/api/directory`, as(u, 'directory'));
check(dir, { 'the whole Directory': r => r.status === 200 && r.json().length === FEEDS });
const listed = http.get(`${BASE}/api/directory/${feedId(Math.floor(Math.random() * FEEDS))}`, as(u, 'listed'));
check(listed, { "a feed's page in the Directory": r => r.status === 200 && r.json().items.length === ITEMS });
// Not the Directory: since #204 it is ipx-directory's, which this harness does not start (#245).
sleep(1 + Math.random() * 2);
}

3
tests/load/run.js
View File

@@ -189,7 +189,8 @@ async function seed() {
}
// The media test's listener takes the feeds with files. They may be downloaded already: the
// first start subscribes the admin to the whole catalogue, so the first scan fetched them.
for (let n = 0; n < MEDIA; n++) await api('listener', `/api/popular/${feedId(n)}`, { method: 'POST' });
// By OPML as the others: /api/popular asks the directory, which this harness does not start (#245).
await api('listener', '/api/opml', { method: 'POST', body: JSON.stringify({ xml: opml(Array.from({ length: MEDIA }, (_, n) => n)) }) });
for (let t = Date.now(); ; await new Promise(r => setTimeout(r, 500))) {
const got = await api('listener', '/api/entries?filter=downloaded&limit=50');
if (got.entries.flatMap(e => e.enclosures).filter(x => x.path).length >= MEDIA) break;

1
web/CHANGELOG.md
View File

@@ -13,6 +13,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
### Changed
- The page reports how long each list you open takes to show, from the click to the list drawn, for the dashboard (#246).
- The page and the API's answers are sent compressed, zstd or gzip, which the feed list and item lists, over 100 KB each, were not; live updates and audio are not compressed (#239).
## [1.0.2] - 2026-10-15

6
web/src/events.ts
View File

@@ -6,7 +6,7 @@ let sse: EventSource;
/// the app is in the background, when everything is missed (#168).
const catchUp=(()=>{ let t: number; return ()=>{ clearTimeout(t); t=setTimeout(()=>{
loadFeeds(true).catch(()=>{});
if(S.feed) loadEntries().catch(()=>{});
if(S.feed) loadEntries(false,true).catch(()=>{});
},300); }; })();
document.addEventListener('visibilitychange',()=>{ if(!document.hidden) catchUp(); });
let dropped=false;
@@ -16,7 +16,7 @@ function connect(){
sse.onopen=()=>{ if(dropped){ dropped=false; catchUp(); } };
const soon=(fn: ()=>void,ms=500)=>{ let t: number; return ()=>{ clearTimeout(t); t=setTimeout(fn,ms); }; };
// Caught: a network gone when one fires (a laptop asleep) was an unhandled rejection (#219).
const refreshEntries=soon(()=>{ if(S.feed) loadEntries().catch(()=>{}); });
const refreshEntries=soon(()=>{ if(S.feed) loadEntries(false,true).catch(()=>{}); });
// Every scan's events reach everyone; only this person's feeds are theirs to show or refresh.
const mine=(id: string)=>S.feeds.some(f=>f.id===id);
sse.onmessage=m=>{
@@ -41,7 +41,7 @@ function connect(){
if(!mine(ev.feed)) return;
if(ev.saved_s>0&&document.querySelector('.dapend')) toast(`DeadAir is done: ${shorter(ev.saved_s)}`);
refreshEntries();
if(S.sel) loadEntries().then(()=>{ const e=cur(); if(e) showDetail(e); }).catch(()=>{});
if(S.sel) loadEntries(false,true).then(()=>{ const e=cur(); if(e) showDetail(e); }).catch(()=>{});
}
else if(ev.ev==='download_error'){
const bar=document.querySelector(`.dlbar[data-bar="${ev.enclosure}"]`);

6
web/src/items.ts
View File

@@ -1,6 +1,7 @@
/* ---------------- items ---------------- */
let loadSeq=0;
async function loadEntries(append?: boolean){
/// `quiet` for a refresh nobody asked for (a live update): not a wait anyone sees, so not timed.
async function loadEntries(append?: boolean, quiet?: boolean){
// The Directory lists feeds, and Currently Listening draws its own episodes.
if(!S.feed || VIEWS[S.feed]?.url) return;
const p=new URLSearchParams({offset:String(S.offset),limit:String(LIMIT),filter:S.filter,sort:S.sort.col,dir:S.sort.dir});
@@ -29,6 +30,9 @@ async function loadEntries(append?: boolean){
}
S.entries = entries;
renderEntries();
// From asking to the list drawn: what someone waits for after a click, under that click's trace
// (#246). The API's own time is in the trace; this is the whole wait, the network included.
if(!quiet) report('list_shown',{ms:Math.round(performance.now()-asked),feed:S.feed,filter:S.filter});
}
function renderEntries(){
const box=$('#eps'); if(!box) return;

3
web/src/util.ts
View File

@@ -93,8 +93,9 @@ function traceparent(){
/// a frame.
const reported=new Map<string,number>();
function report(ev: string, o: Record<string,any>={}){
// A timing comes of something someone did, not a loop, so every one is sent.
const key=ev+(o.msg||''), now=Date.now();
if(o.msg==='signed out' || now-(reported.get(key)||0)<60_000) return;
if(o.msg==='signed out' || (o.ms==null && now-(reported.get(key)||0)<60_000)) return;
reported.set(key,now);
fetch('/api/client',{method:'POST',keepalive:true,headers:{'Content-Type':'application/json',traceparent:traceparent()},
body:JSON.stringify({ev,...o})}).catch(()=>{});