[MDEV-25417] reduce InnoDB buffer pool load time Created: 2021-04-14  Updated: 2022-11-28  Resolved: 2022-11-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Fix Version/s: 10.11.2, 10.5.19, 10.6.12, 10.7.8, 10.8.7, 10.9.5, 10.10.3

Type: Task Priority: Major
Reporter: Ian Gilfillan Assignee: Daniel Black
Resolution: Fixed Votes: 0
Labels: None

Attachments: PNG File hdd_1_thd.png     PNG File hdd_32_thd.png     PNG File ssd_1_thd.png     PNG File ssd_32_thd.png    
Issue Links:
Blocks
is blocked by MDEV-26547 Restoring InnoDB buffer pool dump is ... Closed
Relates
relates to MDEV-29343 MariaDB 10.6.x slower mysqldump etc. Closed
relates to MDEV-9930 Allow to choose an aggressive InnoDB ... Closed

 Description   

When InnoDB starts up, it can be limited by innodb_io_capacity (or innodb_io_capacity_max). Currently, users can increase these temporarily at startup, but this is not ideal, and neither should be left elevated.

Based on the discussion at https://mariadb.zulipchat.com/#narrow/stream/118759-general/topic/InnoDB.20tuning/near/234486913, this task is to add a new parameter for use in buffer pool load (and read-ahead).

 Comments   
Comment by Daniel Black [ 2021-04-14 ]

Also activity during loading shouldn't significant decrease either loading or user operation.

Comment by Marko Mäkelä [ 2022-08-30 ]

Is there anything that could be done after MDEV-26547? I mean, does loading the buffer pool already use all innodb_read_io_threads and available innodb_io_capacity?

Comment by Daniel Black [ 2022-11-14 ]

I was concerned that buf_load_throttle_if_needed would be throttling too much:

Starting from flushed page cache sync; echo 3 > /proc/sys/vm/drop_caches.

While loading 7G worth of pool, all in test.t1 table, while doing a simulation load.

light load

 
$ while [ ! -S /tmp/mysql.sock ]; do sleep 0.001; done; while client/mysql -S /tmp/mysql.sock -e 'insert into test.noise values(1)'; do sleep 0.1; done

Was sufficient to stretch the 11 second loading without any concurrent activity:

10.5.19-fe330b63fe4ee51a26ac6e222d8eb4ee44a73d50 using libaio

 
2022-11-14 17:07:59 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-11-14 17:07:59 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-11-14 17:07:59 0 [Note] Reading of all Master_info entries succeeded
 
2022-11-14 17:07:59 0 [Note] Added new Master_info '' to hash table
 
2022-11-14 17:07:59 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.5.19-MariaDB-1:10.5.13+maria~stretch'  socket: '/tmp/mysql.sock'  port: 0  mariadb.org binary distribution
 
2022-11-14 17:08:10 0 [Note] InnoDB: Buffer pool(s) load completed at 221114 17:08:10

To 3 minutes:

2022-11-14 17:15:34 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-11-14 17:15:34 0 [Note] Reading of all Master_info entries succeeded
 
2022-11-14 17:15:34 0 [Note] Added new Master_info '' to hash table
 
2022-11-14 17:15:34 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.5.19-MariaDB-1:10.5.13+maria~stretch'  socket: '/tmp/mysql.sock'  port: 0  mariadb.org binary distribution
 
 
 
2022-11-14 17:18:33 0 [Note] InnoDB: Buffer pool(s) load completed at 221114 17:18:33

Comment by Daniel Black [ 2022-11-14 ]

I attempted the brutal approach and removed buf_load_throttle_if_needed. On the light load above it loaded the buffer pool in 10-11 seconds as if it wasn't there.

For a more brutal write test, sysbench oltp_write_only was used:

sysbench

 
$ while [ ! -S /tmp/mysql.sock ]; do sleep 0.001; done ; sysbench /usr/share/sysbench/oltp_write_only.lua --mysql-socket=/tmp/mysql.sock --time=60 --threads=8 --tables=10 --table-size=20000 --report-interval=1 run
 
sysbench 1.0.20 (using system LuaJIT 2.1.0-beta3)
 
 
 
Running the test with following options:
 
Number of threads: 8
 
Report intermediate results every 1 second(s)
 
Initializing random number generator from current time
 
 
 
 
 
Initializing worker threads...
 
 
 
Threads started!
 
 
 
[ 1s ] thds: 8 tps: 2050.13 qps: 12340.72 (r/w/o: 0.00/8232.48/4108.25) lat (ms,95%): 7.56 err/s: 0.00 reconn/s: 0.00
 
[ 2s ] thds: 8 tps: 1905.20 qps: 11431.23 (r/w/o: 0.00/7620.82/3810.41) lat (ms,95%): 4.57 err/s: 0.00 reconn/s: 0.00
 
[ 3s ] thds: 8 tps: 823.17 qps: 4938.99 (r/w/o: 0.00/3292.66/1646.33) lat (ms,95%): 21.50 err/s: 0.00 reconn/s: 0.00
 
[ 4s ] thds: 8 tps: 2359.05 qps: 14154.32 (r/w/o: 0.00/9436.21/4718.11) lat (ms,95%): 6.32 err/s: 0.00 reconn/s: 0.00
 
[ 5s ] thds: 8 tps: 2370.98 qps: 14195.88 (r/w/o: 0.00/9453.92/4741.96) lat (ms,95%): 4.65 err/s: 0.00 reconn/s: 0.00
 
[ 6s ] thds: 8 tps: 2178.13 qps: 13074.77 (r/w/o: 0.00/8718.51/4356.26) lat (ms,95%): 6.21 err/s: 0.00 reconn/s: 0.00
 
[ 7s ] thds: 8 tps: 2286.88 qps: 13741.26 (r/w/o: 0.00/9167.51/4573.75) lat (ms,95%): 5.00 err/s: 0.00 reconn/s: 0.00
 
[ 8s ] thds: 8 tps: 2451.14 qps: 14698.86 (r/w/o: 0.00/9796.57/4902.29) lat (ms,95%): 5.77 err/s: 0.00 reconn/s: 0.00
 
[ 9s ] thds: 8 tps: 2512.00 qps: 15084.00 (r/w/o: 0.00/10060.00/5024.00) lat (ms,95%): 5.99 err/s: 0.00 reconn/s: 0.00
 
[ 10s ] thds: 8 tps: 2528.97 qps: 15172.80 (r/w/o: 0.00/10114.87/5057.93) lat (ms,95%): 5.57 err/s: 0.00 reconn/s: 0.00
 
[ 11s ] thds: 8 tps: 2387.00 qps: 14320.00 (r/w/o: 0.00/9546.00/4774.00) lat (ms,95%): 4.57 err/s: 0.00 reconn/s: 0.00
 
[ 12s ] thds: 8 tps: 2378.94 qps: 14268.61 (r/w/o: 0.00/9510.74/4757.87) lat (ms,95%): 6.91 err/s: 0.00 reconn/s: 0.00
 
[ 13s ] thds: 8 tps: 2398.90 qps: 14401.39 (r/w/o: 0.00/9603.59/4797.80) lat (ms,95%): 5.77 err/s: 0.00 reconn/s: 0.00
 
[ 14s ] thds: 8 tps: 2508.20 qps: 15032.20 (r/w/o: 0.00/10015.80/5016.40) lat (ms,95%): 5.57 err/s: 0.00 reconn/s: 0.00
 
[ 15s ] thds: 8 tps: 2372.86 qps: 14250.16 (r/w/o: 0.00/9504.44/4745.72) lat (ms,95%): 5.88 err/s: 0.00 reconn/s: 0.00
 
[ 16s ] thds: 8 tps: 2344.11 qps: 14042.67 (r/w/o: 0.00/9354.45/4688.22) lat (ms,95%): 6.32 err/s: 0.00 reconn/s: 0.00
 
[ 17s ] thds: 8 tps: 2301.04 qps: 13832.23 (r/w/o: 0.00/9230.15/4602.08) lat (ms,95%): 4.74 err/s: 0.00 reconn/s: 0.00
 
[ 18s ] thds: 8 tps: 2502.96 qps: 15004.75 (r/w/o: 0.00/9998.83/5005.92) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 19s ] thds: 8 tps: 2461.16 qps: 14779.93 (r/w/o: 0.00/9857.62/4922.31) lat (ms,95%): 4.41 err/s: 0.00 reconn/s: 0.00
 
[ 20s ] thds: 8 tps: 2519.83 qps: 15118.98 (r/w/o: 0.00/10079.32/5039.66) lat (ms,95%): 4.65 err/s: 0.00 reconn/s: 0.00
 
[ 21s ] thds: 8 tps: 2410.13 qps: 14456.77 (r/w/o: 0.00/9636.51/4820.26) lat (ms,95%): 4.74 err/s: 0.00 reconn/s: 0.00
 
[ 22s ] thds: 8 tps: 2404.91 qps: 14433.47 (r/w/o: 0.00/9623.65/4809.82) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 23s ] thds: 8 tps: 2437.65 qps: 14621.91 (r/w/o: 0.00/9746.60/4875.30) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 24s ] thds: 8 tps: 2406.24 qps: 14441.41 (r/w/o: 0.00/9628.94/4812.47) lat (ms,95%): 5.57 err/s: 0.00 reconn/s: 0.00
 
[ 25s ] thds: 8 tps: 370.86 qps: 2225.14 (r/w/o: 0.00/1483.43/741.71) lat (ms,95%): 66.84 err/s: 0.00 reconn/s: 0.00
 
[ 26s ] thds: 8 tps: 27.00 qps: 162.01 (r/w/o: 0.00/108.01/54.00) lat (ms,95%): 383.33 err/s: 0.00 reconn/s: 0.00
 
[ 27s ] thds: 8 tps: 502.54 qps: 3013.22 (r/w/o: 0.00/2008.15/1005.08) lat (ms,95%): 110.66 err/s: 0.00 reconn/s: 0.00
 
[ 28s ] thds: 8 tps: 1591.22 qps: 9549.30 (r/w/o: 0.00/6366.86/3182.43) lat (ms,95%): 5.88 err/s: 0.00 reconn/s: 0.00
 
[ 29s ] thds: 8 tps: 27.03 qps: 162.19 (r/w/o: 0.00/108.13/54.06) lat (ms,95%): 383.33 err/s: 0.00 reconn/s: 0.00
 
[ 30s ] thds: 8 tps: 1674.95 qps: 10049.72 (r/w/o: 0.00/6699.81/3349.91) lat (ms,95%): 5.47 err/s: 0.00 reconn/s: 0.00
 
[ 31s ] thds: 8 tps: 2436.19 qps: 14617.12 (r/w/o: 0.00/9744.75/4872.37) lat (ms,95%): 5.09 err/s: 0.00 reconn/s: 0.00
 
[ 32s ] thds: 8 tps: 2570.94 qps: 15425.64 (r/w/o: 0.00/10283.76/5141.88) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 33s ] thds: 8 tps: 2565.00 qps: 15390.00 (r/w/o: 0.00/10260.00/5130.00) lat (ms,95%): 4.41 err/s: 0.00 reconn/s: 0.00
 
[ 34s ] thds: 8 tps: 2547.00 qps: 15281.97 (r/w/o: 0.00/10187.98/5093.99) lat (ms,95%): 4.41 err/s: 0.00 reconn/s: 0.00
 
[ 35s ] thds: 8 tps: 2430.04 qps: 14580.22 (r/w/o: 0.00/9720.15/4860.07) lat (ms,95%): 5.18 err/s: 0.00 reconn/s: 0.00
 
[ 36s ] thds: 8 tps: 2067.38 qps: 12404.26 (r/w/o: 0.00/8269.51/4134.75) lat (ms,95%): 5.77 err/s: 0.00 reconn/s: 0.00
 
[ 37s ] thds: 8 tps: 381.01 qps: 2286.07 (r/w/o: 0.00/1524.04/762.02) lat (ms,95%): 71.83 err/s: 0.00 reconn/s: 0.00
 
[ 38s ] thds: 8 tps: 2605.97 qps: 15630.79 (r/w/o: 0.00/10419.86/5210.93) lat (ms,95%): 4.41 err/s: 0.00 reconn/s: 0.00
 
[ 39s ] thds: 8 tps: 2539.20 qps: 15240.19 (r/w/o: 0.00/10160.79/5079.40) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 40s ] thds: 8 tps: 2600.77 qps: 15604.59 (r/w/o: 0.00/10403.06/5201.53) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 41s ] thds: 8 tps: 2566.87 qps: 15401.22 (r/w/o: 0.00/10267.48/5133.74) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
 
[ 42s ] thds: 8 tps: 2578.28 qps: 15453.68 (r/w/o: 0.00/10297.12/5156.56) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 43s ] thds: 8 tps: 2609.84 qps: 15667.01 (r/w/o: 0.00/10447.34/5219.67) lat (ms,95%): 4.25 err/s: 0.00 reconn/s: 0.00
 
[ 44s ] thds: 8 tps: 2449.26 qps: 14703.57 (r/w/o: 0.00/9805.05/4898.52) lat (ms,95%): 5.28 err/s: 0.00 reconn/s: 0.00
 
[ 45s ] thds: 8 tps: 2542.97 qps: 15247.84 (r/w/o: 0.00/10161.89/5085.94) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 46s ] thds: 8 tps: 2388.80 qps: 14342.81 (r/w/o: 0.00/9565.21/4777.60) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
 
[ 47s ] thds: 8 tps: 2529.02 qps: 15174.11 (r/w/o: 0.00/10116.07/5058.04) lat (ms,95%): 4.49 err/s: 0.00 reconn/s: 0.00
 
[ 48s ] thds: 8 tps: 2591.74 qps: 15550.44 (r/w/o: 0.00/10366.96/5183.48) lat (ms,95%): 4.65 err/s: 0.00 reconn/s: 0.00
 
[ 49s ] thds: 8 tps: 2624.32 qps: 15745.90 (r/w/o: 0.00/10497.27/5248.63) lat (ms,95%): 4.57 err/s: 0.00 reconn/s: 0.00
 
[ 50s ] thds: 8 tps: 3019.60 qps: 18117.58 (r/w/o: 0.00/12078.38/6039.19) lat (ms,95%): 4.03 err/s: 0.00 reconn/s: 0.00
 
[ 51s ] thds: 8 tps: 2994.50 qps: 17966.98 (r/w/o: 0.00/11977.99/5988.99) lat (ms,95%): 3.89 err/s: 0.00 reconn/s: 0.00
 
[ 52s ] thds: 8 tps: 3023.92 qps: 18141.52 (r/w/o: 0.00/12093.68/6047.84) lat (ms,95%): 3.89 err/s: 0.00 reconn/s: 0.00
 
[ 53s ] thds: 8 tps: 3040.14 qps: 18242.83 (r/w/o: 0.00/12162.55/6080.28) lat (ms,95%): 3.96 err/s: 0.00 reconn/s: 0.00
 
[ 54s ] thds: 8 tps: 3038.74 qps: 18232.44 (r/w/o: 0.00/12154.96/6077.48) lat (ms,95%): 3.96 err/s: 0.00 reconn/s: 0.00
 
[ 55s ] thds: 8 tps: 2978.19 qps: 17864.16 (r/w/o: 0.00/11907.77/5956.39) lat (ms,95%): 4.03 err/s: 0.00 reconn/s: 0.00
 
[ 56s ] thds: 8 tps: 3033.73 qps: 18207.35 (r/w/o: 0.00/12139.90/6067.45) lat (ms,95%): 4.03 err/s: 0.00 reconn/s: 0.00
 
[ 57s ] thds: 8 tps: 2970.27 qps: 17821.61 (r/w/o: 0.00/11881.07/5940.54) lat (ms,95%): 4.18 err/s: 0.00 reconn/s: 0.00
 
[ 58s ] thds: 8 tps: 2939.04 qps: 17619.22 (r/w/o: 0.00/11741.15/5878.07) lat (ms,95%): 3.89 err/s: 0.00 reconn/s: 0.00
 
[ 59s ] thds: 8 tps: 2982.25 qps: 17906.51 (r/w/o: 0.00/11942.00/5964.51) lat (ms,95%): 4.10 err/s: 0.00 reconn/s: 0.00
 
[ 60s ] thds: 8 tps: 1512.93 qps: 9074.58 (r/w/o: 0.00/6048.72/3025.86) lat (ms,95%): 3.89 err/s: 0.00 reconn/s: 0.00
 
[ 61s ] thds: 8 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s: 0.00 reconn/s: 0.00
 
SQL statistics:
 
    queries performed:
 
        read:                            0
 
        write:                           546684
 
        other:                           273342
 
        total:                           820026
 
    transactions:                        136671 (2226.07 per sec.)
 
    queries:                             820026 (13356.41 per sec.)
 
    ignored errors:                      0      (0.00 per sec.)
 
    reconnects:                          0      (0.00 per sec.)
 
 
 
General statistics:
 
    total time:                          61.3915s
 
    total number of events:              136671
 
 
 
Latency (ms):
 
         min:                                    1.38
 
         avg:                                    3.59
 
         max:                                 1899.16
 
         95th percentile:                        5.18
 
         sum:                               490753.52
 
 
 
Threads fairness:
 
    events (avg/stddev):           17083.8750/19.26
 
    execution time (avg/stddev):   61.3442/0.02

The server log was:

$ sql/mysqld --no-defaults --skip-networking --datadir=$HOME/mariadb-datadir --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose --innodb-buffer-pool-size=10G --innodb-buffer-pool-dump-at-shutdown=0  --innodb_buffer_pool_dump_pct=100
 
2022-11-15  8:42:17 0 [Note] sql/mysqld (mysqld 10.5.19-MariaDB-1:10.5.13+maria~stretch) starting as process 196290 ...
 
2022-11-15  8:42:17 0 [Note] InnoDB: Uses event mutexes
 
2022-11-15  8:42:17 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-11-15  8:42:17 0 [Note] InnoDB: Number of pools: 1
 
2022-11-15  8:42:17 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2022-11-15  8:42:17 0 [Note] InnoDB: Using Linux native AIO
 
2022-11-15  8:42:17 0 [Note] InnoDB: Initializing buffer pool, total size = 10737418240, chunk size = 134217728
 
2022-11-15  8:42:17 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-11-15  8:42:17 0 [Note] InnoDB: 128 rollback segments are active.
 
2022-11-15  8:42:17 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-11-15  8:42:17 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-11-15  8:42:17 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2022-11-15  8:42:17 0 [Note] InnoDB: 10.5.19 started; log sequence number 15940321061; transaction id 1248623
 
2022-11-15  8:42:17 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-11-15  8:42:17 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-11-15  8:42:17 0 [Note] Reading of all Master_info entries succeeded
 
2022-11-15  8:42:17 0 [Note] Added new Master_info '' to hash table
 
2022-11-15  8:42:17 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.5.19-MariaDB-1:10.5.13+maria~stretch'  socket: '/tmp/mysql.sock'  port: 0  mariadb.org binary distribution
 
2022-11-15  8:43:06 0 [Note] InnoDB: Buffer pool(s) load completed at 221115  8:43:06

So from the load it took 49 seconds to load. At the 49 second mark on sysbench we see the QPS jump from 2.5k to 3k qps.

When buf_load_throttle_if_needed was re-enabled in the code, the sysbench results where:

[ 595s ] thds: 8 tps: 2535.96 qps: 15216.76 (r/w/o: 0.00/10144.84/5071.92) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00
 
[ 596s ] thds: 8 tps: 2546.10 qps: 15284.58 (r/w/o: 0.00/10192.39/5092.19) lat (ms,95%): 4.74 err/s: 0.00 reconn/s: 0.00
 
[ 597s ] thds: 8 tps: 2664.28 qps: 15978.68 (r/w/o: 0.00/10650.12/5328.57) lat (ms,95%): 4.41 err/s: 0.00 reconn/s: 0.00
 
[ 598s ] thds: 8 tps: 2687.93 qps: 16136.60 (r/w/o: 0.00/10760.73/5375.87) lat (ms,95%): 6.32 err/s: 0.00 reconn/s: 0.00
 
[ 599s ] thds: 8 tps: 2598.82 qps: 15581.91 (r/w/o: 0.00/10384.27/5197.64) lat (ms,95%): 6.67 err/s: 0.00 reconn/s: 0.00
 
[ 600s ] thds: 8 tps: 2628.64 qps: 15771.86 (r/w/o: 0.00/10514.57/5257.29) lat (ms,95%): 4.03 err/s: 0.00 reconn/s: 0.00
 
SQL statistics:
 
    queries performed:
 
        read:                            0
 
        write:                           5231866
 
        other:                           2615933
 
        total:                           7847799
 
    transactions:                        1307966 (2179.76 per sec.)
 
    queries:                             7847799 (13078.56 per sec.)
 
    ignored errors:                      1      (0.00 per sec.)
 
    reconnects:                          0      (0.00 per sec.)
 
 
 
General statistics:
 
    total time:                          600.0471s
 
    total number of events:              1307966
 
 
 
Latency (ms):
 
         min:                                    1.03
 
         avg:                                    3.67
 
         max:                                 2923.01
 
         95th percentile:                        5.18
 
         sum:                              4798169.74
 
 
 
Threads fairness:
 
    events (avg/stddev):           163495.7500/51.35
 
    execution time (avg/stddev):   599.7712/0.01

It was 8 seconds after the 10 minute sysbench run that mariadb finished its buffer pool load, something that on empty takes 10 seconds.

marko, can we straight prune out buf_load_throttle_if_needed in 10.5+? We sacrifice a not insignificant maximum performance on a high load to it will actually complete. Any load will effectively stall the loading of the buffer pool. The 60 minutes emil89 experienced in MDEV-29343 isn't good.

Comment by Daniel Black [ 2022-11-16 ] 

diff --git a/storage/innobase/buf/buf0dump.cc b/storage/innobase/buf/buf0dump.cc
 
index aaf07dd17eb..b4142ca3e3f 100644
 
--- a/storage/innobase/buf/buf0dump.cc
 
+++ b/storage/innobase/buf/buf0dump.cc
 
@@ -46,6 +46,8 @@ Created April 08, 2011 Vasil Dimov
 
 #include "mysql/service_wsrep.h" /* wsrep_recovery */
 
 #include <my_service_manager.h>
 
 
+#include "log.h"
 
+
 
 static void buf_do_load_dump();
 
 
 enum status_severity {
 
@@ -469,6 +471,7 @@ buf_load_throttle_if_needed(
 
        ut_time_ms() that often may turn out to be too expensive. */
 
 
        if (elapsed_time < 1000 /* 1 sec (1000 milli secs) */) {
 
+               sql_print_error("Elapsed_time %lu, activity %lu\n", elapsed_time, *last_activity_count);
 
                os_thread_sleep((1000 - elapsed_time) * 1000 /* micro secs */);
 
        }

Shows extent of 10.5 problem:

10.5 light load

 
Version: '10.5.19-MariaDB-1:10.5.13+maria~stretch'  socket: '/tmp/mysql.sock'  port: 0  mariadb.org binary distribution
 
2022-11-16 19:03:18 0 [ERROR] Elapsed_time 24, activity 1
 
 
 
2022-11-16 19:03:19 0 [ERROR] Elapsed_time 29, activity 10
 
 
 
2022-11-16 19:03:20 0 [ERROR] Elapsed_time 25, activity 19
 
 
 
2022-11-16 19:03:21 0 [ERROR] Elapsed_time 16, activity 28
 
 
 
2022-11-16 19:03:22 0 [ERROR] Elapsed_time 25, activity 37
 
 
 
2022-11-16 19:03:23 0 [ERROR] Elapsed_time 41, activity 46
 
 
 
2022-11-16 19:03:24 0 [ERROR] Elapsed_time 43, activity 55
 
 
 
2022-11-16 19:03:25 0 [ERROR] Elapsed_time 62, activity 64
 
 
 
2022-11-16 19:03:26 0 [ERROR] Elapsed_time 82, activity 73
 
 
 
2022-11-16 19:03:27 0 [ERROR] Elapsed_time 105, activity 82
 
 
 
2022-11-16 19:03:28 0 [ERROR] Elapsed_time 9, activity 90
 
 
 
2022-11-16 19:03:29 0 [ERROR] Elapsed_time 27, activity 99
 
 
 
2022-11-16 19:03:30 0 [ERROR] Elapsed_time 46, activity 108
 
 
 
2022-11-16 19:03:31 0 [ERROR] Elapsed_time 65, activity 117
 
 
 
2022-11-16 19:03:32 0 [ERROR] Elapsed_time 99, activity 126

Since elapsed time in microseconds, the sleep is for ~0.90-0.95 seconds with little work actually done.

10.6 under light load - same patch

 
2022-11-16 19:08:31 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-11-16 19:08:31 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(141).
 
2022-11-16 19:08:31 0 [ERROR] mysqld: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
2022-11-16 19:08:31 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.6.12-MariaDB'  socket: '/tmp/mysql.sock'  port: 0  MariaDB Server
 
2022-11-16 19:08:37 0 [Note] InnoDB: Buffer pool(s) load completed at 221116 19:08:37

10.6 sysbench load (with same patch)

 
2022-11-16 19:09:30 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-11-16 19:09:30 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(141).
 
2022-11-16 19:09:30 0 [ERROR] mysqld: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
2022-11-16 19:09:30 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.6.12-MariaDB'  socket: '/tmp/mysql.sock'  port: 0  MariaDB Server
 
2022-11-16 19:09:38 0 [Note] InnoDB: Buffer pool(s) load completed at 221116 19:09:38

So not 10.6 on sysbench load as expected, effect, only 10.5.

marko quote: "srv_inc_activity_count() is nearly unused in 10.6, only called by BtrBulk::insert() (ALTER TABLE or 10.7+ bulk insert)."

So this could be the emil89 case. The brutality of the sleep isn't proportional to the the activity.

Comment by Daniel Black [ 2022-11-18 ]

further testin

Comment by Daniel Black [ 2022-11-18 ]

10.6 test of alter table too minimal effort to increase buffer pool data from 10 seconds to 42 seconds.

10.6 mimimal load

 
CREATE TABLE `t1` (
 
  `f1` int(11) NOT NULL AUTO_INCREMENT,
 
  `f2` char(200) NOT NULL,
 
  `f3` char(200) NOT NULL,
 
  `f4` char(200) NOT NULL,
 
  PRIMARY KEY (`f1`)
 
) ENGINE=InnoDB AUTO_INCREMENT=3036 DEFAULT CHARSET=latin1 COLLATE=latin1_swedish_ci;
 
 
 
+----------+
 
| count(*) |
 
+----------+
 
|     2880 |
 
+----------+
 
 
 
$  while [ ! -S /tmp/mysql.sock ]; do sleep 0.001; done; while client/mysql -S /tmp/mysql.sock -e 'alter table t1 drop primary key, add primary key(f1,f2,f3,f4); alter table t1 drop primary key, add primary key(f1);' t2; do sleep 0.3; done

non time base throttle:

diff --git a/storage/innobase/buf/buf0dump.cc b/storage/innobase/buf/buf0dump.cc
 
index 770bb74c90a..6a1a5d52e9f 100644
 
--- a/storage/innobase/buf/buf0dump.cc
 
+++ b/storage/innobase/buf/buf0dump.cc
 
@@ -44,6 +44,8 @@ Created April 08, 2011 Vasil Dimov
 
 #include "mysql/service_wsrep.h" /* wsrep_recovery */
 
 #include <my_service_manager.h>
 
 
+#include "log.h"
 
+
 
 static void buf_do_load_dump();
 
 
 enum status_severity {
 
@@ -472,8 +474,11 @@ buf_load_throttle_if_needed(
 
        ut_time_ms() that often may turn out to be too expensive. */
 
 
        if (elapsed_time < 1000 /* 1 sec (1000 milli secs) */) {
 
-               std::this_thread::sleep_for(
 
-                       std::chrono::milliseconds(1000 - elapsed_time));
 
+               sql_print_error("Elapsed_time %lu, activity %lu", elapsed_time, *last_activity_count);
 
+               //std::this_thread::sleep_for(
 
+               //      std::chrono::milliseconds(1000 - elapsed_time));
 
+               os_aio_wait_until_no_pending_reads();
 
+               os_aio_wait_until_no_pending_writes();
 
        }
 
 
        *last_check_time = ut_time_ms();

9 Seconds:

2022-11-18 17:12:51 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-11-18 17:12:51 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-11-18 17:12:51 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(141).
 
2022-11-18 17:12:51 0 [ERROR] mysqld: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
2022-11-18 17:12:51 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.6.12-MariaDB'  socket: '/tmp/mysql.sock'  port: 0  MariaDB Server
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 15, activity 10
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 2, activity 13
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 2, activity 15
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 2, activity 16
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 1, activity 17
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 25, activity 19
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 26, activity 22
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 27, activity 24
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 1, activity 25
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 1, activity 26
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 22, activity 27
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 1, activity 29
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 49, activity 31
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 41, activity 32
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 72, activity 70
 
2022-11-18 17:12:51 0 [ERROR] Elapsed_time 22, activity 85
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 190, activity 119
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 20, activity 121
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 20, activity 124
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 1, activity 126
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 25, activity 128
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 26, activity 132
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 9, activity 135
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 16, activity 136
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 36, activity 138
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 1, activity 141
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 28, activity 143
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 26, activity 147
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 28, activity 150
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 42, activity 151
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 1, activity 223
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 479, activity 238
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 27, activity 240
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 28, activity 243
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 2, activity 246
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 1, activity 247
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 22, activity 249
 
2022-11-18 17:12:52 0 [ERROR] Elapsed_time 1, activity 251
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 28, activity 253
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 257
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 21, activity 259
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 261
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 31, activity 262
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 2, activity 264
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 265
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 267
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 47, activity 269
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 43, activity 270
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 323
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 177, activity 357
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 13, activity 359
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 19, activity 361
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 22, activity 364
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 24, activity 367
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 24, activity 370
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 373
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 374
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 25, activity 376
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 379
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 1, activity 380
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 20, activity 382
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 20, activity 385
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 25, activity 388
 
2022-11-18 17:12:53 0 [ERROR] Elapsed_time 50, activity 389
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 532, activity 476
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 23, activity 480
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 26, activity 483
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 486
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 487
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 5, activity 488
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 0, activity 489
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 23, activity 491
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 1, activity 493
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 23, activity 495
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 27, activity 497
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 24, activity 500
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 501
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 1, activity 502
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 503
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 1, activity 504
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 27, activity 506
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 1, activity 507
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 51, activity 508
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 250, activity 595
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 597
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 1, activity 598
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 0, activity 599
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 600
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 1, activity 601
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 26, activity 603
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 33, activity 606
 
2022-11-18 17:12:54 0 [ERROR] Elapsed_time 2, activity 609
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 610
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 25, activity 612
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 614
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 615
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 29, activity 617
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 0, activity 620
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 29, activity 622
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 33, activity 626
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 33, activity 627
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 680
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 520, activity 714
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 715
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 716
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 26, activity 718
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 721
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 26, activity 723
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 726
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 25, activity 728
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 25, activity 732
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 735
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 23, activity 737
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 26, activity 738
 
2022-11-18 17:12:55 0 [ERROR] Elapsed_time 1, activity 741
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 23, activity 743
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 22, activity 745
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 32, activity 746
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 30, activity 799
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 202, activity 833
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 835
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 26, activity 837
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 839
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 840
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 23, activity 842
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 844
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 28, activity 846
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 23, activity 849
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 2, activity 851
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 21, activity 852
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 854
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 28, activity 856
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 2, activity 859
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 860
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 861
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 862
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 48, activity 864
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 24, activity 865
 
2022-11-18 17:12:56 0 [ERROR] Elapsed_time 1, activity 918
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 497, activity 952
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 953
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 954
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 20, activity 956
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 21, activity 959
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 961
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 962
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 20, activity 964
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 966
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 967
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 968
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 969
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 970
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 21, activity 972
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 24, activity 975
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 22, activity 976
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 24, activity 978
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 980
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 26, activity 983
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 42, activity 984
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 187, activity 1071
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 1073
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 23, activity 1075
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 1077
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 1078
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 1079
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 7, activity 1081
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 24, activity 1083
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 27, activity 1086
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 2, activity 1090
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 1091
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 22, activity 1093
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 25, activity 1096
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 1, activity 1099
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 23, activity 1101
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 19, activity 1102
 
2022-11-18 17:12:57 0 [ERROR] Elapsed_time 42, activity 1103
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 541, activity 1190
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 27, activity 1192
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 24, activity 1195
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 26, activity 1198
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 30, activity 1201
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 1, activity 1204
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 0, activity 1205
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 21, activity 1207
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 3, activity 1209
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 1, activity 1210
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 1, activity 1212
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 1, activity 1213
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 27, activity 1214
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 1, activity 1217
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 15, activity 1218
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 19, activity 1220
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 20, activity 1221
 
2022-11-18 17:12:58 0 [ERROR] Elapsed_time 45, activity 1222
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 196, activity 1309
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 25, activity 1312
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1315
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1316
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 10, activity 1318
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 24, activity 1320
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1323
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1324
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 2, activity 1325
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1326
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 26, activity 1328
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1331
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1332
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 2, activity 1333
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1334
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 3, activity 1335
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 2, activity 1336
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1337
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1338
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 0, activity 1339
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 24, activity 1340
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 43, activity 1341
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 516, activity 1428
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 30, activity 1431
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 2, activity 1434
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 28, activity 1436
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1440
 
2022-11-18 17:12:59 0 [ERROR] Elapsed_time 1, activity 1441
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 2, activity 1443
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 0, activity 1444
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 32, activity 1446
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 2, activity 1449
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 1, activity 1450
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 0, activity 1451
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 27, activity 1452
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 2, activity 1454
 
2022-11-18 17:13:00 0 [ERROR] Elapsed_time 1, activity 1455
 
2022-11-18 17:13:00 0 [Note] InnoDB: Buffer pool(s) load completed at 221118 17:13:00

Impl of os_aio_wait_until_no_pending_writes never guarenteed to reach 0 however.

From marko, a purge thread based throttle ref.

So replacing buf_load_throttle_if_needed

void buf_load_throttle_if_needed()
 
{
 
   if (purge_busy())
 
   {
 
        some waiting criteria
 
   }
 
}
 
 
 
bool purge_busy() { return srv_max_purge_lag && m_history_length > srv_max_purge_lag; }

Comment by Marko Mäkelä [ 2022-11-21 ]

I think that the original motivation of the throttling was to allow some SQL workload to start executing, without the buffer pool restoring interfering it too much. This was implemented back when rotational storage (HDDs instead of SSDs) was the norm.

Normally we do not care much about the purge lag during normal operation. If a DBA cares about it, some explicit action can be executed, such as initiating a slow shutdown, or explicitly waiting for purge (MDEV-16952 SET GLOBAL innodb_max_purge_lag_wait=0;).

If the throttling would only care how busy the purge of transaction history is, do we actually need any throttling at all? How much impact would a best-effort load of the buffer pool dump have on concurrently executing SQL? For a valid test, I think that we must use innodb_flush_method=O_DIRECT so that nothing can be loaded from the file system cache.

Comment by Daniel Black [ 2022-11-21 ]

> How much impact would a best-effort load of the buffer pool dump have on concurrently executing SQL?

16% QPS degradation per comment 4 on a low 8 threads (16 core system).

> For a valid test, I think that we must use innodb_flush_method=O_DIRECT so that nothing can be loaded from the file system cache.

Test runs above used sync; echo 3 > /proc/sys/vm/drop_caches before starting mariadb so the file system cache bias was removed.

Comment by Marko Mäkelä [ 2022-11-22 ]

The change (removing the function buf_load_throttle_if_needed()) looks OK to me, but I think that we need to test the performance before applying this change.

I would not target 10.3, but rather 10.5 or 10.6. The buffer pool I/O layer works quite differently before 10.5 switched to a single buffer pool (MDEV-15058) and optimized the page cleaner thread (MDEV-23399, MDEV-23855).

Comment by Daniel Black [ 2022-11-22 ]

Being single threaded in 10.3, 10.4 (before MDEV-26547) there was only page request in transit at a time and saw this as a lower impact. The original user in SO post was using 10.4 (based on other questions about the same time).

Comment by Axel Schwenke [ 2022-11-28 ]

Benchmark results. I have tested 3 setups:

  1. MariaDB-10.6 @ 6d40274f65b, no buffer pool preloading (A)
  2. same commit, preloading 90% of buffer pool (B)
  3. PR#2339 on top of that commit, preloading 90% of buffer pool (C)

The buffer pool was 32G (with 16G redo) holding 128M rows in 32 tables, totaling 30GB of raw data. The pool was once created with slow shutdown, hence it was completely merged and purged. The pool was recreated from a tarfile for each run.

I tested 4 different workload scenarios:

  1. how it takes to complete the loading of the buffer pool without load
  2. how long it takes to mysqldump the OLTP database (to /dev/null)
  3. throughput for OLTP read/write with 1 thread over 15 minutes
  4. throughput for OLTP read/write with 32 threads over 15 minutes

Numbers:

variant time to load buffer pool
A n/a
B 4:07 min
C 4:05 min
variant time to dump
A 274 s
B 213 s
C 214 s

sysbench OLTP read/write is better viewed as time series plot:

Comment by Axel Schwenke [ 2022-11-28 ]

The same data for the datadir on SSD:

variant time to load buffer pool
A n/a
B 33 s
C 32 s
variant time to dump
A 204 s
B 191 s
C 190 s

time series. For 32 thd only the first 5 min are shown

Verdict: the server behaves very similar with or without PR#2339. OK to go.

Comment by Marko Mäkelä [ 2022-11-28 ]

Thank you, danblack and axel! In hdd_32_thd.png the right column is for loading the buffer pool with the patched version. Both those graphs and hdd_1_thd.png are only indicating an improvement, never any serious regression. So, removing the throttling seemed to be the right thing to do.

Generated at Thu Feb 08 09:37:32 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.