pgbench: reduced performance on RC vs. SSI with CTEs

[nvanbenschoten]

When running pgbench with RC, we found that the explicit transaction case was faster with RC than with SSI.

However, with a workload rewrite that uses CTEs, performance was better with SSI than RC.

We should understand why.

Reproduction steps:

 pgbench \
    --host=${PGHOST} \
    --username=${PGUSER} \
    --port=${PGPORT} \
    --no-vacuum \
    --file=tpcb-cockroach.sql@1 \
    --scale=10 \
    --client=25 \
    --jobs=10 \
    --failures-detailed \
    --verbose-errors \
    --max-tries=3 \
    -T 60 \
    -P 5 \
    ${PGDATABASE}

Jira issue: CRDB-31025

[dbist]

for additional context:

pgbench (PostgreSQL) 15.4 (Homebrew) on OSX Ventura 13.5 using the RC bug bash cluster

generate the workload

pgbench \
    --initialize \
    --host=${PGHOST} \
    --username=${PGUSER} \
    --port=${PGPORT} \
    --no-vacuum \
    --scale=10 \
    ${PGDATABASE}

1000000 of 1000000 tuples (100%) done (elapsed 6.26 s, remaining 0.00 s)
creating primary keys...
done in 67.70 s (drop tables 0.51 s, create tables 0.16 s, client-side generate 15.50 s, primary keys 51.53 s).

run the built-in tpcb-like workload using RC

 pgbench \
    --host=${PGHOST} \
    --username=${PGUSER} \
    --port=${PGPORT} \
    --no-vacuum \
    --scale=10 \
    --client=25 \
    --jobs=10 \
    --failures-detailed \
    --verbose-errors \
    --max-tries=3 \
    -T 60 \
    -P 5 \
    ${PGDATABASE}

progress: 5.0 s, 86.9 tps, lat 259.117 ms stddev 63.863, 0 failed, 0 retried, 0 retries
progress: 10.0 s, 90.1 tps, lat 279.980 ms stddev 100.669, 0 failed, 0 retried, 0 retries
progress: 15.0 s, 89.0 tps, lat 280.995 ms stddev 126.423, 0 failed, 0 retried, 0 retries
progress: 20.0 s, 95.6 tps, lat 262.775 ms stddev 68.858, 0 failed, 0 retried, 0 retries
progress: 25.0 s, 91.4 tps, lat 267.528 ms stddev 79.942, 0 failed, 0 retried, 0 retries
progress: 30.0 s, 93.2 tps, lat 273.620 ms stddev 88.716, 0 failed, 0 retried, 0 retries
progress: 35.0 s, 93.8 tps, lat 262.782 ms stddev 72.336, 0 failed, 0 retried, 0 retries
progress: 40.0 s, 91.0 tps, lat 277.099 ms stddev 93.008, 0 failed, 0 retried, 0 retries
progress: 45.0 s, 93.7 tps, lat 267.252 ms stddev 74.849, 0 failed, 0 retried, 0 retries
progress: 50.0 s, 95.7 tps, lat 259.671 ms stddev 69.328, 0 failed, 0 retried, 0 retries
progress: 55.0 s, 93.4 tps, lat 268.965 ms stddev 89.097, 0 failed, 0 retried, 0 retries
progress: 60.0 s, 92.6 tps, lat 269.907 ms stddev 83.838, 0 failed, 0 retried, 0 retries
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 10
query mode: simple
number of clients: 25
number of threads: 10
maximum number of tries: 3
duration: 60 s
number of transactions actually processed: 5557
number of failed transactions: 0 (0.000%)
number of serialization failures: 0 (0.000%)
number of deadlock failures: 0 (0.000%)
number of transactions retried: 0 (0.000%)
total number of retries: 0
latency average = 269.206 ms
latency stddev = 86.010 ms
initial connection time = 302.108 ms
tps = 92.529279 (without initial connection time)

Running the same workload using serializable:

pgbench: client 6 got an error in command 8 (SQL) of script 0; ERROR:  restart transaction: TransactionRetryWithProtoRefreshError: WriteTooOldError: write for key /Table/133/5/5/0 at timestamp 1693251533.551587143,1 too old; must write at or above 1693251533.551587143,2: "sql txn" meta={id=853081b3 key=/Table/132/5/963804/0 iso=Serializable pri=0.00174511 epo=0 ts=1693251533.551587143,2 min=1693251532.596414700,0 seq=2} lock=true stat=PENDING rts=1693251533.551587143,1 wto=false gul=1693251533.096414700,0
HINT:  See: https://www.cockroachlabs.com/docs/v23.2/transaction-retry-error-reference.html
pgbench: client 13 got an error in command 8 (SQL) of script 0; ERROR:  restart transaction: TransactionRetryWithProtoRefreshError: WriteTooOldError: write for key /Table/133/5/5/0 at timestamp 1693251533.551587143,1 too old; must write at or above 1693251533.551587143,2: "sql txn" meta={id=6a4ccc0a key=/Table/132/5/15984/0 iso=Serializable pri=0.04418758 epo=0 ts=1693251533.551587143,2 min=1693251533.138347563,0 seq=2} lock=true stat=PENDING rts=1693251533.551587143,1 wto=false gul=1693251533.638347563,0
HINT:  See: https://www.cockroachlabs.com/docs/v23.2/transaction-retry-error-reference.html
progress: 55.0 s, 87.0 tps, lat 289.381 ms stddev 122.917, 0 failed, 1 retried, 1 retries
pgbench: client 6 repeats the transaction after the error (try 1/3)
pgbench: client 13 repeats the transaction after the error (try 1/3)
progress: 60.0 s, 90.0 tps, lat 282.948 ms stddev 130.475, 0 failed, 2 retried, 2 retries
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 10
query mode: simple
number of clients: 25
number of threads: 10
maximum number of tries: 3
duration: 60 s
number of transactions actually processed: 5330
number of failed transactions: 0 (0.000%)
number of serialization failures: 0 (0.000%)
number of deadlock failures: 0 (0.000%)
number of transactions retried: 26 (0.488%)
total number of retries: 26
latency average = 280.722 ms
latency stddev = 122.239 ms
initial connection time = 295.635 ms
tps = 88.845936 (without initial connection time)

Following that test, running the same workload as CTE rewrite and serializable

 pgbench \
    --host=${PGHOST} \
    --username=${PGUSER} \
    --port=${PGPORT} \
    --no-vacuum \
    --file=tpcb-cockroach.sql@1 \
    --scale=10 \
    --client=25 \
    --jobs=10 \
    --failures-detailed \
    --verbose-errors \
    --max-tries=3 \
    -T 60 \
    -P 5 \
    ${PGDATABASE}

pgbench (15.4 (Homebrew), server 13.0.0)
progress: 5.0 s, 358.8 tps, lat 65.289 ms stddev 44.672, 0 failed, 0 retried, 0 retries
progress: 10.0 s, 367.9 tps, lat 67.680 ms stddev 62.914, 0 failed, 0 retried, 0 retries
progress: 15.0 s, 344.1 tps, lat 72.093 ms stddev 56.732, 0 failed, 0 retried, 0 retries
progress: 20.0 s, 368.8 tps, lat 68.288 ms stddev 57.884, 0 failed, 0 retried, 0 retries
progress: 25.0 s, 373.5 tps, lat 66.777 ms stddev 58.253, 0 failed, 0 retried, 0 retries
progress: 30.0 s, 360.6 tps, lat 69.013 ms stddev 53.119, 0 failed, 0 retried, 0 retries
progress: 35.0 s, 349.8 tps, lat 71.610 ms stddev 51.474, 0 failed, 0 retried, 0 retries
progress: 40.0 s, 367.1 tps, lat 68.566 ms stddev 53.952, 0 failed, 0 retried, 0 retries
progress: 45.0 s, 374.7 tps, lat 66.161 ms stddev 45.147, 0 failed, 0 retried, 0 retries
progress: 50.0 s, 353.7 tps, lat 71.004 ms stddev 56.735, 0 failed, 0 retried, 0 retries
progress: 55.0 s, 365.8 tps, lat 68.185 ms stddev 50.983, 0 failed, 0 retried, 0 retries
progress: 60.0 s, 380.7 tps, lat 65.772 ms stddev 54.161, 0 failed, 0 retried, 0 retries
transaction type: tpcb-cockroach.sql
scaling factor: 10
query mode: simple
number of clients: 25
number of threads: 10
maximum number of tries: 3
duration: 60 s
number of transactions actually processed: 21853
number of failed transactions: 0 (0.000%)
number of serialization failures: 0 (0.000%)
number of deadlock failures: 0 (0.000%)
number of transactions retried: 0 (0.000%)
total number of retries: 0
latency average = 68.349 ms
latency stddev = 54.175 ms
initial connection time = 292.942 ms
tps = 365.385327 (without initial connection time)

Read Committed with CTE

pgbench (15.4 (Homebrew), server 13.0.0)
progress: 5.0 s, 325.3 tps, lat 71.240 ms stddev 43.175, 0 failed, 0 retried, 0 retries
progress: 10.0 s, 339.2 tps, lat 73.848 ms stddev 45.554, 0 failed, 0 retried, 0 retries
progress: 15.0 s, 337.6 tps, lat 73.693 ms stddev 53.318, 0 failed, 0 retried, 0 retries
progress: 20.0 s, 361.6 tps, lat 69.506 ms stddev 41.133, 0 failed, 0 retried, 0 retries
progress: 25.0 s, 338.9 tps, lat 73.424 ms stddev 44.554, 0 failed, 0 retried, 0 retries
progress: 30.0 s, 356.9 tps, lat 70.146 ms stddev 46.061, 0 failed, 0 retried, 0 retries
progress: 35.0 s, 355.5 tps, lat 70.170 ms stddev 40.404, 0 failed, 0 retried, 0 retries
progress: 40.0 s, 328.8 tps, lat 76.065 ms stddev 57.867, 0 failed, 0 retried, 0 retries
progress: 45.0 s, 356.6 tps, lat 70.433 ms stddev 44.299, 0 failed, 0 retried, 0 retries
progress: 50.0 s, 353.3 tps, lat 70.155 ms stddev 41.400, 0 failed, 0 retried, 0 retries
progress: 55.0 s, 344.3 tps, lat 72.950 ms stddev 44.991, 0 failed, 0 retried, 0 retries
progress: 60.0 s, 326.3 tps, lat 76.553 ms stddev 50.607, 0 failed, 0 retried, 0 retries
transaction type: tpcb-cockroach.sql
scaling factor: 10
query mode: simple
number of clients: 25
number of threads: 10
maximum number of tries: 3
duration: 60 s
number of transactions actually processed: 20647
number of failed transactions: 0 (0.000%)
number of serialization failures: 0 (0.000%)
number of deadlock failures: 0 (0.000%)
number of transactions retried: 0 (0.000%)
total number of retries: 0
latency average = 72.298 ms
latency stddev = 46.332 ms
initial connection time = 322.143 ms
tps = 345.574120 (without initial connection time)

[nvanbenschoten]

There's something interesting going on here. I can reproduce the results from above. RC outperforms SSI in the multi-statement workload, but underperforms it in the single-statement workload.

One thing I'm noticing is that RC hits more (intra-statement) write-write retry errors than SSI. In the following graph, the first and last 5 minutes use RC while the middle two runs use SSI.

I can't explain this, so there's something to learn here.

[nvanbenschoten]

I think I understand what's going on here now.

First off, I found that Serializable and Snapshot behaved the same, so this was a difference between Snapshot and Read Committed, not between Serializable and Snapshot. That makes sense, because the transaction only performs writes (and there are no FKs), so SSI and SI should behave the same.

I then found that the difference disappeared when I disabled per-statement read snapshots for RC. That's kind of strange, because this is a single-statement txn. Bisecting a few different callers led me to this code in connExecutor.commitSQLTransactionInternal:

cockroach/pkg/sql/conn_executor_exec.go

Line 1446 in fea4eb0

if err := ex.state.mu.txn.Step(ctx, true /* allowReadTimestampStep */); err != nil {

The way to interpret this is that we are stepping the transaction's read timestamp (and by extension, provisional commit timestamp) between statements but then also immediately before committing. I believe this last part is unnecessary — there's no reason to step the read timestamp before committing. Doing so just unnecessarily inflates the transaction's commit timestamp. If I pass false for allowReadTimestampStep there, the difference disappears.

NOTE: Read Committed on the left, Serializable on the right

It's interesting to reason about why this has such an effect. My current understanding of the difference is that by stepping the read timestamp before committing, we were causing RC transactions to commit at higher timestamps than they strictly needed to. For example, a transaction may have written its intents at timestamp 10, 10, and 12 (e.g. if there was an intra-statement refresh at some point). Once all of its intents were written, it could just go ahead and commit at timestamp 12. But instead, we were advancing the commit timestamp to 15 at the last moment. We'd then go and resolve all committed versions to timestamp 15.

Doing so expanded the transaction's "contention footprint" (in the MVCC time domain, not real time), leading to more write-write version conflicts and generally more contention. Once the transaction committed at timestamp 15, all other transactions writing to overlapping keys now needed to write at at least timestamp 16. So it's easy to imagine that a conflicting transaction that wanted to write at timestamp 14 would have been fine had the first transaction run under serializable isolation (and would have just committed at 12) but forced to retry had the first transaction run under read committed.

I think the fix here is simple — don't step the transaction's read timestamp in connExecutor.commitSQLTransactionInternal.