Skip to content

UsageManagerImpl.parse() rewind to the oldest unprocessed usage event is unbounded #13906

Description

@Alpha162

problem

Split out of #13399 at @DaanHoogland's request.

UsageManagerImpl.parse() correctly derives its start date from the last successful job:

long lastSuccess = _usageJobDao.getLastJobSuccessDateMillis();
if (lastSuccess != 0) {
    startDateMillis = lastSuccess + 1;
}

and then overwrites it with the create date of the oldest unprocessed event, moving it only ever earlier:

// make sure start date is before all of our un-processed events
Date oldestEventDate = events.get(0).getCreateDate();
if (oldestEventDate.getTime() < startDateMillis) {
    startDateMillis = oldestEventDate.getTime();
    startDate = new Date(startDateMillis);
}

events comes from UsageEventDaoImpl.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 = 1 throughout, so nothing surfaces as an error.

Measured on an affected 4.22.1.0 deployment:

  • 1,678 consecutive successful jobs whose start_millis never advanced past a single event 71 days earlier
  • exec_time of 2,555,055 ms (42.6 min) per hourly run, growing by 24 aggregation periods per day
  • cloud_usage at 54.4M rows / 14 GB, of which roughly 150k rows were genuine; duplicate counts were an exact multiple of the number of replays

Not 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 = 60 and usage.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

  1. Have any row in cloud_usage.usage_event that 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.
  2. Let the usage job run on its normal schedule.
  3. SELECT id, start_date, end_date, exec_time FROM cloud_usage.usage_job WHERE success = 1 ORDER BY id DESC LIMIT 5;start_date stays pinned at the oldest unprocessed event's created while end_date advances.
  4. TIMESTAMPDIFF(HOUR, start_date, end_date) grows without bound, as does exec_time.
  5. Row counts in cloud_usage.cloud_usage per 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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions