The slowest requests on our API were the ones that found nothing

On 9 September 2026, asking our API for the most recent port event of a vessel took 28 ms if the vessel had one and 2.0 to 2.5 s if it had none. Asking for the ETA of a vessel whose IMO we could not map to an MMSI took 12 s on a quiet database and 30 s or more on a busy one, until the statement timeout ended it. Over one night, requests that ended in "not found" used 71% of all the database time spent on the ETA endpoint.

All times below are UTC. Query timings are server-side, from EXPLAIN ANALYZE or the API request log, on TimescaleDB 2.25 and PostgreSQL 16 unless a line says otherwise. A vessel has two identifiers in this post: the MMSI, a radio identity that every AIS message carries, and the IMO number, a hull identity that many messages and records lack.

In March I wrote about moving this platform to TimescaleDB. That post describes vessel_positions: one-hour chunks, compressed after two hours, segmented by MMSI, ordered by time. Positions are mostly read by MMSI and time, which is what those settings are for. port_events and vessel_eta got the same settings. Both are queried by other columns. The settings were wrong for both.

Which requests were slow

Our latency dashboard averaged by raw path, so a single 40 s call to one port sat at the top of the "slowest paths" panel and told us nothing. Grouping by route template (/v1/vessel/{id}/eta, not /v1/vessel/9123456/eta) over six hours showed something else. Two port-event routes were slow in the median, and only when the answer was empty. A port with recent events answered in 10 to 100 ms. A small port with no events in the requested window took 3.6 to 4.3 s, every time. No external call sits on those paths and there was no cache to miss, so the difference was in how many chunks the query touched.

Why a miss visited every chunk

port_events had 764 one-hour chunks, and 760 of them were compressed (the columnstore, in current TimescaleDB terms) with these settings:

ALTER TABLE port_events SET (
  timescaledb.compress,
  timescaledb.compress_segmentby = 'vessel_mmsi',
  timescaledb.compress_orderby   = 'timestamp DESC'
);

Our migrations use these older names throughout. Current TimescaleDB spells them timescaledb.enable_columnstore, timescaledb.segmentby and timescaledb.orderby, and elsewhere in this post convert_to_rowstore, remove_columnstore_policy and hypertable_columnstore_stats.

The query for the most recent port event filters on IMO, with a time bound wide enough to cover every chunk, so the bound prunes nothing:

SELECT ... FROM port_events
WHERE vessel_imo = $1 AND timestamp > now() - $2::interval
ORDER BY timestamp DESC LIMIT 1;

The table has a btree index on (vessel_imo, timestamp). On a compressed chunk that index is still defined and holds nothing. The rows live in an internal table whose only index covers the segment column and the time metadata, so only the four or so uncompressed chunks at the head of the table had a usable IMO index. With ORDER BY timestamp DESC LIMIT 1 the executor visits chunks newest first and stops at the first row, so a vessel with a recent event returns quickly. A vessel with no event has no first row, and the plan for a miss had one sequential scan per compressed chunk. The same miss by MMSI, the segment column, took 0.12 s on the same chunks.

Compression packs up to a thousand rows of one segment into a batch and compresses each column across them. TimescaleDB 2.25 also keeps a bloom filter per batch for columns such as vessel_imo, which should let a miss skip most batches without decompressing them. The per-chunk node looks like this (from our local rehearsal of vessel_eta on 2.28, time conditions elided; production on 2.25 has the same shape with bloom1_contains):

->  Custom Scan (ColumnarScan) on _hyper_3_1664_chunk (actual rows=1 loops=1)
      Vectorized Filter: ((imo = $1) AND ...)
      Rows Removed by Filter: 29
      ...
      ->  Seq Scan on compress_hyper_4_1739_chunk (actual rows=29 loops=1)
            Filter: (_timescaledb_functions.bloom1_contains_any_hashes(_ts_meta_v2_bloomh_imo, ARRAY[_timescaledb_functions.bloom1_hash($1)]) AND ...)
            Rows Removed by Filter: 48
            ...

The inner scan reads the chunk's batches and tests the bloom filter and the time metadata, which rejected 48 of 77 batches here. The other 29 were decompressed and the outer filter kept one row (the rehearsal seed has about one row per batch). In production the filter skipped far less, for a reason in our data. A large minority of port_events rows carry no IMO. A batch whose IMO values are all NULL carries a NULL bloom filter, and a NULL filter passes every lookup.

The by-port query had a second problem, in our SQL. It compared the port code with COALESCE((SELECT ...), $1), a subquery that resolves an alternative code. TimescaleDB pushes many right-hand expressions down to the bloom filter, and in the versions we ran COALESCE is not among them. Ours was skipped, and every batch in every chunk of the requested window was decompressed: 6.05 s for a port that had two rows. The same query with a plain bound parameter took 0.84 s. We now resolve the code in Go first and pass it as a parameter, and a test asserts that the generated SQL contains no subquery.

Compression saved 0.1% on port_events

hypertable_compression_stats('port_events') reported 1,689 MB before compression and 1,687 MB after.

Segmenting by MMSI inside a one-hour chunk means a batch holds one vessel's port events for one hour. A vessel rarely has more than one, and most of our segments held a single row, so there was nothing to compress across. On vessel_eta, where a vessel reports many times an hour, the same settings give 3.0x.

Compression cost us the use of every index except the one on the segment column, across 760 chunks, and returned 2 MB. The options we looked at:

• Add vessel_imo and port_unlo_code to segmentby. Lookups by those columns would get an index on the compressed chunk, and the segments would become smaller still. We did not test it. With one row per segment there was no compression to keep, and that index would have been a slower copy of the btree we already had.
• A negative cache in the API for misses. We checked the request log first. Repeat requests for the same path arrived more than an hour apart, so a short TTL would never hit.
• Daily chunks with no compression, so the btree indexes work on every chunk. We chose this one. It costs disk: the table grew by about a sixth.

Decompressing 762 chunks under live traffic

By the evening 762 chunks were compressed. The first migration removes the compression policy and changes the interval. The order matters, because the policy's job runs every 30 minutes and would recompress chunks behind the loop.

BEGIN;
SET LOCAL lock_timeout = '5s';
SET LOCAL statement_timeout = '60s';
SELECT remove_compression_policy('port_events', if_exists => true);
SELECT set_chunk_time_interval('port_events', INTERVAL '1 day');
COMMIT;

set_chunk_time_interval applies to new chunks only. Existing hourly chunks keep their ranges until retention drops them.

A single SELECT decompress_chunk(c) FROM show_chunks(...) would hold locks on every chunk until the end. We ran a loop with one chunk per transaction, newest first. decompress_chunk holds an exclusive lock while it copies, which lets reads continue (nothing writes to chunks that old), and a brief access-exclusive lock at the end. Each call runs with lock_timeout = 5s and is retried on timeout, so the loop never queues behind API readers for long. It pauses between chunks, aborts if other sessions start waiting on locks, suspends the retention and continuous aggregate jobs (TimescaleDB's materialised rollups) while it runs, and can be rerun, since it selects only chunks that are still compressed.

We rehearsed it on a local container with 3.1M synthetic rows in 745 chunks, 742 of them compressed, and the loop decompressed those in 341 s. We predicted 15 to 20 minutes for production. It took 2,280 s, about 3 s a chunk, because rebuilding the indexes on each decompressed chunk cost more on real data than on the seed. There were no lock-timeout retries and no aborts, a watcher sampling the API once a minute saw no 5xx, and the row count before the cutoff was identical afterwards. The second migration sets timescaledb.compress = false. TimescaleDB returns an error if any compressed chunk remains, so the migration counts them first and stops with a message naming the loop to run.

Planning still costs 75 to 100 ms per query across roughly 750 chunks, and falls as the hourly chunks age out.

vessel_eta needed a different fix

vessel_eta is 78 GB across 752 hourly chunks, segmented by MMSI. Compression earns its 3.0x there and stays. The API asks it two questions. One is the newest ETA report for a vessel. The other is which vessels are inbound to a port. Both ask for the current state. The table holds weeks of history.

By MMSI the first question is cheap. By IMO it is cheap only when we can map the IMO to an MMSI. When we cannot, the query filters on imo, which is neither the segment column nor the order column, and walks every chunk: 12 s warm, and up to the statement timeout under load. The bloom filter on imo helps less than it sounds. The scan still reads every batch's metadata row in every chunk to test it, and batches with no IMO pass. The inbound query filters on destination_port and has the same problem. With a freshness window of several days it covers well over a hundred chunks, and took 12.5 s on a good day.

For a day we blamed the wrong thing for part of this. Metrics showed a 10 to 25 s transaction at the top of every hour, and a continuous aggregate refresh is scheduled hourly. The next morning, with ten hours of traffic to read, the refresh turned out to run at three minutes past the hour and take 10 to 16 s. The longer transactions were these IMO lookups, in requests arriving on the hour.

As a stopgap we capped concurrent history scans and added a short-lived negative cache for IMOs with no ETA. The cache was switched off once the table below existed.

The fix is a plain PostgreSQL table next to the hypertable that holds the newest report per key:

CREATE TABLE vessel_eta_latest (
    mmsi             BIGINT      NOT NULL,
    imo              BIGINT,
    destination_port TEXT,
    eta              TIMESTAMPTZ,
    timestamp        TIMESTAMPTZ NOT NULL,
    -- ... payload columns ...
    dest_key TEXT        GENERATED ALWAYS AS (COALESCE(destination_port, '')) STORED,
    eta_key  TIMESTAMPTZ GENERATED ALWAYS AS (COALESCE(eta, '-infinity'::timestamptz)) STORED,
    imo_key  BIGINT      GENERATED ALWAYS AS (COALESCE(imo, 0)) STORED,
    PRIMARY KEY (mmsi, dest_key, eta_key, imo_key)
) WITH (fillfactor = 80, autovacuum_vacuum_scale_factor = 0.02);

One row per vessel is the obvious design, and it returns different answers from the hypertable. At two large ports it dropped 8 of 58 and 8 of 166 inbound vessels, because a vessel had since reported another destination. One row per vessel and destination still dropped 3 and 2, where an ETA had been revised out of the requested window. One row per vessel, destination and ETA value dropped none. IMO is in the key because about a third of reports carry no IMO. Vessels rarely revise an ETA (97.7% of vessel and destination pairs carry a single ETA value in any hour), so the table stays small: 592,672 rows and 248 MB with indexes.

The ingestion service upserts into it after every batch it writes to the hypertable, with ON CONFLICT (...) DO UPDATE ... WHERE EXCLUDED.timestamp >= vessel_eta_latest.timestamp. Each batch is reduced to one row per key first, since one statement cannot update the same row twice. A daily job deletes rows past the retention window.

We checked that the two read paths agree before switching. Locally, EXCEPT in both directions between the hypertable queries and the table queries returned 0 rows. A byte diff of 4,105 API responses between the two read modes also showed no differences, and we counted it as a pass. In production, 500 random MMSIs and 20 random IMOs matched, and so did 37 of 38 port windows. The 38th differed by 4 rows and matched on the next run: the writer commits the hypertable insert and the upsert as two transactions, and the comparison had landed between them. A report now appears on the ETA endpoints a moment later than it used to. A request for inbound vessels as of a past time still goes to the hypertable.

The backfill copied the history in six-hour slices of 20 to 45 s each, and partway through PostgreSQL reported deadlock detected (SQLSTATE 40P01). A slice inserted in key order and held its row locks for the whole statement, and ON CONFLICT DO UPDATE locks the conflicting row even when the WHERE clause then rejects the update. The live writer upserted in arrival order, so the two statements locked the same rows in different orders. 19 live batches lost their upsert (the hypertable rows were intact, and nothing read the table yet). The writer and the backfill now sort by the key in plain byte order (COLLATE "C" on the text column, which matches Go's string ordering), and the statement uses unnest(...) WITH ORDINALITY ... ORDER BY ord. PostgreSQL does not document the order in which one statement takes its row locks. In this shape it follows the input order, and both sides retry on 40P01 in case it does not. The ordering was needed regardless of the backfill. Two hours later, with no bulk job running, the live writer deadlocked against itself.

Once reads had moved, we changed the vessel_eta chunk interval from one hour to six. (Tiger Data's guidance sizes the indexes of the chunk being written against a quarter of memory. We were more conservative and looked at the whole uncompressed chunk with its indexes: about 300 MB for an hour, so about 1.8 GB for six hours and 7 GB for a day. A day would not fit the write working set.) The first full six-hour chunk compressed from 1,734 MB to 443 MB in about 31 s. That is 3.9x against 3.0x for the hourly chunks, presumably because a segment now holds six hours of a vessel's reports.

The release that returned 500 on two endpoints

The API release that switched reads to the new table failed in production. For about half an hour the ETA and inbound endpoints returned 500 to every request. Other endpoints and ingestion were unaffected. Post-deploy probes caught it within minutes and we rolled back to the previous build. The fixed build shipped the same evening.

The new query selected NULL::uuid AS id, because the table has no id column and the row scanner expected one. The scanner read id into a Go string. pgx v5 returns can't scan into dest[0] (col: id): cannot scan NULL into *string. The fix is *string. The value is never used.

Two checks had passed before this release. The SQL equivalence check was sound, and by design it cannot see an error in Go's row scanning. The API diff could have seen it, and it never ran against the new code. It starts two local servers, one per read mode, sends the same requests to both and compares the bodies. A server from a test earlier that day was still running and held the port. Both new servers failed to bind, with "address already in use" in a log we did not read at the time, and every request of both passes went to the old process. The 4,105 responses were byte-identical because one server had produced all of them.

Re-running the diff on the fixed code exposed a second gap. Every inbound request in every earlier local run had returned 400 on both sides, because the script asked for a page of 200 and the limit is 50. We had been comparing two identical error bodies.

The re-validation compared about 11,600 responses on each side. 13 differed on a window boundary (a vessel due at exactly 20:00:00, with the two passes either side of 20:00) and matched with a fixed window.

What changed in how we release:

• The diff script exits at start if its port is taken, and checks for its own server's startup line before sending anything.
• A test behind an environment variable scans a real row from the new table. On the broken commit it fails with the production error.
• The built binary is probed against a real row after the final edit.
• The probe set runs as soon as a new instance is serving.

A background job filled the request pool

That table still has a 567 ms p99, and one inbound request took 13.6 s. All 12 ETA and inbound requests over 3 s in those 14.5 hours fell in six one-minute slots. In each, the API's request pool was fully occupied, with hundreds of seconds of acquire wait per minute summed across waiting requests. Three ETA calls finished together at an identical 13.0 s, which fits requests queued for a connection.

A request for vessel details can trigger a background refresh of that vessel's aggregates, and a burst of detail requests across many vessels started many of them at once on the pool that serves requests. The refresh now has its own small pool with a concurrency cap, and a refresh that waits too long is dropped. None was dropped in the next 18 hours, the request pool stayed well below its limit, and ETA p99 was 32 ms.

The true top-of-hour spike, found on the evening of 10 September, was ours. An hourly job in our ingestion service ran SELECT DISTINCT imo over two days of positions and took 58 s. It now reads vessel_eta_latest, a close enough list of active vessels for that job, and takes 0.3 s.

Three quarters of the ETA rows were copies

Some reports reach us again after we have already stored them, identical in vessel, report time and content. The copies were byte-identical repeats of reports we already held. The ETA and inbound endpoints return one report per vessel, the newest that matches, so a copy never appeared in a response. An earlier fix had removed such repeats from positions. vessel_eta still stored them.

The latest-row table made the check cheap. Before inserting, the ingestion service compares each incoming report with the row for its key and drops it when the two are identical. A new report is stored as before. A report that arrives out of order and cannot be shown to be a copy by a second exact lookup is also kept. Reports of that kind were 0.7% of what the check examined. The check adds about 0.6 s to each batch.

Rows written fell by about three quarters against the same quarter hour of the same weekday a week earlier, and by a little more on a second weekday. The check can only drop a report that matches a stored one exactly, so it cannot remove a distinct report. Distinct reports per vessel moved by a few per cent, up on one day and down on the other. A six-hour chunk went from 1.8 GB to about 440 MB uncompressed, and from 450 MB to 125 MB compressed. Every row of vessel_eta_latest touched in a six-hour window had an identical row in the hypertable.

Had we done this first, the 78 GB table would probably have been under 20 GB, going by that reduction. We did it last because the check depends on the latest-row table, which did not exist until the second day.

What is left

Requests for inbound vessels as of a past time are still served from the hypertable, a path this work did not speed up. port_events planning stays at 75 to 100 ms until its hourly chunks have aged out, and vessel_eta waits the same way for its six-hour chunks.

Bounding-box queries over positions are untouched by this work and are next.