Repository navigation
UsageManagerImpl.parse() rewind to the oldest unprocessed usage event is unbounded #13906
Description
Activity
Some production data for this, from a 4.22.1.0 cluster where the rewind had the aggregation window pinned for ten weeks.
cloud_usage.usage_job grouped by the recorded aggregation start:
start_date jobs 2026-06-04 16:50:51 1676 2026-06-02 00:00:00 1 2026-06-03 00:00:00 1 2026-06-04 00:00:00 1 2026-08-14 16:00:00 11,676 consecutive jobs, every one success = 1, all re-aggregating from the same instant. That timestamp is the created value of cloud_usage.usage_event id 1 (the first event the cluster ever emitted, and one that had never been processed). Nothing moved the window forward for ten weeks.
The same table grouped by the day the aggregation window started rather than the day the job ran, which is why the whole pinned period collapses into one row:
d jobs min_ms max_ms 2026-06-02 1 252 252 2026-06-03 1 116 116 2026-06-04 1677 570 3139799 2026-08-14 8 2143 2483 2026-08-15 24 2096 2361 2026-08-16 24 2099 2323 2026-08-17 20 2094 2263Within the pinned group exec_time grows from 570 ms on the first run to 3,139,799 ms, 52 minutes of every hour (on the last, since each run re-covered one more hourly period than the one before). cloud_usage reached 54,460,998 rows / 14 GB against roughly 150k genuine records.
Remediation was to force the six unprocessed events processed:
UPDATE cloud_usage.usage_event SET processed = 1 WHERE id IN (1,2,3,4,5,6);Update the flag rather than deleting the rows; getMostRecentEventId() is ORDER BY id DESC LIMIT 1 over the whole table and returns 0 on an empty one, which triggers COPY_ALL_EVENTS and re-copies every event with processed = 0.
From the next run onward the window advanced hourly and exec_time settled at ~2.1 s, as the 14 Aug row onward shows. Same code, same data volume, six rows changed, roughly a 1,460× reduction.
Two things made this hard to spot: all 1,676 of those runs recorded success = 1, and usage.sanity.check.interval was NULL, so the check that might have caught it was disabled.
On how the events got stuck in the first place, a duplicate-key failure on usage_volume (#13909) whose exception left the caller's transaction unbalanced (#13905), so the batch's processed flags were silently discarded. The rewind then pinned to them indefinitely.
problem
Split out of #13399 at @DaanHoogland's request.
UsageManagerImpl.parse()correctly derives its start date from the last successful job:and then overwrites it with the create date of the oldest unprocessed event, moving it only ever earlier:
eventscomes fromUsageEventDaoImpl.listLatestEvents()—WHERE processed = 0 AND created <= ? ORDER BY createDate ASC, with no limit and no floor.Consequence: any event that can never be successfully processed pins the aggregation start date permanently. Each subsequent run re-aggregates from that date to the present, growing by one aggregation range per range elapsed. The job continues to report
success = 1throughout, so nothing surfaces as an error.Measured on an affected 4.22.1.0 deployment:
start_millisnever advanced past a single event 71 days earlierexec_timeof 2,555,055 ms (42.6 min) per hourly run, growing by 24 aggregation periods per daycloud_usageat 54.4M rows / 14 GB, of which roughly 150k rows were genuine; duplicate counts were an exact multiple of the number of replaysNot specific to one event type: #13112 was reported on 4.21.0.0 against
usage_type = 13, predating the volume-specific trigger in #13399. The rewind is the common mechanism; the triggering event type varies.versions
Observed on CloudStack 4.22.1.0 (EL9 packages), MySQL 8.x / InnoDB, with
usage.stats.job.aggregation.range = 60andusage.stats.job.exec.time = 00:15.#13112 reports the same mechanism on 4.21.0.0, so this is not new in 4.22.
The steps to reproduce the bug
cloud_usage.usage_eventthat cannot be successfully processed, Usage Server repeatedly reprocesses historical usage and creates duplicate cloud_usage records for usage_type=1 #13399 gives one reliable route, but the mechanism is independent of cause.SELECT id, start_date, end_date, exec_time FROM cloud_usage.usage_job WHERE success = 1 ORDER BY id DESC LIMIT 5;—start_datestays pinned at the oldest unprocessed event'screatedwhileend_dateadvances.TIMESTAMPDIFF(HOUR, start_date, end_date)grows without bound, as doesexec_time.cloud_usage.cloud_usageper period equal the number of times that period has been re-aggregated.What to do about it?
Bound the rewind, and/or provide a way to quarantine or age out events that repeatedly fail to process, so one unprocessable row cannot halt aggregation indefinitely.
This is a design decision rather than an obvious patch, which is why it's raised separately from #13399.