Increased IO Wait in postgres

[Devidxyz]

Introduction

We have been using River for about a year, and we’ve had almost no issues that we couldn’t solve by tuning the configs or modifying the workers. Overall, we are very satisfied. However, in the last week, we encountered an issue twice that we haven’t been able to resolve yet.

We have the following versions in production:

github.com/riverqueue/river v0.20.2
github.com/riverqueue/river/riverdriver/riverpgxv5 v0.20.2
github.com/riverqueue/river/rivertype v0.20.2

Use-case

We run a go app in k8s, the rest API pods emit events, we insert these events to postgres as river jobs, and another deployment with river workers in it processes the events (make HTTP calls for the webhook subscriptions).

The problem

We noticed that fewer webhook calls were being made that the usual.
We checked what's happening in our DB with select state, count(*) from webhooks.river_job;:

   state   | count  
-----------+--------
 available |   1.404
 completed | 272.082
 discarded |  44.583
 retryable |  98.424
 running   |   2.739

Then we checked the error fields of the retryable jobs, and all of them errored with "Job rescued by rescuer".
We initially thought our workers couldn't process the jobs in time, but we only do an HTTP call in each job which has a 2 second timeout, so we were almost certain it's not the case.
Then we found many BatchCompleter: Completer error (will retry after sleep) and BatchCompleter: Too many errors; giving up log entries, all showing timeout: context deadline exceeded error. There were also JobScheduler: Error scheduling jobs and Elector: Error attempting reelection errors with the same context deadline exceeded cause.

For postgres we have a 4vCPU 16GB memory Cloud SQL instance. (Which is shared among some apps, but the current one is the most significant.)

Here we see a significant increase in IO wait. We eventually switch to maintenance mode around 7:30PM and tried to fix the error, that's why the load decreased, it wasn't natural. (The horizontal line in the chart is a different metric, it does not mean we hit the CPU limit or something. The CPU utilization was ~70-80% so we never hit 100%, when we doulbed the resources the utilization was ~60%.)

What we tried

• We deleted all the completed jobs, but the issue persisted
• We updated all the retryable and running jobs to available status, but the issue persisted
• We increased the DB resources to 8vCPU 32GB ram, the issue persisted
• We stopped the app completely, removed everything but the 120k available jobs from the river_jobs table, did a VACUUM, but when we started the app, the BatchCompleter: Completer error (will retry after sleep) errors appeared almost instantly, and only ~30% of the jobs were completed, the rest stayed in running, eventually in retryable state.

Now we will update river to the newest version, and see if the issue appears again.
We don't expect anyone to solve our problems, but we are curious if you seen something similar before, or have some tips what might be causing this behavior.

Another minor detail is that we use river in multiple databases in this cluster, even in multiple schemas in the same database, in case this has anything to do with our issue.

[brandur]

The first and foremost thing to check for is long running queries. These lead to bloat which leads to degraded performance elsewhere, and are often the culprit when it comes to operational trouble. Check for these with something like:

SELECT
  pid,
  now() - pg_stat_activity.query_start AS duration,
  query,
  state
FROM pg_stat_activity
WHERE (now() - pg_stat_activity.query_start) > interval '5 minutes';

[Devidxyz]

Thanks!!
We actually did that. On one occasion, it was the -- name: JobSetStateIfRunningMany :many ... query that was running for 6+ minutes. At another time, it was the -- name: JobSchedule :many ... query, along with autovacuum: VACUUM webhooks.river_job
These were in active state, I'm not counting idle connections.

In the meantime we are actively working to reproduce the issue in a sandbox environment.

[brandur]

Okay, let us know what you find. For what it's worth, none of your job numbers are very high (a few hundred thousand jobs is ~nothing), so it sounds like something quite degenerate is happening within the DB itself.

[Devidxyz]

We identified the root cause of the problem: our Postgres instance hit the maximum number of disk operations the SSD could handle, which led to increased IO timeouts for the queries

While this might seem unrelated to River, we encountered another anomaly during our load tests. After a certain number of jobs entered the retryable state, they stayed there indefinitely because the scheduler timed out.
In one of our load test we inserted 500 jobs per second, each with a 10% random fail rate. Initially, the worker pool processed about 500 jobs per second, but over time throughput dropped to 400 jobs per second, and the scheduler began timing out. With higher job insert rates we got the timeouts earlier, and even the "completed" job cleanup queries started to time out.

A very similar thing happens in our prod environment. For example, this afternoon I checked the prod jobs, and there were ~15k jobs in the retryable state (8k in completed, so ~23k jobs overall). The "retryable" jobs failed to schedule. The interesting part was what happened after I deleted all the "retryable" jobs:

The write operations per sec metric fall from around 10k/s to below 1k/sec.

Our theory:

1. Some jobs fail
2. Retryable jobs begin to accumulate
3. BatchCompleter and JobScheduler start timing out
4. This results in a sharp increase in disk IO

Around 4:00 PM, I deleted ~15k retryable jobs using select * from river_job where state = 'retryable'. As shown in the third chart, this single action reduced DB write operations from ~10k/s to <1k/s.

For now, we avoid putting jobs with non-negligible failure rates into River, but it would be good to understand what we might be overlooking.

[brandur]

Overall there's only so much you're going to be able to do when your database is in a severely degraded state (high churn components like your job queue are going to suffer first, but most things will suffer eventually), but I think we can improve this somewhat by trying to do work in smaller incremental batches if we detect trouble. The smaller the batch of work, the more likely it is to succeed in mandated timeout timeframe, and thereby at least make some progress. Opened #1013.

[Devidxyz]

Thank you very much, we look forward to seeing it in action.