Most of a slow feed's scan time is in untraced work after the fetch #96

Closed
opened 2026-09-29 09:39:41 -07:00 by rays · 1 comment
Owner

In scan traces, a feed span often runs seconds longer than its fetch and site_icon children: mobilesyrup 4.1s with a 0.47s fetch (20 items, no files); legacy-of-the-ancients-rise-of-the-runel 3.5s with a 0.2s fetch (one item, inside the Glass Cannon Patreon group); androids-aliens 2.2s with 0.27s. Trace dc356eb2da00b0fe37865b55df9847b8 (67s scan, 2026-09-29 16:14).

Checking the feed's artwork takes about 0.15s, so the rest is the database work in scan_one: record_feed, policy_for, adopt (for a group's shows), skipped_by_filter, a record_entry and record_enclosure per item even when stored, rehide, pending. None has a span, so which one it is cannot be told from the trace.

Next step: spans around scan_one's phases (artwork, store, adopt, policy, rehide), then fix what they show. Likely candidates: skipping inserts for items already stored (one query for the feed's known guids and URLs instead of one per item), and adopt.

Feeds are also scanned one after another, so a scan takes the sum of every due feed's time; checking a few at once would shorten it, at the cost of more concurrent load on the database.

In scan traces, a feed span often runs seconds longer than its fetch and site_icon children: mobilesyrup 4.1s with a 0.47s fetch (20 items, no files); legacy-of-the-ancients-rise-of-the-runel 3.5s with a 0.2s fetch (one item, inside the Glass Cannon Patreon group); androids-aliens 2.2s with 0.27s. Trace dc356eb2da00b0fe37865b55df9847b8 (67s scan, 2026-09-29 16:14). Checking the feed's artwork takes about 0.15s, so the rest is the database work in scan_one: record_feed, policy_for, adopt (for a group's shows), skipped_by_filter, a record_entry and record_enclosure per item even when stored, rehide, pending. None has a span, so which one it is cannot be told from the trace. Next step: spans around scan_one's phases (artwork, store, adopt, policy, rehide), then fix what they show. Likely candidates: skipping inserts for items already stored (one query for the feed's known guids and URLs instead of one per item), and adopt. Feeds are also scanned one after another, so a scan takes the sum of every due feed's time; checking a few at once would shorten it, at the cost of more concurrent load on the database.
rays added the enhancement label 2026-09-29 09:39:41 -07:00
Author
Owner

Fixed in 57ab419, after the spans from 2799704 showed where the time went. Two full scans of 134 feeds, before and after: storing items 117s -> 0.1s (plus 0.12s for stored_items); the whole scan 315s -> 143s (da9a419b2637bf301e9ec4de910f613e, 146ec0fdd122db7eb4b5482cb7083c87). What is left is downloads (88s, 33 files), fetching (39s) and, on a forced scan only, artwork (12s). Checking several feeds at once is the remaining lever; not done.

Fixed in 57ab419, after the spans from 2799704 showed where the time went. Two full scans of 134 feeds, before and after: storing items 117s -> 0.1s (plus 0.12s for stored_items); the whole scan 315s -> 143s (da9a419b2637bf301e9ec4de910f613e, 146ec0fdd122db7eb4b5482cb7083c87). What is left is downloads (88s, 33 files), fetching (39s) and, on a forced scan only, artwork (12s). Checking several feeds at once is the remaining lever; not done.
rays closed this issue 2026-09-29 11:19:28 -07:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: rays/ipx#96