Summary
Between 11:15 UTC and 23:47 UTC on October 9, CircleCI customers experienced hours-long delays and failures across pipelines, workflows and jobs, along with delays in the CircleCI UI, API and notifications.
- From 11:15 to 13:00 UTC, pipelines were created but not processed, and outbound webhooks and Slack and email notifications were not sent.
- From 13:00 to 14:40 UTC, workflows and jobs started with delays while we worked through the backlog.
- From 15:15 to 20:48 UTC, workflows and jobs started with increasing delays, of up to about an hour, and the CircleCI UI and API fell behind by up to about 2 hours. During this time, some jobs failed to start and some in-progress workflows failed.
- From 20:48 to 22:10 UTC, we temporarily paused starting new workflows and jobs so our systems could recover. New pipelines were accepted and queued during this time.
- From 22:10 to 23:47 UTC, queued workflows and jobs resumed and were successfully processed. Some of them had waited up to about 2 hours.
- By 23:47, the incident was mitigated.
The status page for this incident can be found at October 9 - Delay in data appearing in UI and API. Customers experienced a similar incident earlier in the week at October 6 - Delays in pipelines, workflows, UI data, and notifications.
Multiple CircleCI services use Temporal backed by Postgres as a reliable queueing mechanism, and both incidents had the same cause: the rate of writes to Temporal’s Postgres instance were faster than Postgres’s transaction log could archive those writes. In both cases, this caused multi-hour delays in processing both pipelines and status notifications.
We evaluated several mitigations, then paused new workflow starts so the system could recover safely, and ramped back up gradually. We then throttled work back up until our systems returned to normal.
To permanently resolve the bottleneck, we have split work across multiple Temporal instances, each with its own independent database and worker clusters, and we load-balance across them. We had already scheduled infrastructure work starting the week of October 12 that would have removed this exact bottleneck and prevented these incidents. So starting 19:11 on October 9 our engineering team implemented, tested, and rolled out a simpler version of these changes within a few hours. We further added new alerting and tuned the underlying databases for better performance under high load.
Customers whose jobs failed during this window may rerun them.
Background
To run customer jobs, CircleCI executes a series of steps: we accept customer pipelines; we assign jobs for those pipelines to workers; we deliver status updates for those pipelines and jobs; and we charge customers for the credits those jobs consume. Each of these steps is implemented by an independent service, with reliable queues in between.
Historically we have implemented these reliable queues with RabbitMQ on top of durable storage, with exponential backoff and dead letter queues for reliability. Over the last year, we have increasingly reimplemented our reliable queues on Temporal, which provides far better durability and reliability guarantees over a simpler and more powerful programming model. Our build service (which turns a pipeline config into an executable plan), our workflow orchestrator service (which distributes tasks onto workers), our notification service (which delivers status updates), and our charging service (which charges customers for credits) all now use Temporal.
Temporal stores the state for its workflows and activities (called “history”) in a database, and this is the only component in a Temporal instance that is synchronous and stateful. As a consequence, a Temporal instance’s ability to accept and execute workflows is dependent on the write rate of its backing database. We have also configured Temporal to delete completed workflows and activities from its history 3 days after they complete.
At the time of this incident, we used a single clustered Temporal instance backed by a Multi-AZ Postgres RDS instance for all of these reliable queues. While a Multi-AZ RDS instance is resilient to zone failures, it maintains database consistency via a single write-ahead-log (WAL). At the time we had configured our Postgres instance to store its WAL on a Dedicated Log Volume (DLV) so log writes did not compete with data writes. The database archives the log continuously to backup storage, and it can only reuse space on the volume after the log has been archived. If the database writes logs faster than it archives, the volume fills and Postgres has no space to the write its WAL log. Then the database stops accepting incoming writes and goes entirely read-only. An RDS DLV is limited to 1TB of storage and 3000 IOPS and per AWS these limits are hardcoded and cannot be increased.
What Happened
(All times UTC)
One of the contributing factors to the October 6 incident was that we were processing a high rate of Temporal history deletions at the same time as incoming work, which in turn put pressure on the backing database. To resolve the October 6 incident, we changed cleanup settings on Temporal’s largest tables and moved the transaction log back to its dedicated volume. These changes eliminated the major source of transaction log writes, but did not consider the additional log writes from scheduled deletions. Because we have configured Temporal to delete completed workflows and activities from its history 3 days after they complete, the October 6 history was scheduled to be deleted on October 9.
Starting at 08:00 on October 9, Temporal began processing those scheduled deletions, and as a consequence free space on the Postgres DLV began dropping precipitously, from 0.8TB at 08:00 to 0.1TB by 10:10. Our monitoring alerted at 10:28 and we declared an incident at 10:31. While our infrastructure team was investigating, at 11:15 the DLV ran out of space and the Postgres instance went read-only. This stopped all Temporal processing in its tracks.
At 11:42, we restarted Postgres to move the WAL log from the DLV onto the data volume and use the spare disk space and IOPS there. This maneuver had mitigated the incident on October 6, and we knew it would take roughly 60 minutes.
While the database was restarting, we began implementing several load-shedding techniques upstream of Temporal:
- We began investigating whether we should shed incoming workloads altogether to keep the rest moving, but ultimately decided that this would provide no value.
- At 12:29, we flagged off credit charging updates, which represented 12% of Temporal activities. This left the Pipeline Usage page with stale charging data, until we would backfill it, but would not lose data or prevent pipelines from running.
At 12:59, the database was back up and began processing work that had queued since 11:15 and by 14:40, this backlog had cleared and jobs were starting on time. However, by 15:15, delays returned as database’s routing cleanup had fallen far behind on the tables Temporal uses to track queued and scheduled work. Those tables normally hold tens of thousands of deleted rows awaiting cleanup, but by late afternoon, they held tens of millions of rows. Every Temporal operation had to read past those rows, so the database spent much more processing time on each one and Temporal ran slower. This resulted in customers continuing to see hour-long delays in starting pipelines and in status updates.
For the next several hours we attempted various mitigations, including:
- Manipulating Temporal configuration values to reduce database pressure. This had minimal effect.
- Running manual vacuum jobs to clean up dead rows in Postgres. This ended up competing for CPU with queries themselves, and was ultimately counterproductive. We cancelled them at 17:45 to relieve the pressure on the database load.
- We began trying to move all of the notification usecases to a separate Temporal instance. This represented 18% of Temporal activities. We successfully finished moving notifications by 17:07.
- At 17:16, we successfully implemented an optimization in our representation of pipeline state, which reduced it by 5%. That in turn reduced the size of database writes and therefore data pressure on the Postgres WAL log.
None of these fully mitigated the issue.
By 20:48, we realized that Postgres was now thrashing on database CPU and was no longer bottlenecked on log writes. We further realized that our upstream systems were both submitting new work and also retrying work that had earlier been submitted and failed. Recognizing that we were in a classic retry storm, we paused all incoming and retry work and let it queue up, in order to allow the database to fully complete in-process work. We then slowly throttled up queued work from 22:07 to keep the database at a sustainable load.
This fully succeeded by 23:47 when all queued work had started, and we closed the incident at 02:08 on October 10.
Future Prevention and Process Improvement
Multiple Temporal Instances
In parallel with incident mitigation and resolution, starting at 19:11 on October 9, we also began standing up multiple sharded Temporal instances and implementing the ability to load-balance incoming work between them.
Each of the multiple Temporal instances maintains its own independent database and worker clusters, and so is isolated from the others. As a postmortem action item from the October 6 incident, we had already scheduled infrastructure work that would have removed the bottleneck of a single Temporal instance and Postgres database, starting October 12 and expecting to take 2 weeks. On October 9, we realized that this work simply could not wait, so our engineering team implemented, tested, and rolled out a simpler version of the planned changes within a few hours.
These changes completed successfully at 01:45 on October 10.
In addition, we are changing how we store and monitor transaction logs. Our Temporal database no longer uses the fixed-size log volume. We are adding alerts on how far log archiving falls behind and how fast the database writes logs, so we can act hours earlier than we did on October 9.
We are also revisiting the Temporal’s deletion schedule. Temporal deletes finished work a few days after it runs, so a busy day returns as database load later in the week. We are changing when and how quickly those deletions run.
We are changing how our systems retry when Temporal is slow. On October 9, our systems retried failed work against Temporal and added to its load. As we committed after the October 6 incident, we are changing our systems to wait for Temporal to recover so work is not dropped.
Conclusion
Customer experience is our top priority, and we commit to continually improving the reliability of our systems to match the trust that our customers place in us. We thank our customers for their patience while our team worked to resolve these incidents.
Please reach out to our support team with any questions or concerns.