RE: [Proposal] Add accumulated statistics - Mailing list pgsql-hackers

On Wed, Oct 30, 2019 at 5:51 AM, imai.yoshikazu@fujitsu.com wrote:
> The overhead which is induced by getting wait event info was discussed from old times, but I couldn't find the
actual
> measuring results, so I want to measure its overhead.

And here is the patch which counts the wait event and measuring the wait event time. It is currently like POC and has
severalthings to be improved.
 

You can get wait event info by executing "select * from pg_stat_waitaccum;" and reset its counters by "select
pg_stat_reset_shared('waitaccum');".

I tried to reduce the overhead of counting the wait event. It is difficult to reduce the overhead of measuring wait
eventstimes, I made measuring time is configurable like track_io_timing.
 

In the other DB, they use more light function than gettimeofday or clock_gettime and it is the CPU cycle counter,
rdtsc.
So I also created the patch which uses rdtsc for measuring wait events times.
There are some investigations for rdtsc before[1]. If we want to use rdtsc, we need more investigation for which
platformcan use it or how to prevent time go backwards in the rdtsc and so on.
 
Here, I wanted to see its overhead, so I didn't care such things in this patch.

I measured its performance with pgbench on a VM machine which has 4 core CPU and 8 GB Mem.
I tested against below four cases.

    master:      master (2fc2a88)

    only counts: 0001 patched, only counts wait events
                 (with track_wait_timing is off)
    counts/time: 0001 patched, counts wait event and measure its time by gettimeofday or clock_gettime
                 (with track_wait_timing is on)
    counts/time(rdtsc): 0001 + 0002 patched, counts wait event and measure its time by rdtsc
                 (with track_wait_timing is on)

I executed the below pgbench scripts, initializing database with scale 1 or 100 and executing pgbench with standard
modeor select-only mode.
 

    [standard mode]
    for i in `seq 1 15`
    do  
    pgbench -i -s (1 or 100) -q
    pgbench -c 8 -j 8 -n -T 60
    done

    [select only mode]
    pgbench -i -s (1 or 100) -q
    for i in `seq 1 10`
    do  
    pgbench -c 8 -j 8 -n -S -T 60
    done

The result was below.

[standard, scale 1]
      version      |   TPS  | diff(%)
            master | 813.82 |       0
       only counts | 797.48 |    2.01
       counts/time | 833.16 |   -2.38
counts/time(rdtsc) | 876.29 |   -7.68

[standard, scale 100]
      version      |   TPS   | diff(%)
            master | 2170.34 |       0
       only counts | 2125.37 |    2.07
       counts/time | 2147.8  |    1.04
counts/time(rdtsc) | 2187.37 |  -0.785

[select-only, scale 1]
      version      |   TPS   | diff(%)
            master | 28487.6 |       0
       only counts | 28481.1 |   0.023
       counts/time | 28364.7 |   0.431
counts/time(rdtsc) | 28462.6 |   0.088

[select-only, scale 100]
      version      |   TPS    | diff(%)
            master | 25767.89 |       0
       only counts | 26068.65 |  -1.167
       counts/time | 25567.69 |   0.777
counts/time(rdtsc) | 25525.26 |   0.942


An example of wait event info after executing pgbench was below.

[standard, scale 100]
number of transactions actually processed: 129844
latency average = 3.697 ms
tps = 2163.667427 (including connections establishing)
tps = 2163.918398 (excluding connections establishing)

 wait_event_type |      wait_event      | calls  |   times   
-----------------+----------------------+--------+-----------
 Client          | ClientRead           | 908807 | 114473878
 IO              | DataFileRead         | 216025 |   2867211
 LWLock          | WALWriteLock         | 191977 | 195192237
 IO              | DataFileWrite        | 154540 |   3406232
 IO              | WALWrite             |  49932 |   2728543
 IO              | WALSync              |  49737 |  49649308
 Lock            | transactionid        |   6209 |   8999545
 LWLock          | buffer_content       |   5337 |    288951
 IO              | DataFileExtend       |   2346 |     90375
 LWLock          | wal_insert           |   2013 |     25141
 LWLock          | WALBufMappingLock    |    630 |     14680
 LWLock          | CLogControlLock      |    454 |      2414
 LWLock          | buffer_mapping       |    170 |       852
 LWLock          | XidGenLock           |    146 |      3268
 LWLock          | lock_manager         |    141 |      5209
 Lock            | tuple                |    112 |    120163
 LWLock          | ProcArrayLock        |     97 |       495
 Lock            | extend               |     42 |     26875
 IO              | RelationMapRead      |     22 |        57
 LWLock          | CheckpointerCommLock |     18 |      1217
 IO              | DataFilePrefetch     |     18 |        24
 IPC             | ClogGroupUpdate      |      9 |      1867
 LWLock          | SyncRepLock          |      3 |       116
 IO              | DataFileTruncate     |      1 |       116


[select-only, scale 1]
number of transactions actually processed: 1682642
latency average = 0.285 ms
tps = 28043.407989 (including connections establishing)
tps = 28048.158085 (excluding connections establishing)
 wait_event_type |   wait_event    |  calls  |   times   
-----------------+-----------------+---------+-----------
 Client          | ClientRead      | 1682661 | 287999638
 IO              | RelationMapRead |      22 |        54
 LWLock          | lock_manager    |       2 |      2087


[select-only, scale 100]
number of transactions actually processed: 1513536
latency average = 0.317 ms
tps = 25223.558569 (including connections establishing)
tps = 25228.820644 (excluding connections establishing)
 wait_event_type |   wait_event    |  calls  |   times   
-----------------+-----------------+---------+-----------
 IO              | DataFileRead    | 2524682 |  14579531
 Client          | ClientRead      | 1513558 | 283968554
 LWLock          | buffer_mapping  |    1225 |      6392
 IO              | RelationMapRead |      22 |        46
 LWLock          | buffer_io       |      11 |       876
 LWLock          | lock_manager    |       6 |       507


I wanted to measure and compare the performance where wait_event occurs many times, but unfortunately, TPS was not
stableand differed in each standard test that wait_event occurs many times that I couldn't get consistent performance
tendencybetween each version.
 

I need to find more suitable test for clarifying its performance or if there are any good tests, please let me know.
Also,any tests are very welcome.
 


--
Yoshikazu Imai