Re: WAL Insertion Lock Improvements

On Mon, Apr 10, 2023 at 9:38 AM Michael Paquier <michael@paquier.xyz> wrote:
>
> I have been trying to get some reproducible numbers, but I think that
> I am going to need a bigger maching than what I have been using for
> the last few days, up to 400 connections.  It is worth noting that
> 00d1e02b may influence a bit the results, so we may want to have more
> numbers with that in place particularly with INSERTs, and one of the
> tests used upthread uses single row INSERTs.

I ran performance tests on the patch with different use-cases. Clearly
the patch reduces burden on LWLock's waitlist lock (evident from perf
reports [1]). However, to see visible impact in the output, the txns
must be generating small (between 16 bytes to 2 KB) amounts of WAL in
a highly concurrent manner, check the results below (FWIW, I've zipped
and attached perf images for better illustration along with test
setup).

When the txns are generating a small amount of WAL i.e. between 16
bytes to 2 KB in a highly concurrent manner, the benefit is clearly
visible in the TPS more than 2.3X improvement. When the txns are
generating more WAL i.e. more than 2 KB, the gain from reduced burden
on waitlist lock is offset by increase in the wait/release for WAL
insertion locks and no visible benefit is seen.

As the amount of WAL each txn generates increases, it looks like the
benefit gained from reduced burden on waitlist lock is offset by
increase in the wait for WAL insertion locks.

Note that I've used pg_logical_emit_message() for ease of
understanding about the txns generating various amounts of WAL, but
the pattern is the same if txns are generating various amounts of WAL
say with inserts.

test-case 1: -T5, WAL ~16 bytes
clients    HEAD    PATCHED
1    1437    1352
2    1376    1419
4    2919    2774
8    5875    6371
16    11148    12242
32    22108    23532
64    41414    46478
128    85304    85235
256    83771    152901
512    61970    141021
768    56514    118899
1024    51784    110960
2048    39141    84150
4096    16901    45759

test-case 1: -t1000, WAL ~16 bytes
clients    HEAD    PATCHED
1    1417    1333
2    1363    1791
4    2978    2970
8    5954    6198
16    11179    11164
32    23742    24043
64    45537    44103
128    84683    91762
256    80369    146293
512    61080    132079
768    57236    118046
1024    53497    114574
2048    46423    93588
4096    42067    85790

test-case 2: -T5, WAL ~256 bytes
clients    HEAD    PATCHED
1    1521    1386
2    1647    1637
4    3088    3270
8    6011    5631
16    12778    10317
32    24117    20006
64    43966    38199
128    72660    67936
256    93096    121261
512    57247    142418
768    53782    126218
1024    50279    109153
2048    35109    91602
4096    21184    39848

test-case 2: -t1000, WAL ~256 bytes
clients    HEAD    PATCHED
1    1265    1389
2    1522    1258
4    2802    2775
8    5875    5422
16    11664    10853
32    21961    22145
64    44304    40851
128    73278    80494
256    91172    122287
512    60966    136734
768    56590    125050
1024    52481    124341
2048    47878    104760
4096    42838    94121

test-case 3: -T5, WAL 512 bytes
clients    HEAD    PATCHED
1    1464    1284
2    1520    1381
4    2985    2877
8    6237    5261
16    11296    10621
32    22257    20789
64    40548    37243
128    66507    59891
256    92516    97506
512    56404    119716
768    51127    112482
1024    48463    103484
2048    38079    81424
4096    18977    40942

test-case 3: -t1000, WAL 512 bytes
clients    HEAD    PATCHED
1    1452    1434
2    1604    1649
4    3051    2971
8    5967    5650
16    10471    10702
32    20257    20899
64    39412    36750
128    62767    61110
256    81050    89768
512    56888    122786
768    51238    114444
1024    48972    106867
2048    43451    98847
4096    40018    111079

test-case 4: -T5, WAL 1024 bytes
clients    HEAD    PATCHED
1    1405    1395
2    1638    1607
4    3176    3207
8    6271    6024
16    11653    11103
32    20530    20260
64    34313    32367
128    55939    52079
256    74355    76420
512    56506    90983
768    50088    100410
1024    44589    99025
2048    39640    90931
4096    20942    36035

test-case 4: -t1000, WAL 1024 bytes
clients    HEAD    PATCHED
1    1330    1304
2    1615    1366
4    3117    2667
8    6179    5390
16    10524    10426
32    19819    18620
64    34844    29731
128    52180    48869
256    73284    71396
512    55714    96014
768    49336    108100
1024    46113    102789
2048    44627    104721
4096    44979    106189

test-case 5: -T5, WAL 2048 bytes
clients    HEAD    PATCHED
1    1407    1377
2    1518    1559
4    2589    2870
8    4883    5493
16    9075    9201
32    15957    16295
64    27471    25029
128    37493    38642
256    46369    45787
512    61755    62836
768    59144    68419
1024    52495    68933
2048    48608    72500
4096    26463    61252

test-case 5: -t1000, WAL 2048 bytes
clients    HEAD    PATCHED
1    1289    1366
2    1489    1628
4    2960    3036
8    5536    5965
16    9248    10399
32    15770    18140
64    27626    27800
128    36817    39483
256    48533    52105
512    64453    64007
768    59146    64160
1024    57637    61756
2048    59063    62109
4096    58268    61206

test-case 6: -T5, WAL 4096 bytes
clients    HEAD    PATCHED
1    1322    1325
2    1504    1551
4    2811    2880
8    5330    5159
16    8625    8315
32    12820    13534
64    19737    19965
128    26298    24633
256    34630    29939
512    34382    36669
768    33421    33316
1024    33525    32821
2048    37053    37752
4096    37334    39114

test-case 6: -t1000, WAL 4096 bytes
clients    HEAD    PATCHED
1    1212    1371
2    1383    1566
4    2858    2967
8    5092    5035
16    8233    8486
32    13353    13678
64    19052    20072
128    24803    24726
256    34065    33139
512    31590    32029
768    31432    31404
1024    31357    31366
2048    31465    31508
4096    32157    32180

test-case 7: -T5, WAL 8192 bytes
clients    HEAD    PATCHED
1    1287    1233
2    1552    1521
4    2658    2617
8    4680    4532
16    6732    7110
32    9649    9198
64    13276    12042
128    17100    17187
256    17408    17448
512    16595    16358
768    16599    16500
1024    16975    17300
2048    19073    19137
4096    21368    21735

test-case 7: -t1000, WAL 8192 bytes
clients    HEAD    PATCHED
1    1144    1190
2    1414    1395
4    2618    2438
8    4645    4485
16    6766    7001
32    9620    9804
64    12943    13023
128    15904    17148
256    16645    16035
512    15800    15796
768    15788    15810
1024    15814    15817
2048    17775    17771
4096    31715    31682

> Looking at the patch..  LWLockConflictsWithVar() and
> LWLockReleaseClearVar() are the trivial bits.  These are OK.

Hm, the crux of the patch is avoiding LWLock's waitlist lock for
reading/writing the lock variable. Essentially, they are important
bits.

> +    * NB: Note the use of pg_atomic_exchange_u64 as opposed to just
> +    * pg_atomic_write_u64 to update the value. Since pg_atomic_exchange_u64 is
> +    * a full barrier, we're guaranteed that the subsequent shared memory
> +    * reads/writes, if any, happen after we reset the lock variable.
>
> This mentions that the subsequent read/write operations are safe, so
> this refers to anything happening after the variable is reset.  As
> a full barrier, should be also mention that this is also ordered with
> respect to anything that the caller did before clearing the variable?
> From this perspective using pg_atomic_exchange_u64() makes sense to me
> in LWLockReleaseClearVar().

Wordsmithed that comment a bit.

> +            * XXX: Use of a spinlock at the beginning of this function to read
> +            * current insert position implies memory ordering. That means that
> +            * the immediate loads and stores to shared memory (for instance,
> +            * in LWLockUpdateVar called via LWLockWaitForVar) don't need an
> +            * explicit memory barrier as far as the current usage is
> +            * concerned. But that might not be safe in general.
>              */
> What's the part where this is not safe?  Based on what I see, this
> code path is safe because of the previous spinlock.  This is the same
> comment as at the beginning of LWLockConflictsWithVar().  Is that
> something that we ought to document at the top of LWLockWaitForVar()
> as well?  We have one caller of this function currently, but there may
> be more in the future.

'But that might not be safe in general' applies only for
LWLockWaitForVar not for WaitXLogInsertionsToFinish for sure. My bad.

If there's another caller for LWLockWaitForVar without any spinlock,
that's when the LWLockWaitForVar needs to have an explicit memory
barrier.

Per a comment upthread
https://www.postgresql.org/message-id/20221205183007.s72oygp63s43dqyz%40awork3.anarazel.de,
I had a note in WaitXLogInsertionsToFinish before LWLockWaitForVar. I
now have modified that comment.

> - * you're about to write out.
> + * you're about to write out. Using an atomic variable for insertingAt avoids
> + * taking any explicit lock for reads and writes.
>
> Hmm.  Not sure that we need to comment at all.

Removed. I was being verbose. One who understands pg_atomic_uint64 can
get to that point easily.

> -LWLockUpdateVar(LWLock *lock, uint64 *valptr, uint64 val)
> +LWLockUpdateVar(LWLock *lock, pg_atomic_uint64 *valptr, uint64 val)
> [...]
>     Assert(pg_atomic_read_u32(&lock->state) & LW_VAL_EXCLUSIVE);
>
> -   /* Update the lock's value */
> -   *valptr = val;
>
> The sensitive change is in LWLockUpdateVar().  I am not completely
> sure to understand this removal, though.  Does that influence the case
> where there are waiters?

I'll send about this in a follow-up email to not overload this
response with too much data.

> Another thing I was wondering about: how much does the fast-path used
> in LWLockUpdateVar() influence the performance numbers? Am I right to
> guess that it counts for most of the gain seen?

I'll send about this in a follow-up email to not overload this
response with too much data.

> Or could it be that
> the removal of the spin lock in
> LWLockConflictsWithVar()/LWLockWaitForVar() the point that has the
> highest effect?

I'll send about this in a follow-up email to not overload this
response with too much data.

I've addressed the above review comments and attached the v6 patch.

[1]
test-case 1: -T5, WAL ~16 bytes HEAD:
+   81.52%     0.03%  postgres  [.] __vstrfmon_l_internal
+   81.52%     0.00%  postgres  [.] startup_hacks
+   81.52%     0.00%  postgres  [.] PostmasterMain
+   63.95%     1.01%  postgres  [.] LWLockWaitListLock
+   61.93%     0.02%  postgres  [.] WaitXLogInsertionsToFinish
+   61.89%     0.05%  postgres  [.] LWLockWaitForVar
+   48.83%    48.33%  postgres  [.] pg_atomic_read_u32_impl
+   48.78%     0.40%  postgres  [.] pg_atomic_read_u32
+   43.19%     0.12%  postgres  [.] LWLockConflictsWithVar
+   19.81%     0.01%  postgres  [.] LWLockQueueSelf
+    7.86%     2.46%  postgres  [.] perform_spin_delay
+    6.14%     6.06%  postgres  [.] spin_delay
+    5.82%     0.01%  postgres  [.] pg_atomic_fetch_or_u32
+    5.81%     5.76%  postgres  [.] pg_atomic_fetch_or_u32_impl
+    4.00%     0.01%  postgres  [.] XLogInsert
+    3.93%     0.03%  postgres  [.] XLogInsertRecord
+    2.13%     0.02%  postgres  [.] LWLockRelease
+    2.10%     0.03%  postgres  [.] LWLockAcquire
+    1.92%     0.00%  postgres  [.] LWLockDequeueSelf
+    1.87%     0.01%  postgres  [.] WALInsertLockAcquire
+    1.68%     0.04%  postgres  [.] LWLockAcquireOrWait
+    1.64%     0.01%  postgres  [.] pg_analyze_and_rewrite_fixedparams
+    1.62%     0.00%  postgres  [.] WALInsertLockRelease
+    1.62%     0.00%  postgres  [.] LWLockReleaseClearVar
+    1.55%     0.01%  postgres  [.] parse_analyze_fixedparams
+    1.51%     0.00%  postgres  [.] transformTopLevelStmt
+    1.50%     0.00%  postgres  [.] transformOptionalSelectInto
+    1.50%     0.01%  postgres  [.] transformStmt
+    1.47%     0.02%  postgres  [.] transformSelectStmt
+    1.29%     0.01%  postgres  [.] XactLogCommitRecord

test-case 1: -T5, WAL ~16 bytes PATCHED:
+   74.49%     0.04%  postgres  [.] __vstrfmon_l_internal
+   74.49%     0.00%  postgres  [.] startup_hacks
+   74.49%     0.00%  postgres  [.] PostmasterMain
+   51.60%     0.01%  postgres  [.] finish_xact_command
+   51.60%     0.02%  postgres  [.] CommitTransactionCommand
+   51.37%     0.03%  postgres  [.] CommitTransaction
+   49.43%     0.05%  postgres  [.] RecordTransactionCommit
+   46.55%     0.05%  postgres  [.] XLogFlush
+   46.37%     0.85%  postgres  [.] LWLockWaitListLock
+   43.79%     0.02%  postgres  [.] LWLockQueueSelf
+   38.87%     0.03%  postgres  [.] WaitXLogInsertionsToFinish
+   38.79%     0.11%  postgres  [.] LWLockWaitForVar
+   34.99%    34.49%  postgres  [.] pg_atomic_read_u32_impl
+   34.93%     0.35%  postgres  [.] pg_atomic_read_u32
+    6.99%     2.12%  postgres  [.] perform_spin_delay
+    6.64%     0.01%  postgres  [.] XLogInsert
+    6.54%     0.06%  postgres  [.] XLogInsertRecord
+    6.26%     0.08%  postgres  [.] LWLockAcquireOrWait
+    5.31%     5.22%  postgres  [.] spin_delay
+    4.23%     0.04%  postgres  [.] LWLockRelease
+    3.74%     0.01%  postgres  [.] pg_atomic_fetch_or_u32
+    3.73%     3.68%  postgres  [.] pg_atomic_fetch_or_u32_impl
+    3.33%     0.06%  postgres  [.] LWLockAcquire
+    2.97%     0.01%  postgres  [.] pg_plan_queries
+    2.95%     0.01%  postgres  [.] WALInsertLockAcquire
+    2.94%     0.02%  postgres  [.] planner
+    2.94%     0.01%  postgres  [.] pg_plan_query
+    2.92%     0.01%  postgres  [.] LWLockDequeueSelf
+    2.89%     0.04%  postgres  [.] standard_planner
+    2.81%     0.00%  postgres  [.] WALInsertLockRelease
+    2.80%     0.00%  postgres  [.] LWLockReleaseClearVar
+    2.38%     0.07%  postgres  [.] subquery_planner
+    2.35%     0.01%  postgres  [.] XactLogCommitRecord

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com