Skip to content

Performance degradation and API timeouts with nightly PlaceVisitsCalculatingJob #2963

Open
Open
Performance degradation and API timeouts with nightly PlaceVisitsCalculatingJob#2963
@treben

Description

@treben
treben
opened on Jun 17, 2026

BEFORE OPENING AN ISSUE, MAKE SURE YOU READ THIS: #1382

OS & Hardware
Synology 920+ DSM 7.3

Version
1.8.1

Describe the bug
Following recent updates (v1.8.x), background workers are stalling indefinitely, causing severe database contention and I/O saturation. This directly impacts the point ingestion API, forcing mobile trackers (GPSLogger) to hit socket timeouts and fail to upload points.

It potentially could be because PlaceVisitsCalculatingJob runs for 15+ hours everyday, triggering heavy disk read/write cycles on the points table, which then forces aggressive PostgreSQL autovacuuming that starves incoming API writes of disk performance.

Expected behavior
For the visits job to complete and free up the database so that new points can be ingested without timing out

Logs
When attempting to upload a single live point the request stalled for over 7 seconds with almost the entirety of that time spent waiting on the databse:

{"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2805,"duration":7156.69,"view":0.13,"db":7148.41}

Checking the sidekiq works shows that the nightly PlaceVisitsCalculatingJob is stalling and has been running for over 15 hours straight and repeats daily.

# Sidekiq::Workers output
{
  "queue" => "visit_suggesting",
  "payload" => "{\"retry\":false,\"queue\":\"visit_suggesting\",\"wrapped\":\"PlaceVisitsCalculatingJob\",\"args\":[{\"job_class\":\"PlaceVisitsCalculatingJob\",\"job_id\":\"ae6b8a65-92c1-49e5-8815-e9dbbd9d8a8b\",\"arguments\":[1],\"executions\":0}],\"class\":\"Sidekiq::ActiveJob::Wrapper\",\"jid\":\"235726dd440a7301f1aca50c\",\"created_at\":1781668819304,\"enqueued_at\":1781668819305}",
  "run_at" => 1781668819
}

Running a diagnostic query on the DB confirms aggressive autovacuuming is locking down the points table while active point inserts are delayed.

pid  |       age       |               query                | state  
-------+-----------------+------------------------------------+-------- 
 31568 | 00:00:01.435286 | COMMIT                             | active 
 12784 | 00:24:19.409439 | autovacuum: VACUUM public.points   | active

Additional context
Issue causes data loss/gaps due to mobile clients failing to dump full point payload. Also causing hardware strain due to constant unthrottled disk i/o. The issue seems to correlate with recent database migrations but I'm not sure.

Additional Logs

06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2944,"duration":9352.15,"view":0.12,"db":9338.71}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: 13cd667d-9e5b-4d09-ba14-ac79a5aac3f1) to Sidekiq(low_priority) with arguments: 1, 1781530484, 1781530484
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2672,"duration":3676.01,"view":0.13,"db":3666.79}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: f1c37ede-95e0-4345-952f-46b17d62f80c) to Sidekiq(low_priority) with arguments: 1, 1781530495, 1781530495
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2808,"duration":5405.56,"view":0.13,"db":5395.79}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: 8202bbef-6911-408b-bc5c-1bdaf1ada92e) to Sidekiq(low_priority) with arguments: 1, 1781265433, 1781265433
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2606,"duration":1432.49,"view":0.14,"db":1412.03}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: d3f42691-0e0f-457e-a287-395615679513) to Sidekiq(low_priority) with arguments: 1, 1781265442, 1781265442
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2667,"duration":2816.72,"view":0.21,"db":2805.97}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: 389bf595-438e-4494-98a3-650a3fc32b59) to Sidekiq(low_priority) with arguments: 1, 1781265678, 1781265678
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Tracks::RealtimeGenerationJob (Job ID: 7268bf1c-368e-4a6b-bf04-08d385b2cf32) to Sidekiq(tracks) at 2026-06-17 18:55:36 UTC with arguments: 1
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2840,"duration":4708.29,"view":0.13,"db":4698.92}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: f748e532-2e1b-4bd3-93c3-9d8655804ee3) to Sidekiq(low_priority) with arguments: 1, 1781265689, 1781265689
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2650,"duration":2080.78,"view":0.12,"db":2071.72}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: e61dae53-7a68-4355-bdf4-840813532f5f) to Sidekiq(low_priority) with arguments: 1, 1781530506, 1781530506
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2677,"duration":3726.46,"view":0.14,"db":3717.01}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: e838f1df-2544-4eb2-9180-d36d0928190e) to Sidekiq(low_priority) with arguments: 1, 1781265453, 1781265453
06/17/2026, 02:59:02 PM dawarich_app STDOUT: Enqueued Points::AnomalyFilterJob (Job ID: 5614cfcc-e363-46e0-a15d-2c3ad012cbe2) to Sidekiq(low_priority) with arguments: 1, 1781530516, 1781530516
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2641,"duration":2407.38,"view":0.16,"db":2394.9}
06/17/2026, 02:59:02 PM dawarich_app STDOUT: {"method":"POST","path":"/api/v1/owntracks/points","format":"html","controller":"Api::V1::Owntracks::PointsController","action":"create","status":200,"allocations":2625,"duration":2987.91,"view":0.78,"db":2973.83}

06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:29:10.312 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:35:00.842 UTC LOG:  checkpoint complete: wrote 1762 buffers (10.8%); 0 WAL file(s) added, 0 removed, 3 recycled; write=261.024 s, sync=60.800 s, total=351.729 s; sync files=20, longest=10.886 s, average=3.040 s; distance=48359 kB, estimate=48359 kB; lsn=60/295DE408, redo lsn=60/25F02388
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:35:00.842 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:38:42.141 UTC LOG:  checkpoint complete: wrote 1014 buffers (6.2%); 0 WAL file(s) added, 0 removed, 4 recycled; write=171.719 s, sync=24.559 s, total=221.299 s; sync files=20, longest=14.094 s, average=1.228 s; distance=57570 kB, estimate=57570 kB; lsn=60/2BDE99F8, redo lsn=60/2973AF38
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:40:00.219 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:45:03.467 UTC LOG:  checkpoint complete: wrote 821 buffers (5.0%); 0 WAL file(s) added, 0 removed, 4 recycled; write=261.812 s, sync=12.254 s, total=303.249 s; sync files=26, longest=5.819 s, average=0.472 s; distance=59538 kB, estimate=59538 kB; lsn=60/30D22028, redo lsn=60/2D15F808
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:45:03.467 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:48:44.227 UTC LOG:  checkpoint complete: wrote 992 buffers (6.1%); 0 WAL file(s) added, 0 removed, 4 recycled; write=173.573 s, sync=22.948 s, total=220.761 s; sync files=20, longest=10.524 s, average=1.148 s; distance=64254 kB, estimate=64254 kB; lsn=60/339396D8, redo lsn=60/3101F0D0
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:50:03.288 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:54:55.572 UTC LOG:  checkpoint complete: wrote 2617 buffers (16.0%); 0 WAL file(s) added, 0 removed, 4 recycled; write=254.434 s, sync=6.646 s, total=292.285 s; sync files=20, longest=6.204 s, average=0.333 s; distance=71548 kB, estimate=71548 kB; lsn=60/3919AD80, redo lsn=60/355FE328
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 16:55:03.577 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:01:11.381 UTC LOG:  checkpoint complete: wrote 5718 buffers (34.9%); 0 WAL file(s) added, 0 removed, 4 recycled; write=266.070 s, sync=69.638 s, total=367.804 s; sync files=19, longest=12.603 s, average=3.666 s; distance=67683 kB, estimate=71162 kB; lsn=60/3CB12460, redo lsn=60/39817000
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:01:11.381 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:07:17.214 UTC LOG:  checkpoint complete: wrote 882 buffers (5.4%); 0 WAL file(s) added, 0 removed, 3 recycled; write=230.012 s, sync=90.046 s, total=365.833 s; sync files=18, longest=17.934 s, average=5.003 s; distance=53934 kB, estimate=69439 kB; lsn=60/42D8CE20, redo lsn=60/3CCC2978
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:07:18.900 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:12:32.705 UTC LOG:  checkpoint complete: wrote 2261 buffers (13.8%); 0 WAL file(s) added, 0 removed, 7 recycled; write=262.357 s, sync=12.267 s, total=315.490 s; sync files=20, longest=7.047 s, average=0.614 s; distance=104017 kB, estimate=104017 kB; lsn=60/47A3A728, redo lsn=60/43256E50
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:12:32.705 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:17:41.603 UTC LOG:  checkpoint complete: wrote 3935 buffers (24.0%); 0 WAL file(s) added, 0 removed, 4 recycled; write=259.607 s, sync=24.761 s, total=308.898 s; sync files=23, longest=10.482 s, average=1.077 s; distance=79263 kB, estimate=101541 kB; lsn=60/4BAF2480, redo lsn=60/47FBEA70
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:17:41.603 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:22:39.486 UTC LOG:  checkpoint complete: wrote 1674 buffers (10.2%); 0 WAL file(s) added, 0 removed, 4 recycled; write=265.571 s, sync=14.018 s, total=297.883 s; sync files=21, longest=5.334 s, average=0.668 s; distance=65759 kB, estimate=97963 kB; lsn=60/4E816148, redo lsn=60/4BFF68D8
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:22:41.487 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:25:22.667 UTC LOG:  checkpoint complete: wrote 152 buffers (0.9%); 0 WAL file(s) added, 0 removed, 3 recycled; write=140.960 s, sync=5.303 s, total=161.180 s; sync files=19, longest=5.303 s, average=0.280 s; distance=43855 kB, estimate=92552 kB; lsn=60/51105D00, redo lsn=60/4EACA5D0
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:27:41.902 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:30:55.540 UTC LOG:  checkpoint complete: wrote 1326 buffers (8.1%); 0 WAL file(s) added, 0 removed, 6 recycled; write=163.218 s, sync=4.590 s, total=193.638 s; sync files=27, longest=3.384 s, average=0.170 s; distance=87522 kB, estimate=92049 kB; lsn=60/56F224E8, redo lsn=60/54043020
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:32:41.641 UTC LOG:  checkpoint starting: time
06/17/2026, 02:59:02 PM dawarich_db STDOUT: 2026-06-17 17:34:45.877 UTC LOG:  automatic vacuum of table "dawarich_production.public.points": index scans: 1
	pages: 0 removed, 52664 remain, 51728 scanned (98.22% of total)
	tuples: 6936 removed, 229280 remain, 6288 are dead but not yet removable
	removable cutoff: 2867717, which was 478 XIDs old when operation ended
	frozen: 5399 pages from table (10.25% of total) had 9037 tuples frozen
	index scan needed: 30211 pages from table (57.37% of total) had 51761 dead item identifiers removed
	index "points_pkey": pages: 1485 in total, 0 newly deleted, 0 currently deleted, 0 reusable
	index "index_points_on_import_id": pages: 687 in total, 0 newly deleted, 2 currently deleted, 2 reusable
	index "index_points_on_lonlat_timestamp_user_id": pages: 4328 in total, 0 newly deleted, 0 currently deleted, 0 reusable
	index "index_points_on_lonlat": pages: 12444 in total, 151 newly deleted, 873 currently deleted, 722 reusable
	index "index_points_on_raw_data_archive_id": pages: 484 in total, 0 newly deleted, 0 currently deleted, 0 reusable
	index "index_points_on_track_id": pages: 1001 in total, 2 newly deleted, 2 currently deleted, 0 reusable
	index "idx_points_user_country_name": pages: 647 in total, 0 newly deleted, 197 currently deleted, 197 reusable
	index "index_points_on_user_id_and_empty_geodata": pages: 1625 in total, 1 newly deleted, 1540 currently deleted, 1539 reusable
	index "idx_points_user_visit_null_timestamp": pages: 1691 in total, 0 newly deleted, 259 currently deleted, 259 reusable
	index "index_points_on_user_id_and_timestamp": pages: 1662 in total, 0 newly deleted, 0 currently deleted, 0 reusable
	index "index_points_on_visit_id": pages: 1276 in total, 17 newly deleted, 216 currently deleted, 214 reusable
	index "index_points_on_not_reverse_geocoded": pages: 1171 in total, 0 newly deleted, 1167 currently deleted, 1167 reusable
	index "idx_points_track_id_timestamp": pages: 2559 in total, 7 newly deleted, 256 currently deleted, 249 reusable
	index "index_points_on_user_id": pages: 385 in total, 0 newly deleted, 0 currently deleted, 0 reusable
	index "index_points_on_unarchived": pages: 1817 in total, 0 newly deleted, 0 currently deleted, 0 reusable
	avg read rate: 0.243 MB/s, avg write rate: 0.136 MB/s
	buffer usage: 77209 hits, 95785 misses, 53475 dirtied
	WAL usage: 72969 records, 47789 full page images, 250612623 bytes
	system usage: CPU: user: 1.21 s, system: 3.65 s, elapsed: 3079.63 s

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions