Why we spent the last month eliminating PostgreSQL subtransactions

Since last June, we noticed the database on GitLab.com would
mysteriously stall for minutes, which would lead to users seeing 500
errors during this time. Through a painstaking investigation over
several weeks, we finally uncovered the cause of this: initiating a
subtransaction via the SAVEPOINT SQL query while
a long transaction is in progress can wreak havoc on database
replicas. Thus launched a race, which we recently completed, to
eliminate all SAVEPOINT queries from our code. Here's what happened,
how we discovered the problem, and what we did to fix it.

The symptoms begin

On June 24th, we noticed that our CI/CD runners service reported a high
error rate:

A quick investigation revealed that database queries used to retrieve
CI/CD builds data were timing out and that the unprocessed builds
backlog grew at a high rate:

Our monitoring also showed that some of the SQL queries were waiting for
PostgreSQL lightweight locks (LWLocks):

In the following weeks we had experienced a few incidents like this. We were
surprised to see how sudden these performance degradations were, and how
quickly things could go back to normal:

Introducing Nessie: Stalled database queries

In order to learn more, we extended our observability tooling to sample
more data from pg_stat_activity. In PostgreSQL, the pg_stat_activity
virtual table contains the list of all database connections in the system as
well as what they are waiting for, such as a SQL query from the
client. We observed a consistent pattern: the queries were waiting on
SubtransControlLock. Below shows a graph of the URLs or jobs that were
stalled:

The purple line shows the sampled number of transactions locked by
SubtransControlLock for the POST /api/v4/jobs/request endpoint that
we use for internal communication between GitLab and GitLab Runners
processing CI/CD jobs.

Although this endpoint was impacted the most, the whole database cluster
appeared to be affected as many other, unrelated queries timed out.

This same pattern would rear its head on random days. A week would pass
by without incident, and then it would show up for 15 minutes and
disappear for days. Were we chasing the Loch Ness Monster?

Let's call these stalled queries Nessie for fun and profit.

What is a SAVEPOINT?

To understand SubtransControlLock (PostgreSQL
13
renamed this to SubtransSLRU), we first must understand how
subtransactions work in PostgreSQL. In PostgreSQL, a transaction can
start via a BEGIN statement, and a subtransaction can be started with
a subsequent SAVEPOINT query. PostgreSQL assigns each of these a
transaction ID (XID for short) when a transaction or a subtransaction
needs one, usually before a client modifies data.

Why would you use a SAVEPOINT?

For example, let's say you were running an online store and a customer
placed an order. Before the order is fullfilled, the system needs to
ensure a credit card account exists for that user. In Rails, a common
pattern is to start a transaction for the order and call
find_or_create_by. For
example:

Order.transaction do
  begin
    CreditAccount.transaction(requires_new: true) do
      CreditAccount.find_or_create_by(customer_id: customer.id)
  rescue ActiveRecord::RecordNotUnique
    retry
  end
  # Fulfill the order
  # ...
end

If two orders were placed around the same time, you wouldn't want the
creation of a duplicate account to fail one of the orders. Instead, you
would want the system to say, "Oh, an account was just created; let me
use that."

That's where subtransactions come in handy: the requires_new: true
tells Rails to start a new subtransaction if the application already is
in a transaction. The code above translates into several SQL calls that
look something like:

--- Start a transaction
BEGIN
SAVEPOINT active_record_1
--- Look up the account
SELECT * FROM credit_accounts WHERE customer_id = 1
--- Insert the account; this may fail due to a duplicate constraint
INSERT INTO credit_accounts (customer_id) VALUES (1)
--- Abort this by rolling back
ROLLBACK TO active_record_1
--- Retry here: Start a new subtransaction
SAVEPOINT active_record_2
--- Find the newly-created account
SELECT * FROM credit_accounts WHERE customer_id = 1
--- Save the data
RELEASE SAVEPOINT active_record_2
COMMIT

On line 7 above, the INSERT might fail if the customer account was
already created, and the database unique constraint would prevent a
duplicate entry. Without the first SAVEPOINT and ROLLBACK block, the
whole transaction would have failed. With that subtransaction, the
transaction can retry gracefully and look up the existing account.

What is SubtransControlLock?

As we mentioned earlier, Nessie returned at random times with queries
waiting for SubtransControlLock. SubtransControlLock indicates that
the query is waiting for PostgreSQL to load subtransaction data from
disk into shared memory.

Why is this data needed? When a client runs a SELECT, for example,
PostgreSQL needs to decide whether each version of a row, known as a
tuple, is actually visible within the current transaction. It's possible
that a tuple has been deleted or has yet to be committed by another
transaction. Since only a top-level transaction can actually commit
data, PostgreSQL needs to map a subtransaction ID (subXID) to its parent
XID.

This mapping of subXID to parent XID is stored on disk in the
pg_subtrans directory. Since reading from disk is slow, PostgreSQL
adds a simple least-recently used (SLRU) cache in front for each
backend process. The lookup is fast if the desired page is already
cached. However, as Laurenz Albe discussed in his blog
post,
PostgreSQL may need to read from disk if the number of active
subtransactions exceeds 64 in a given transaction, a condition
PostgreSQL terms suboverflow. Think of it as the feeling you might get
if you ate too many Subway sandwiches.

Suboverflowing (is that a word?) can bog down performance because as
Laurenz said, "Other transactions have to update pg_subtrans to
register subtransactions, and you can see in the perf output how they
vie for lightweight locks with the readers."

Hunting for nested subtransactions

Laurenz's blog post suggested that we might be using too many
subtransactions in one transaction. At first, we suspected we might be
doing this in some of our expensive background jobs, such as project
export or import. However, while we did see numerous SAVEPOINT calls
in these jobs, we didn't see an unusual degree of nesting in local
testing.

To isolate the cause, we started by adding Prometheus metrics to track
subtransactions as a Prometheus metric by model.
This led to nice graphs as the following:

While this was helpful in seeing the rate of subtransactions over time,
we didn't see any obvious spikes that occurred around the time of the
database stalls. Still, it was possible that suboverflow was happening.

To see if that was happening, we instrumented our application to track
subtransactions and log a message whenever we detected more than 32
SAVEPOINT calls in a given transaction. Rails
makes it possible for the application to subscribe to all of its SQL
queries via ActiveSupport notifications. Our instrumentation looked
something like this, simplified for the purposes of discussion:

ActiveSupport::Notifications.subscribe('sql.active_record') do |event|
  sql = event.payload.dig(:sql).to_s
  connection = event.payload[:connection]
  manager = connection&.transaction_manager

  context = manager.transaction_context
  return if context.nil?

  if sql.start_with?('BEGIN')
    context.set_depth(0)
  elsif cmd.start_with?('SAVEPOINT', 'EXCEPTION')
    context.increment_savepoints
  elsif cmd.start_with?('ROLLBACK TO SAVEPOINT')
    context.increment_rollbacks
  elsif cmd.start_with?('RELEASE SAVEPOINT')
    context.increment_releases
  elsif sql.start_with?('COMMIT', 'ROLLBACK')
    context.finish_transaction
  end
end

This code looks for the key SQL commands that initiate transactions and
subtransactions and increments counters when they occurred. After a
COMMIT, we log a JSON message that contained the backtrace and the
number of SAVEPOINT and RELEASES calls. For example:

{
  "sql": "/*application:web,correlation_id:01FEBFH1YTMSFEEHS57FA8C6JX,endpoint_id:POST /api/:version/projects/:id/merge_requests/:merge_request_iid/approve*/ BEGIN",
  "savepoints_count": 1,
  "savepoint_backtraces": [
    [
      "app/models/application_record.rb:75:in `block in safe_find_or_create_by'",
      "app/models/application_record.rb:75:in `safe_find_or_create_by'",
      "app/models/merge_request.rb:1859:in `ensure_metrics'",
      "ee/lib/analytics/merge_request_metrics_refresh.rb:11:in `block in execute'",
      "ee/lib/analytics/merge_request_metrics_refresh.rb:10:in `each'",
      "ee/lib/analytics/merge_request_metrics_refresh.rb:10:in `execute'",
      "ee/app/services/ee/merge_requests/approval_service.rb:57:in `calculate_approvals_metrics'",
      "ee/app/services/ee/merge_requests/approval_service.rb:45:in `block in create_event'",
      "ee/app/services/ee/merge_requests/approval_service.rb:43:in `create_event'",
      "app/services/merge_requests/approval_service.rb:13:in `execute'",
      "ee/app/services/ee/merge_requests/approval_service.rb:14:in `execute'",
      "lib/api/merge_request_approvals.rb:58:in `block (3 levels) in <class:MergeRequestApprovals>'",
    ]
  "rollbacks_count": 0,
  "releases_count": 1
}

This log message contains not only the number of subtransactions via
savepoints_count, but it also contains a handy backtrace that
identifies the exact source of the problem. The sql field also
contains Marginalia comments
that we tack onto every SQL query. These comments make it possible to
identify what HTTP request initiated the SQL query.

Taking a hard look at PostgreSQL

The new instrumentation showed that while the application regularly used
subtransactions, it never exceeded 10 nested SAVEPOINT calls.

Meanwhile, Nikolay Samokhvalov, founder
of Postgres.ai, performed a battery of tests trying to replicate the problem.
He replicated Laurenz's results when a single transaction exceeded 64
subtransactions, but that wasn't happening here.

When the database stalls occurred, we observed a number of patterns:

1. Only the replicas were affected; the primary remained unaffected.
2. There was a long-running transaction, usually relating to
   PostgreSQL's autovacuuming, during the time. The stalls stopped quickly after the transaction ended.

Why would this matter? Analyzing the PostgreSQL source code, Senior
Support Engineer Catalin Irimie posed an
intriguing question that led to a breakthrough in our understanding:

Does this mean that, having subtransactions spanning more than 32 cache pages, concurrently, would trigger the exclusive SubtransControlLock because we still end up reading them from the disk?

Reproducing the problem with replicas

To answer this, Nikolay immediately modified his test to involve replicas and long-running transactions. Within a day, he reproduced the problem:

The image above shows that transaction rates remain steady around
360,000 transactions per second (TPS). Everything was proceeding fine
until the long-running transaction started on the primary. Then suddenly
the transaction rates plummeted to 50,000 TPS on the replicas. Canceling
the long transaction immediately caused the transaction rate to return.

What is going on here?

In his blog post, Nikolay called the problem Subtrans SLRU overflow.
In a busy database, it's possible for the size of the subtransaction log
to grow so large that the working set no longer fits into memory. This
results in a lot of cache misses, which in turn causes a high amount of
disk I/O and CPU as PostgreSQL furiously tries to load data from disk to
keep up with all the lookups.

As mentioned earlier, the subtransaction cache holds a mapping of the
subXID to the parent XID. When PostgreSQL needs to look up the subXID,
it calculates in which memory page this ID would live, and then does a
linear search to find in the memory page. If the page is not in the
cache, it evicts one page and loads the desired one into memory. The
diagram below shows the memory layout of the subtransaction SLRU.

By default, each SLRU page is an 8K buffer holding 4-byte parent
XIDs. This means 8192/4 = 2048 transaction IDs can be stored in each
page.

Note that there may be gaps in each page. PostgreSQL will cache XIDs as
needed, so a single XID can occupy an entire page.

There are 32 (NUM_SUBTRANS_BUFFERS) pages, which means up to 65K
transaction IDs can be stored in memory. Nikolay demonstrated that in a
busy system, it took about 18 seconds to fill up all 65K entries. Then
performance dropped off a cliff, making the database replicas unusable.

To our surprise, our experiments also demonstrated that a single
SAVEPOINT during a long-transaction could initiate this problem if
many writes also occurred simultaneously. That
is, it wasn't enough just to reduce the frequency of SAVEPOINT; we had
to eliminate them completely.

Why does a single SAVEPOINT cause problems?

To answer this question, we need to understand what happens when a
SAVEPOINT occurs in one query while a long-running transaction is
running.

We mentioned earlier that PostgreSQL needs to decide whether a given row
is visible to support a feature called multi-version concurrency control, or MVCC for
short. It does this by storing hidden columns, xmin and xmax, in
each tuple.

xmin holds the XID of when the tuple was created, and xmax holds the
XID when it was marked as dead (0 if the row is still present). In
addition, at the beginning of a transaction, PostgreSQL records metadata
in a database snapshot. Among other items, this snapshot records the
oldest XID and the newest XID in its own xmin and xmax values.

This metadata helps PostgreSQL determine whether a tuple is visible.
For example, a committed XID that started before xmin is definitely
visible, while anything after xmax is invisible.

What does this have to do with long transactions?

Long transactions are bad in general because they can tie up
connections, but they can cause a subtly different problem on a
replica. On the replica, a single SAVEPOINT during a long transaction
causes a snapshot to suboverflow. Remember that dragged down performance
in the case where we had more than 64 subtransactions.

Fundamentally, the problem happens because a replica behaves differently
from a primary when creating snapshots and checking for tuple
visibility. The diagram below illustrates an example with some of the
data structures used in PostgreSQL:

On the top of this diagram, we can see the XIDs increase at the
beginning of a subtransaction: the INSERT after the BEGIN gets 1,
and the subsequent INSERT in SAVEPOINT gets 2. Another client comes
along and performs a INSERT and SELECT at XID 3.

On the primary, PostgreSQL stores the transactions in progress in a
shared memory segment. The process array (procarray) stores XID 1 with
the first connection, and the database also writes that information to
the pg_xact directory. XID 2 gets stored in the pg_subtrans
directory, mapped to its parent, XID 1.

If a read happens on the primary, the snapshot generated contains xmin
as 1, and xmax as 3. txip holds a list of transactions in progress,
and subxip holds a list of subtransactions in progress.

However, neither the procarray nor the snapshot are shared directly
with the replica. The replica receives all the data it needs from the
write-ahead log (WAL).

Playing the WAL back one entry at time, the replica populates a shared data
structure called KnownAssignedIds. It contains all the transactions in
progress on the primary. Since this structure can only hold a limited number of
IDs, a busy database with a lot of active subtransactions could easily fill
this buffer. PostgreSQL made a design choice to kick out all subXIDs from this
list and store them in the pg_subtrans directory.

When a snapshot is generated on the replica, notice how txip is
blank. A PostgreSQL replica treats all XIDs as though they are
subtransactions and throws them into the subxip bucket. That works
because if a XID has a parent XID, then it's a subtransaction. Otherwise, it's a normal transaction. The code comments
explain the rationale.

However, this means the snapshot is missing subXIDs, and that could be
bad for MVCC. To deal with that, the replica also updates lastOverflowedXID:

 * When we throw away subXIDs from KnownAssignedXids, we need to keep track of
 * that, similarly to tracking overflow of a PGPROC's subxids array.  We do
 * that by remembering the lastOverflowedXID, ie the last thrown-away subXID.
 * As long as that is within the range of interesting XIDs, we have to assume
 * that subXIDs are missing from snapshots.  (Note that subXID overflow occurs
 * on primary when 65th subXID arrives, whereas on standby it occurs when 64th
 * subXID arrives - that is not an error.)

What is this "range of interesting XIDs"? We can see this in the code below:

if (TransactionIdPrecedesOrEquals(xmin, procArray->lastOverflowedXid))
    suboverflowed = true;

If lastOverflowedXid is smaller than our snapshot's xmin, it means
that all subtransactions have completed, so we don't need to check for
subtransactions. However, in our example:

1. xmin is 1 because of the transaction.
2. lastOverflowXid is 2 because of the SAVEPOINT.

This means suboverflowed is set to true here, which tells PostgreSQL
that whenever a XID needs to be checked, check to see if it has a parent
XID. Remember that this causes PostgreSQL to:

1. Look up the subXID for the parent XID in the SLRU cache.
2. If this doesn't exist in the cache, fetch the data from pg_trans.

In a busy system, the requested XIDs could span an ever-growing range of
values, which could easily exhaust the 64K entries in the SLRU
cache. This range will continue to grow as long as the transaction runs;
the rate of increase depends on how many updates are happening on the
prmary. As soon as the transaction terminates, the suboverflowed state
gets set to false.

In other words, we've replicated the same conditions as we saw with 64
subtransactions, only with a single SAVEPOINT and a long transaction.

What can we do about getting rid of Nessie?

There are three options:

1. Eliminate SAVEPOINT calls completely.
2. Eliminate all long-running transactions.
3. Apply Andrey Borodin's patches to PostgreSQL and increase the subtransaction cache.

We chose the first option because most uses of subtransaction could be
removed fairly easily. There were a number of approaches we took:

1. Perform updates outside of a subtransaction. Examples: 1, 2
2. Rewrite a query to use a INSERT or an UPDATE with an ON CONFLICT clause to deal with duplicate constraint violations. Examples: 1, 2, 3
3. Live with a non-atomic find_or_create_by. We used this approach sparingly. Example: 1

In addition, we added an alert whenever the application used a a single SAVEPOINT:

This had the side benefit of flagging a minor bug.

Why not eliminate all long-running transactions?

In our database, it wasn't practical to eliminate all long-running
transactions because we think many of them happened via database
autovacuuming,
but we're not able to reproduce this yet.
We are working on partitioning the tables and sharding the database, but this is a much more time-consuming problem
than removing all subtransactions.

What about the PostgreSQL patches?

Although we tested Andrey's PostgreSQL patches, we did not feel comfortable
deviating from the official PostgreSQL releases. Plus, maintaining a
custom patched release over upgrades would add a significant maintenance
burden for our infrastructure team. Our self-managed customers would
also not benefit unless they used a patched database.

Andrey's patches do two main things:

1. Allow administrators to change the SLRU size to any value.
2. Adds an associative cache.
   to make it performant to use a large cache value.

Remember that the SLRU cache does a linear search for the desired
page. That works fine when there are only 32 pages to search, but if you
increase the cache size to 100 MB the search becomes much more
expensive. The associative cache makes the lookup fast by indexing pages
with a bitmask and looking up the entry with offsets from the remaining
bits. This mitigates the problem because a transaction would need to be
several magnitudes longer to cause a problem.

Nikolay demonstrated that the SAVEPOINT problem disappeared as soon as
we increased the SLRU size to 100 MB with those patches. With a 100 MB
cache, PostgreSQL can cache 26.2 million IDs (104857600/4), far more
than the measely 65K.

These patches are currently awaiting review,
but in our opinion they should be given high priority for PostgreSQL 15.

Conclusion

Since removing all SAVEPOINT queries, we have not seen Nessie rear her
head again. If you are running PostgreSQL with read replicas, we
strongly recommend that you also remove all subtransactions until
further notice.

PostgreSQL is a fantastic database, and its well-commented code makes it
possible to understand its limitations under different configurations.

We would like to thank the GitLab community for bearing with us while we
iron out this production issue.

We are also grateful for the support from Nikolay
Samokhvalov and Catalin
Irimie, who contributed to understanding where our
Loch Ness Monster was hiding.

Cover image by Khadi Ganiev on iStock, licensed under standard license