Re: Commit Latency

[ravi k <ravisql09@xxxxxxxxx>]

Please find the detail below: 

Our system is of 4TB(SSD shared pure storage) and xfs filesystem:

• Also handling 300 TPS (~3500 DML queries)
• 80% of modified data is BLOB (text)
• Table sizes generally under 70GB
• Unusual naptime configuration due to data characteristics
• Idle in TX expected regularly ~1ms
• Action items are in pipeline:
  a. Adjusting vacuum parameters
  b. Planning manual vacuum jobs during off-hours
• Note: App team is working on refactoring, but this will take time

Pg_stat_activity o/p: 

state        | count
---------------------+-------
                     |     5
 active              |     9
 idle in transaction |     2
 idle                |   212
(4 rows)

Laurenz, thanks for the article.

Alvaro, regarding pg_wait_sampling, we are unable to enable it at this time due to the requirement for a server restart.

Tomas, please find the fsync log attached below for your review.Let me know if you need any further information or clarification.

5 seconds per test
O_DIRECT supported on this platform for open_datasync and open_sync.

Compare file sync methods using one 8kB write:
(in wal_sync_method preference order, except fdatasync is Linux's default)
        open_datasync                      3530.460 ops/sec     283 usecs/op
        fdatasync                          3477.850 ops/sec     288 usecs/op
        fsync                              2990.668 ops/sec     334 usecs/op
        fsync_writethrough                              n/a
        open_sync                          3287.932 ops/sec     304 usecs/op

Compare file sync methods using two 8kB writes:
(in wal_sync_method preference order, except fdatasync is Linux's default)
        open_datasync                      1752.086 ops/sec     571 usecs/op
        fdatasync                          3198.132 ops/sec     313 usecs/op
        fsync                              2980.334 ops/sec     336 usecs/op
        fsync_writethrough                              n/a
        open_sync                          1555.356 ops/sec     643 usecs/op

Compare open_sync with different write sizes:
(This is designed to compare the cost of writing 16kB in different write
open_sync sizes.)
         1 * 16kB open_sync write          2898.926 ops/sec     345 usecs/op
         2 *  8kB open_sync writes         1631.841 ops/sec     613 usecs/op
         4 *  4kB open_sync writes          861.491 ops/sec    1161 usecs/op
         8 *  2kB open_sync writes          451.548 ops/sec    2215 usecs/op
        16 *  1kB open_sync writes          233.062 ops/sec    4291 usecs/op

Test if fsync on non-write file descriptor is honored:
(If the times are similar, fsync() can sync data written on a different
descriptor.)
        write, fsync, close                2747.990 ops/sec     364 usecs/op
        write, close, fsync                2804.104 ops/sec     357 usecs/op

Non-sync'ed 8kB writes:
        write                            386932.826 ops/sec       3 usecs/op

We suspect issues with wal_init_zero due to a 3-minute log commit spike coinciding with increased WAL creation time, as shown in the attached graphs.

Note:  Size of the wal file is 1GB and generates wal of 3GB/min

            active | IO: WALInitWrite    | 00:00:00.249311 |      COMMIT

       IO | WALInitSync   | active  474.163 ms| COMMIT  

Commit spike timings:

Wal creation_timings:

Best,

Ravi

On Fri, Feb 7, 2025 at 10:14 PM Tomas Vondra <tomas@xxxxxxxxx> wrote:

On 2/7/25 14:00, ravi k wrote:
> Thanks for the suggestions!
>
> It looks the issue is happening at the time of wal creation, does
> wal_init_zero off is good option?
>

It's impossible to say if that option will help, considering how little
info about the system you provided. I suggest you start by answering the
questions you've been asked by me & Alvaro, explain why you concluded
it's related to WAL creation, etc.


regards

--
Tomas Vondra