[#MDEV-29401] InnoDB history list length increased in 10.6 compared to 10.5 for the same load

[MDEV-29401] InnoDB history list length increased in 10.6 compared to 10.5 for the same load Created: 2022-08-27 Updated: 2024-01-02 Resolved: 2023-04-27
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB
Affects Version/s:	10.6.9
Fix Version/s:	11.1.1, 10.11.3, 11.0.2, 10.6.13, 10.8.8, 10.9.6, 10.10.4

Type:

Bug

Priority:

Critical

Reporter:

Valerii Kravchuk

Assignee:

Marko Mäkelä

Resolution:

Fixed

Votes:

Labels:

None

Attachments:

pt_large.test

tpcc2.pdf

write-only2.pdf

Issue Links:

Blocks
blocks	MDEV-16260	Scale the purge effort according to t...	Open
PartOf
is part of	MDEV-30628	10.6 performance regression with sust...	Needs Feedback
Relates
relates to	~~MDEV-29593~~	Purge misses a chance to free not-yet...	Closed
relates to	~~MDEV-30100~~	Assertion `purge_sys.tail.trx_no <= p...	Closed
relates to	~~MDEV-31169~~	innodb_max_purge_lag is documented as...	Closed
relates to	~~MDEV-29296~~	Undo Size Problems with MariaDB 10.6	Closed
relates to	~~MDEV-32050~~	UNDO logs still growing for write-int...	Closed

Description

Consider the following primitive sysbench test executed on a freshly installed server started with --no-defaults:

./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --time=300 --report_interval=10 prepare

./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --time=300 --report_interval=10 run

On 10.5.18 I get:

Yuliyas-MacBook-Air:maria10.5 Valerii$ bin/mysqld_safe --no-defaults &

[1] 52361

Yuliyas-MacBook-Air:maria10.5 Valerii$ 220827 15:58:06 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.5/data/Yuliyas-Air.err'.

220827 15:58:06 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.5/data

Yuliyas-MacBook-Air:maria10.5 Valerii$ bin/mysql -e 'show global variables like "innodb%purge%"';

+--------------------------------------+------------+

| Variable_name                        | Value      |

+--------------------------------------+------------+

| innodb_max_purge_lag                 | 0          |

| innodb_max_purge_lag_delay           | 0          |

| innodb_max_purge_lag_wait            | 4294967295 |

| innodb_purge_batch_size              | 300        |

| innodb_purge_rseg_truncate_frequency | 128        |

| innodb_purge_threads                 | 4          |

+--------------------------------------+------------+

Yuliyas-MacBook-Air:maria10.5 Valerii$ bin/mysql -e 'create database sbtest';

Yuliyas-MacBook-Air:maria10.5 Valerii$ bin/mysql -e 'show global status like "%history%"';

+----------------------------+-------+

| Variable_name              | Value |

+----------------------------+-------+

| Innodb_history_list_length | 60    |

+----------------------------+-------+

Then after running prepare:

Yuliyas-MacBook-Air:maria10.5 Valerii$ bin/mysql -e 'show global status like "%history%"';

+----------------------------+-------+

| Variable_name              | Value |

+----------------------------+-------+

| Innodb_history_list_length | 21    |

+----------------------------+-------+

Then I run the test for 300 seconds:

Yuliyas-MacBook-Air:sysbench Valerii$ ./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --time=300 --report_interval=10 run

sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:

Number of threads: 4

Report intermediate results every 10 second(s)

Initializing random number generator from current time

Initializing worker threads...

Threads started!

[ 10s ] thds: 4 tps: 593.70 qps: 11879.11 (r/w/o: 8316.51/2374.80/1187.80) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 4 tps: 604.43 qps: 12088.03 (r/w/o: 8461.44/2417.73/1208.86) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 4 tps: 619.17 qps: 12385.00 (r/w/o: 8669.71/2476.96/1238.33) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 4 tps: 606.82 qps: 12137.18 (r/w/o: 8495.57/2427.98/1213.64) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 4 tps: 637.16 qps: 12739.69 (r/w/o: 8917.73/2547.64/1274.32) lat (ms,95%): 8.74 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 4 tps: 611.75 qps: 12238.95 (r/w/o: 8566.97/2448.49/1223.50) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 4 tps: 605.34 qps: 12105.49 (r/w/o: 8474.62/2420.18/1210.69) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 4 tps: 609.67 qps: 12195.05 (r/w/o: 8535.62/2439.99/1219.45) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 4 tps: 624.65 qps: 12490.97 (r/w/o: 8744.48/2497.29/1249.20) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 4 tps: 621.98 qps: 12440.71 (r/w/o: 8708.33/2488.42/1243.96) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 4 tps: 609.24 qps: 12183.33 (r/w/o: 8528.71/2436.15/1218.47) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 4 tps: 617.56 qps: 12353.37 (r/w/o: 8646.42/2471.84/1235.12) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 130s ] thds: 4 tps: 601.65 qps: 12030.75 (r/w/o: 8422.46/2404.99/1203.29) lat (ms,95%): 9.73 err/s: 0.00 reconn/s: 0.00

[ 140s ] thds: 4 tps: 625.19 qps: 12504.72 (r/w/o: 8753.20/2501.14/1250.37) lat (ms,95%): 8.74 err/s: 0.00 reconn/s: 0.00

[ 150s ] thds: 4 tps: 611.64 qps: 12234.06 (r/w/o: 8563.00/2447.77/1223.29) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 160s ] thds: 4 tps: 630.46 qps: 12607.53 (r/w/o: 8826.19/2520.43/1260.91) lat (ms,95%): 8.74 err/s: 0.00 reconn/s: 0.00

[ 170s ] thds: 4 tps: 618.25 qps: 12366.61 (r/w/o: 8655.71/2474.40/1236.50) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 180s ] thds: 4 tps: 599.52 qps: 11990.45 (r/w/o: 8393.31/2398.09/1199.04) lat (ms,95%): 9.56 err/s: 0.00 reconn/s: 0.00

[ 190s ] thds: 4 tps: 625.74 qps: 12514.52 (r/w/o: 8760.30/2502.74/1251.47) lat (ms,95%): 8.74 err/s: 0.00 reconn/s: 0.00

[ 200s ] thds: 4 tps: 615.72 qps: 12312.31 (r/w/o: 8619.42/2461.46/1231.43) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 210s ] thds: 4 tps: 623.64 qps: 12474.94 (r/w/o: 8731.52/2496.15/1247.27) lat (ms,95%): 8.58 err/s: 0.00 reconn/s: 0.00

[ 220s ] thds: 4 tps: 620.10 qps: 12397.36 (r/w/o: 8678.34/2478.81/1240.21) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 230s ] thds: 4 tps: 611.32 qps: 12228.84 (r/w/o: 8560.94/2445.27/1222.63) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 240s ] thds: 4 tps: 617.59 qps: 12351.54 (r/w/o: 8645.62/2470.75/1235.17) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 250s ] thds: 4 tps: 609.73 qps: 12194.84 (r/w/o: 8536.85/2438.53/1219.46) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 260s ] thds: 4 tps: 620.58 qps: 12413.35 (r/w/o: 8688.68/2483.51/1241.15) lat (ms,95%): 8.90 err/s: 0.00 reconn/s: 0.00

[ 270s ] thds: 4 tps: 624.39 qps: 12488.29 (r/w/o: 8741.52/2497.98/1248.79) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 280s ] thds: 4 tps: 625.15 qps: 12503.04 (r/w/o: 8752.13/2500.61/1250.30) lat (ms,95%): 8.43 err/s: 0.00 reconn/s: 0.00

[ 290s ] thds: 4 tps: 474.41 qps: 9488.10 (r/w/o: 6641.67/1897.62/948.81) lat (ms,95%): 17.63 err/s: 0.00 reconn/s: 0.00

[ 300s ] thds: 4 tps: 598.52 qps: 11970.42 (r/w/o: 8379.30/2394.08/1197.04) lat (ms,95%): 11.24 err/s: 0.00 reconn/s: 0.00

SQL statistics:

    queries performed:

        read:                            2564226

        write:                           732636

        other:                           366318

        total:                           3663180

    transactions:                        183159 (610.51 per sec.)

    queries:                             3663180 (12210.26 per sec.)

    ignored errors:                      0      (0.00 per sec.)

    reconnects:                          0      (0.00 per sec.)

Throughput:

    events/s (eps):                      610.5130

    time elapsed:                        300.0084s

    total number of events:              183159

Latency (ms):

         min:                                    3.23

         avg:                                    6.55

         max:                                  122.19

         95th percentile:                        9.22

         sum:                              1199364.94

Threads fairness:

    events (avg/stddev):           45789.7500/18.14

    execution time (avg/stddev):   299.8412/0.00

and while it runs in another shell I monitor history list length for 200 seconds:

Yuliyas-MacBook-Air:maria10.5 Valerii$ for i in `seq 1 200`; do bin/mysql -B -e "show global status like '%history%'" | grep history ; sleep 1; done

Innodb_history_list_length	45

Innodb_history_list_length	17

Innodb_history_list_length	93

Innodb_history_list_length	56

Innodb_history_list_length	40

Innodb_history_list_length	20

Innodb_history_list_length	80

Innodb_history_list_length	58

Innodb_history_list_length	67

Innodb_history_list_length	36

Innodb_history_list_length	49

Innodb_history_list_length	27

Innodb_history_list_length	80

Innodb_history_list_length	29

Innodb_history_list_length	54

Innodb_history_list_length	73

Innodb_history_list_length	30

Innodb_history_list_length	8

Innodb_history_list_length	3

Innodb_history_list_length	16

Innodb_history_list_length	68

Innodb_history_list_length	78

Innodb_history_list_length	4

Innodb_history_list_length	13

Innodb_history_list_length	77

Innodb_history_list_length	47

Innodb_history_list_length	27

Innodb_history_list_length	12

Innodb_history_list_length	40

Innodb_history_list_length	16

Innodb_history_list_length	1

Innodb_history_list_length	92

Innodb_history_list_length	54

Innodb_history_list_length	41

Innodb_history_list_length	92

Innodb_history_list_length	58

Innodb_history_list_length	57

Innodb_history_list_length	44

Innodb_history_list_length	16

Innodb_history_list_length	68

Innodb_history_list_length	76

Innodb_history_list_length	81

Innodb_history_list_length	88

Innodb_history_list_length	69

Innodb_history_list_length	76

Innodb_history_list_length	61

Innodb_history_list_length	43

Innodb_history_list_length	36

Innodb_history_list_length	72

Innodb_history_list_length	75

Innodb_history_list_length	32

Innodb_history_list_length	8

Innodb_history_list_length	11

Innodb_history_list_length	8

Innodb_history_list_length	11

Innodb_history_list_length	16

Innodb_history_list_length	29

Innodb_history_list_length	60

Innodb_history_list_length	31

Innodb_history_list_length	81

Innodb_history_list_length	60

Innodb_history_list_length	45

Innodb_history_list_length	26

Innodb_history_list_length	9

Innodb_history_list_length	86

Innodb_history_list_length	84

Innodb_history_list_length	44

Innodb_history_list_length	17

Innodb_history_list_length	34

Innodb_history_list_length	24

Innodb_history_list_length	92

Innodb_history_list_length	71

Innodb_history_list_length	24

Innodb_history_list_length	97

Innodb_history_list_length	82

Innodb_history_list_length	12

Innodb_history_list_length	4

Innodb_history_list_length	84

Innodb_history_list_length	93

Innodb_history_list_length	20

Innodb_history_list_length	4

Innodb_history_list_length	4

Innodb_history_list_length	25

Innodb_history_list_length	13

Innodb_history_list_length	4

Innodb_history_list_length	10

Innodb_history_list_length	96

Innodb_history_list_length	32

Innodb_history_list_length	4

Innodb_history_list_length	4

Innodb_history_list_length	12

Innodb_history_list_length	8

Innodb_history_list_length	16

Innodb_history_list_length	8

Innodb_history_list_length	4

Innodb_history_list_length	37

Innodb_history_list_length	38

Innodb_history_list_length	72

Innodb_history_list_length	20

Innodb_history_list_length	33

Innodb_history_list_length	84

Innodb_history_list_length	28

Innodb_history_list_length	8

Innodb_history_list_length	92

Innodb_history_list_length	83

Innodb_history_list_length	83

Innodb_history_list_length	52

Innodb_history_list_length	22

Innodb_history_list_length	28

Innodb_history_list_length	24

Innodb_history_list_length	20

Innodb_history_list_length	17

Innodb_history_list_length	60

Innodb_history_list_length	39

Innodb_history_list_length	44

Innodb_history_list_length	9

Innodb_history_list_length	8

Innodb_history_list_length	72

Innodb_history_list_length	72

Innodb_history_list_length	23

Innodb_history_list_length	34

Innodb_history_list_length	41

Innodb_history_list_length	21

Innodb_history_list_length	12

Innodb_history_list_length	87

Innodb_history_list_length	78

Innodb_history_list_length	56

Innodb_history_list_length	29

Innodb_history_list_length	41

Innodb_history_list_length	54

Innodb_history_list_length	24

Innodb_history_list_length	28

Innodb_history_list_length	68

Innodb_history_list_length	24

Innodb_history_list_length	39

Innodb_history_list_length	20

Innodb_history_list_length	70

Innodb_history_list_length	79

Innodb_history_list_length	72

Innodb_history_list_length	44

Innodb_history_list_length	48

Innodb_history_list_length	39

Innodb_history_list_length	38

Innodb_history_list_length	56

Innodb_history_list_length	56

Innodb_history_list_length	48

Innodb_history_list_length	4

Innodb_history_list_length	88

Innodb_history_list_length	80

Innodb_history_list_length	80

Innodb_history_list_length	74

Innodb_history_list_length	94

Innodb_history_list_length	49

Innodb_history_list_length	6

Innodb_history_list_length	29

Innodb_history_list_length	30

Innodb_history_list_length	29

Innodb_history_list_length	72

Innodb_history_list_length	65

Innodb_history_list_length	40

Innodb_history_list_length	31

Innodb_history_list_length	92

Innodb_history_list_length	88

Innodb_history_list_length	59

Innodb_history_list_length	45

Innodb_history_list_length	15

Innodb_history_list_length	52

Innodb_history_list_length	91

Innodb_history_list_length	79

Innodb_history_list_length	22

Innodb_history_list_length	14

Innodb_history_list_length	24

Innodb_history_list_length	53

Innodb_history_list_length	33

Innodb_history_list_length	36

Innodb_history_list_length	77

Innodb_history_list_length	84

Innodb_history_list_length	40

Innodb_history_list_length	40

Innodb_history_list_length	40

Innodb_history_list_length	33

Innodb_history_list_length	56

Innodb_history_list_length	37

Innodb_history_list_length	26

Innodb_history_list_length	24

Innodb_history_list_length	99

Innodb_history_list_length	85

Innodb_history_list_length	54

Innodb_history_list_length	46

Innodb_history_list_length	50

Innodb_history_list_length	16

Innodb_history_list_length	20

Innodb_history_list_length	85

Innodb_history_list_length	17

Innodb_history_list_length	12

Innodb_history_list_length	60

Innodb_history_list_length	50

Innodb_history_list_length	68

Innodb_history_list_length	40

Innodb_history_list_length	97

Yuliyas-MacBook-Air:maria10.5 Valerii$ bin/mysql -e 'show global status like "%history%"';

+----------------------------+-------+

| Variable_name              | Value |

+----------------------------+-------+

| Innodb_history_list_length | 68    |

+----------------------------+-------+

Yuliyas-MacBook-Air:maria10.5 Valerii$

Note that it never grows even to 100 (this is on an old MacBook Air 2015 with 4 cores and SSD).

With 10.6.9 started with --no-defaults the same test gives:

Yuliyas-MacBook-Air:maria10.6 Valerii$ bin/mysqld_safe --no-defaults &

[1] 51231

Yuliyas-MacBook-Air:maria10.6 Valerii$ 220827 15:41:30 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.

220827 15:41:30 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data

Yuliyas-MacBook-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb%purge%"';

+--------------------------------------+------------+

| Variable_name                        | Value      |

+--------------------------------------+------------+

| innodb_max_purge_lag                 | 0          |

| innodb_max_purge_lag_delay           | 0          |

| innodb_max_purge_lag_wait            | 4294967295 |

| innodb_purge_batch_size              | 300        |

| innodb_purge_rseg_truncate_frequency | 128        |

| innodb_purge_threads                 | 4          |

+--------------------------------------+------------+

Yuliyas-MacBook-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"';

+----------------------------+-------+

| Variable_name              | Value |

+----------------------------+-------+

| Innodb_history_list_length | 4     |

+----------------------------+-------+

Yuliyas-MacBook-Air:maria10.6 Valerii$ bin/mysql -e 'create database sbtest';

and then:

Yuliyas-MacBook-Air:sysbench Valerii$ ./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --time=300 --report_interval=10 prepare

sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)

Initializing worker threads...

Creating table 'sbtest1'...Creating table 'sbtest2'...Creating table 'sbtest4'...

Creating table 'sbtest3'...

Inserting 100000 records into 'sbtest1'

Inserting 100000 records into 'sbtest2'

Inserting 100000 records into 'sbtest4'

Inserting 100000 records into 'sbtest3'

Creating a secondary index on 'sbtest1'...

Creating a secondary index on 'sbtest3'...

Creating a secondary index on 'sbtest2'...

Creating a secondary index on 'sbtest4'...

Yuliyas-MacBook-Air:sysbench Valerii$ ./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --time=300 --report_interval=10 run

sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:

Number of threads: 4

Report intermediate results every 10 second(s)

Initializing random number generator from current time

Initializing worker threads...

Threads started!

[ 10s ] thds: 4 tps: 603.02 qps: 12066.02 (r/w/o: 8447.49/2412.08/1206.44) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 4 tps: 604.71 qps: 12095.01 (r/w/o: 8466.18/2419.42/1209.41) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 4 tps: 607.60 qps: 12150.59 (r/w/o: 8505.60/2429.80/1215.20) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 4 tps: 614.18 qps: 12285.11 (r/w/o: 8599.36/2457.40/1228.35) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 4 tps: 597.57 qps: 11950.47 (r/w/o: 8364.63/2390.79/1195.05) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 4 tps: 616.51 qps: 12332.02 (r/w/o: 8632.48/2466.42/1233.11) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 4 tps: 607.43 qps: 12146.90 (r/w/o: 8503.95/2428.10/1214.85) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 4 tps: 601.10 qps: 12020.89 (r/w/o: 8414.26/2404.42/1202.21) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 4 tps: 610.95 qps: 12219.33 (r/w/o: 8553.65/2443.79/1221.89) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 4 tps: 607.67 qps: 12155.79 (r/w/o: 8508.17/2432.28/1215.34) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 4 tps: 598.80 qps: 11968.57 (r/w/o: 8377.58/2393.59/1197.40) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 4 tps: 597.24 qps: 11950.60 (r/w/o: 8366.96/2388.96/1194.68) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00

[ 130s ] thds: 4 tps: 597.25 qps: 11946.35 (r/w/o: 8361.54/2390.31/1194.51) lat (ms,95%): 9.56 err/s: 0.00 reconn/s: 0.00

[ 140s ] thds: 4 tps: 593.66 qps: 11867.71 (r/w/o: 8307.05/2373.34/1187.32) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00

[ 150s ] thds: 4 tps: 599.07 qps: 11985.28 (r/w/o: 8389.77/2397.48/1198.04) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00

[ 160s ] thds: 4 tps: 602.51 qps: 12046.31 (r/w/o: 8432.35/2408.84/1205.12) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 170s ] thds: 4 tps: 586.73 qps: 11738.76 (r/w/o: 8218.39/2346.91/1173.46) lat (ms,95%): 10.27 err/s: 0.00 reconn/s: 0.00

[ 180s ] thds: 4 tps: 611.28 qps: 12227.12 (r/w/o: 8557.86/2446.70/1222.55) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 190s ] thds: 4 tps: 599.95 qps: 11994.93 (r/w/o: 8396.42/2398.61/1199.90) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 200s ] thds: 4 tps: 605.24 qps: 12105.68 (r/w/o: 8474.61/2420.58/1210.49) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 210s ] thds: 4 tps: 610.98 qps: 12222.81 (r/w/o: 8555.36/2445.50/1221.95) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00

[ 220s ] thds: 4 tps: 618.72 qps: 12370.35 (r/w/o: 8659.61/2473.29/1237.45) lat (ms,95%): 8.74 err/s: 0.00 reconn/s: 0.00

[ 230s ] thds: 4 tps: 622.05 qps: 12445.03 (r/w/o: 8711.15/2489.79/1244.09) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00

[ 240s ] thds: 4 tps: 608.42 qps: 12162.67 (r/w/o: 8513.73/2432.09/1216.85) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 250s ] thds: 4 tps: 618.69 qps: 12379.66 (r/w/o: 8665.90/2476.37/1237.39) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00

[ 260s ] thds: 4 tps: 590.16 qps: 11801.45 (r/w/o: 8262.01/2359.13/1180.32) lat (ms,95%): 10.09 err/s: 0.00 reconn/s: 0.00

[ 270s ] thds: 4 tps: 602.18 qps: 12045.33 (r/w/o: 8430.74/2410.23/1204.36) lat (ms,95%): 9.56 err/s: 0.00 reconn/s: 0.00

[ 280s ] thds: 4 tps: 592.40 qps: 11843.06 (r/w/o: 8290.24/2368.01/1184.81) lat (ms,95%): 9.56 err/s: 0.00 reconn/s: 0.00

[ 290s ] thds: 4 tps: 584.11 qps: 11685.27 (r/w/o: 8180.59/2336.45/1168.23) lat (ms,95%): 9.91 err/s: 0.00 reconn/s: 0.00

[ 300s ] thds: 4 tps: 587.95 qps: 11758.94 (r/w/o: 8231.26/2351.79/1175.89) lat (ms,95%): 9.73 err/s: 0.00 reconn/s: 0.00

SQL statistics:

    queries performed:

        read:                            2533818

        write:                           723948

        other:                           361974

        total:                           3619740

    transactions:                        180987 (603.27 per sec.)

    queries:                             3619740 (12065.36 per sec.)

    ignored errors:                      0      (0.00 per sec.)

    reconnects:                          0      (0.00 per sec.)

Throughput:

    events/s (eps):                      603.2679

    time elapsed:                        300.0110s

    total number of events:              180987

Latency (ms):

         min:                                    2.73

         avg:                                    6.63

         max:                                   87.35

         95th percentile:                        9.22

         sum:                              1199374.08

Threads fairness:

    events (avg/stddev):           45246.7500/30.85

    execution time (avg/stddev):   299.8435/0.00

We get a bit smaller TPS and QPS throughput, but the same script checking history list length for 200 seconds gives the following:

Yuliyas-MacBook-Air:maria10.6 Valerii$ for i in `seq 1 200`; do bin/mysql -B -e "show global status like '%history%'" | grep history ; sleep 1; done

Innodb_history_list_length	1653

Innodb_history_list_length	2303

Innodb_history_list_length	2876

Innodb_history_list_length	3517

Innodb_history_list_length	4142

Innodb_history_list_length	4786

Innodb_history_list_length	5406

Innodb_history_list_length	6026

Innodb_history_list_length	6625

Innodb_history_list_length	7278

Innodb_history_list_length	7913

Innodb_history_list_length	8557

Innodb_history_list_length	9192

Innodb_history_list_length	9772

Innodb_history_list_length	10443

Innodb_history_list_length	11053

Innodb_history_list_length	11700

Innodb_history_list_length	12313

Innodb_history_list_length	12932

Innodb_history_list_length	13571

Innodb_history_list_length	14231

Innodb_history_list_length	14859

Innodb_history_list_length	15470

Innodb_history_list_length	16088

Innodb_history_list_length	16740

Innodb_history_list_length	17355

Innodb_history_list_length	17995

Innodb_history_list_length	18627

Innodb_history_list_length	19244

Innodb_history_list_length	19879

Innodb_history_list_length	20577

Innodb_history_list_length	530

Innodb_history_list_length	1154

Innodb_history_list_length	1783

Innodb_history_list_length	2436

Innodb_history_list_length	3048

Innodb_history_list_length	3727

Innodb_history_list_length	4365

Innodb_history_list_length	5027

Innodb_history_list_length	5672

Innodb_history_list_length	6254

Innodb_history_list_length	6835

Innodb_history_list_length	7408

Innodb_history_list_length	8043

Innodb_history_list_length	8687

Innodb_history_list_length	9308

Innodb_history_list_length	9941

Innodb_history_list_length	10611

Innodb_history_list_length	11258

Innodb_history_list_length	11890

Innodb_history_list_length	12543

Innodb_history_list_length	13170

Innodb_history_list_length	13800

Innodb_history_list_length	14417

Innodb_history_list_length	15063

Innodb_history_list_length	15707

Innodb_history_list_length	16372

Innodb_history_list_length	16999

Innodb_history_list_length	17631

Innodb_history_list_length	18275

Innodb_history_list_length	598

Innodb_history_list_length	1213

Innodb_history_list_length	1845

Innodb_history_list_length	2470

Innodb_history_list_length	3068

Innodb_history_list_length	3666

Innodb_history_list_length	4299

Innodb_history_list_length	4954

Innodb_history_list_length	5605

Innodb_history_list_length	6247

Innodb_history_list_length	6889

Innodb_history_list_length	7479

Innodb_history_list_length	8118

Innodb_history_list_length	8720

Innodb_history_list_length	9326

Innodb_history_list_length	9969

Innodb_history_list_length	10636

Innodb_history_list_length	11295

Innodb_history_list_length	11891

Innodb_history_list_length	12534

Innodb_history_list_length	13174

Innodb_history_list_length	13801

Innodb_history_list_length	14411

Innodb_history_list_length	15044

Innodb_history_list_length	15676

Innodb_history_list_length	16309

Innodb_history_list_length	16953

Innodb_history_list_length	17620

Innodb_history_list_length	12695

Innodb_history_list_length	656

Innodb_history_list_length	1282

Innodb_history_list_length	1887

Innodb_history_list_length	2520

Innodb_history_list_length	3108

Innodb_history_list_length	3756

Innodb_history_list_length	4400

Innodb_history_list_length	5057

Innodb_history_list_length	5705

Innodb_history_list_length	6338

Innodb_history_list_length	6969

Innodb_history_list_length	7524

Innodb_history_list_length	8169

Innodb_history_list_length	8766

Innodb_history_list_length	9345

Innodb_history_list_length	9988

Innodb_history_list_length	10633

Innodb_history_list_length	11265

Innodb_history_list_length	11894

Innodb_history_list_length	12470

Innodb_history_list_length	13063

Innodb_history_list_length	13657

Innodb_history_list_length	14278

Innodb_history_list_length	14918

Innodb_history_list_length	15566

Innodb_history_list_length	16213

Innodb_history_list_length	16840

Innodb_history_list_length	17486

Innodb_history_list_length	18109

Innodb_history_list_length	76

Innodb_history_list_length	704

Innodb_history_list_length	1294

Innodb_history_list_length	1936

Innodb_history_list_length	2530

Innodb_history_list_length	3167

Innodb_history_list_length	3800

Innodb_history_list_length	4445

Innodb_history_list_length	5093

Innodb_history_list_length	5737

Innodb_history_list_length	6346

Innodb_history_list_length	6932

Innodb_history_list_length	7479

Innodb_history_list_length	8092

Innodb_history_list_length	8705

Innodb_history_list_length	9334

Innodb_history_list_length	9968

Innodb_history_list_length	10609

Innodb_history_list_length	11220

Innodb_history_list_length	11884

Innodb_history_list_length	12518

Innodb_history_list_length	13107

Innodb_history_list_length	13710

Innodb_history_list_length	14342

Innodb_history_list_length	14953

Innodb_history_list_length	15556

Innodb_history_list_length	16178

Innodb_history_list_length	16796

Innodb_history_list_length	17438

Innodb_history_list_length	18071

Innodb_history_list_length	193

Innodb_history_list_length	791

Innodb_history_list_length	1434

Innodb_history_list_length	2044

Innodb_history_list_length	2677

Innodb_history_list_length	3312

Innodb_history_list_length	3952

Innodb_history_list_length	4594

Innodb_history_list_length	5214

Innodb_history_list_length	5824

Innodb_history_list_length	6430

Innodb_history_list_length	6954

Innodb_history_list_length	7591

Innodb_history_list_length	8176

Innodb_history_list_length	8846

Innodb_history_list_length	9484

Innodb_history_list_length	10127

Innodb_history_list_length	10756

Innodb_history_list_length	11404

Innodb_history_list_length	12024

Innodb_history_list_length	12672

Innodb_history_list_length	13267

Innodb_history_list_length	13904

Innodb_history_list_length	14540

Innodb_history_list_length	15176

Innodb_history_list_length	15797

Innodb_history_list_length	16407

Innodb_history_list_length	17044

Innodb_history_list_length	17686

Innodb_history_list_length	18330

Innodb_history_list_length	18939

Innodb_history_list_length	556

Innodb_history_list_length	1171

Innodb_history_list_length	1837

Innodb_history_list_length	2441

Innodb_history_list_length	3097

Innodb_history_list_length	3708

Innodb_history_list_length	4378

Innodb_history_list_length	5028

Innodb_history_list_length	5603

Innodb_history_list_length	6238

Innodb_history_list_length	6857

Innodb_history_list_length	7458

Innodb_history_list_length	8100

Innodb_history_list_length	8754

Innodb_history_list_length	9377

Innodb_history_list_length	9994

Innodb_history_list_length	10622

Innodb_history_list_length	11247

Innodb_history_list_length	11910

Innodb_history_list_length	12528

Innodb_history_list_length	13184

So, the length grow up to 19000 and is constantly much higher than with 10.5, all this with the same default values. This will definitely impact any concurrent SELECTs and in general can be considered a performance regression with default settings that should be documented if not resolved.

Comments

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

I was able to repeat a significant difference between 10.5 and 10.6 when using some parameters that were suggested in ~~MDEV-29296~~. A possible explanation of a 10.5-to-10.6 regression might be the numerous changes to make DDL crash-safe. This looks like a delicate producer/consumer problem with no simple cause or fix.

With the following patch, I proved ~~MDEV-26356~~ to be innocent:

diff --git a/storage/innobase/trx/trx0purge.cc b/storage/innobase/trx/trx0purge.cc

index c0fafe1ec6b..15bc0b716ca 100644

--- a/storage/innobase/trx/trx0purge.cc

+++ b/storage/innobase/trx/trx0purge.cc

@@ -41,6 +41,7 @@ Created 3/26/1996 Heikki Tuuri

 #include <mysql/service_wsrep.h>

 #include <unordered_map>

+#include "log.h"

 #ifdef UNIV_PFS_RWLOCK

 extern mysql_pfs_key_t trx_purge_latch_key;

@@ -1167,6 +1168,8 @@ trx_purge_attach_undo_recs(ulint n_purge_threads)

 	purge_sys.head = purge_sys.tail;

+	sql_print_information("purge %zu", n_purge_threads);

 #ifdef UNIV_DEBUG

 	i = 0;

 	/* Debug code to validate some pre-requisites and reset done flag. */

Most of the time, this would display innodb_purge_threads. Occasionally during a test with innodb_purge_threads=32, the number of purge threads would be as low as 29. There were several hundred purge batches scheduled per second, possibly because I was using innodb_purge_batch_size=50. During shutdown (be it normal or innodb_fast_shutdown=0), the number of purge threads would quickly drop to 1.

On my system (nproc says 40), with 8×1M tables and Sysbench --threads=40, innodb_purge_threads=1 started to fall behind, but there was only a small difference between 10.5 and 10.6. Both were able to reduce the history list length every now and then.

One possible solution might be to tweak the thread pool somehow. I did not test --thread-handling=pool-of-threads, and I do not know how it is supposed to interact with the tpool, which is what schedules the purge tasks in 10.5 and 10.6. I hope that wlad can provide some insight.

Comment by Valerii Kravchuk [ 2022-08-29 ]

Tested the same way also on 2 slow cores Ubuntu 22.04 with slow HDD. With 10.5 we have:

openxs@ao756:~/dbs/maria10.5$ sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=openxs --time=300 --report_interval=10 run

sysbench 1.0.20 (using bundled LuaJIT 2.1.0-beta2)

Running the test with following options:

Number of threads: 4

Report intermediate results every 10 second(s)

Initializing random number generator from current time

Initializing worker threads...

Threads started!

[ 10s ] thds: 4 tps: 155.22 qps: 3110.81 (r/w/o: 2178.29/621.68/310.84) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 4 tps: 159.21 qps: 3182.71 (r/w/o: 2227.45/636.84/318.42) lat (ms,95%): 42.61 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 4 tps: 166.10 qps: 3324.60 (r/w/o: 2327.23/665.18/332.19) lat (ms,95%): 38.94 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 4 tps: 167.10 qps: 3342.06 (r/w/o: 2339.44/668.41/334.21) lat (ms,95%): 33.72 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 4 tps: 165.60 qps: 3311.41 (r/w/o: 2318.21/662.00/331.20) lat (ms,95%): 33.72 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 4 tps: 163.60 qps: 3270.67 (r/w/o: 2289.68/653.79/327.20) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 4 tps: 156.90 qps: 3139.49 (r/w/o: 2197.50/628.20/313.80) lat (ms,95%): 44.98 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 4 tps: 47.80 qps: 955.96 (r/w/o: 669.14/191.21/95.61) lat (ms,95%): 325.98 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 4 tps: 150.78 qps: 3016.09 (r/w/o: 2111.01/603.52/301.56) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 4 tps: 155.62 qps: 3112.43 (r/w/o: 2178.70/622.49/311.24) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 4 tps: 161.40 qps: 3225.07 (r/w/o: 2257.88/644.39/322.80) lat (ms,95%): 34.33 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 4 tps: 158.48 qps: 3172.51 (r/w/o: 2220.43/635.12/316.96) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 130s ] thds: 4 tps: 158.02 qps: 3160.39 (r/w/o: 2212.27/632.08/316.04) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 140s ] thds: 4 tps: 157.90 qps: 3157.95 (r/w/o: 2210.56/631.59/315.79) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 150s ] thds: 4 tps: 156.70 qps: 3134.08 (r/w/o: 2193.86/626.82/313.41) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 160s ] thds: 4 tps: 156.98 qps: 3133.94 (r/w/o: 2193.55/626.73/313.66) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 170s ] thds: 4 tps: 149.52 qps: 2993.84 (r/w/o: 2096.04/598.47/299.33) lat (ms,95%): 44.98 err/s: 0.00 reconn/s: 0.00

[ 180s ] thds: 4 tps: 164.49 qps: 3292.03 (r/w/o: 2304.28/658.77/328.98) lat (ms,95%): 33.72 err/s: 0.00 reconn/s: 0.00

[ 190s ] thds: 4 tps: 148.29 qps: 2965.74 (r/w/o: 2076.02/593.15/296.57) lat (ms,95%): 45.79 err/s: 0.00 reconn/s: 0.00

[ 200s ] thds: 4 tps: 155.91 qps: 3118.10 (r/w/o: 2182.67/623.62/311.81) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 210s ] thds: 4 tps: 163.11 qps: 3261.17 (r/w/o: 2282.89/652.05/326.23) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 220s ] thds: 4 tps: 63.60 qps: 1272.13 (r/w/o: 891.12/253.81/127.20) lat (ms,95%): 215.44 err/s: 0.00 reconn/s: 0.00

[ 230s ] thds: 4 tps: 103.99 qps: 2080.31 (r/w/o: 1455.77/416.56/207.98) lat (ms,95%): 110.66 err/s: 0.00 reconn/s: 0.00

[ 240s ] thds: 4 tps: 158.01 qps: 3160.78 (r/w/o: 2212.30/632.46/316.03) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 250s ] thds: 4 tps: 149.00 qps: 2979.99 (r/w/o: 2085.99/596.00/298.00) lat (ms,95%): 44.98 err/s: 0.00 reconn/s: 0.00

[ 260s ] thds: 4 tps: 152.29 qps: 3045.65 (r/w/o: 2132.03/609.05/304.58) lat (ms,95%): 44.98 err/s: 0.00 reconn/s: 0.00

[ 270s ] thds: 4 tps: 149.41 qps: 2986.47 (r/w/o: 2090.32/597.33/298.82) lat (ms,95%): 55.82 err/s: 0.00 reconn/s: 0.00

[ 280s ] thds: 4 tps: 159.38 qps: 3187.67 (r/w/o: 2231.77/637.13/318.77) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 290s ] thds: 4 tps: 155.72 qps: 3114.42 (r/w/o: 2179.69/623.28/311.44) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 300s ] thds: 4 tps: 161.29 qps: 3224.05 (r/w/o: 2257.22/644.35/322.47) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

SQL statistics:

    queries performed:

        read:                            626066

        write:                           178876

        other:                           89438

        total:                           894380

    transactions:                        44719  (149.05 per sec.)

    queries:                             894380 (2981.01 per sec.)

    ignored errors:                      0      (0.00 per sec.)

    reconnects:                          0      (0.00 per sec.)

General statistics:

    total time:                          300.0222s

    total number of events:              44719

Latency (ms):

         min:                                    9.56

         avg:                                   26.83

         max:                                 1412.27

         95th percentile:                       44.98

         sum:                              1199859.18

Threads fairness:

    events (avg/stddev):           11179.7500/12.97

    execution time (avg/stddev):   299.9648/0.01

and history list length is small, less than 100:

openxs@ao756:~/dbs/maria10.5$ for i in `seq 1 200`; do bin/mysql -B -e "show global status like '%history%'" | grep history ; sleep 1; done

Innodb_history_list_length	28

Innodb_history_list_length	50

Innodb_history_list_length	18

Innodb_history_list_length	32

Innodb_history_list_length	6

Innodb_history_list_length	48

Innodb_history_list_length	15

Innodb_history_list_length	0

Innodb_history_list_length	38

Innodb_history_list_length	63

Innodb_history_list_length	50

Innodb_history_list_length	40

Innodb_history_list_length	66

Innodb_history_list_length	40

Innodb_history_list_length	5

Innodb_history_list_length	21

Innodb_history_list_length	6

Innodb_history_list_length	43

Innodb_history_list_length	12

Innodb_history_list_length	46

Innodb_history_list_length	30

Innodb_history_list_length	59

Innodb_history_list_length	38

Innodb_history_list_length	2

Innodb_history_list_length	50

Innodb_history_list_length	25

Innodb_history_list_length	54

Innodb_history_list_length	31

Innodb_history_list_length	16

Innodb_history_list_length	28

Innodb_history_list_length	10

Innodb_history_list_length	60

Innodb_history_list_length	27

Innodb_history_list_length	7

Innodb_history_list_length	48

Innodb_history_list_length	7

Innodb_history_list_length	56

Innodb_history_list_length	24

Innodb_history_list_length	46

Innodb_history_list_length	18

Innodb_history_list_length	51

Innodb_history_list_length	20

Innodb_history_list_length	57

Innodb_history_list_length	41

Innodb_history_list_length	3

Innodb_history_list_length	31

Innodb_history_list_length	67

Innodb_history_list_length	45

Innodb_history_list_length	51

Innodb_history_list_length	4

Innodb_history_list_length	63

Innodb_history_list_length	13

Innodb_history_list_length	27

Innodb_history_list_length	5

Innodb_history_list_length	60

Innodb_history_list_length	49

Innodb_history_list_length	64

Innodb_history_list_length	10

Innodb_history_list_length	31

Innodb_history_list_length	66

Innodb_history_list_length	49

Innodb_history_list_length	9

Innodb_history_list_length	54

Innodb_history_list_length	18

Innodb_history_list_length	22

Innodb_history_list_length	37

Innodb_history_list_length	27

Innodb_history_list_length	4

Innodb_history_list_length	74

Innodb_history_list_length	65

Innodb_history_list_length	43

Innodb_history_list_length	66

Innodb_history_list_length	50

Innodb_history_list_length	29

Innodb_history_list_length	60

Innodb_history_list_length	21

Innodb_history_list_length	42

Innodb_history_list_length	1

Innodb_history_list_length	42

Innodb_history_list_length	57

Innodb_history_list_length	4

Innodb_history_list_length	50

Innodb_history_list_length	8

Innodb_history_list_length	9

Innodb_history_list_length	61

Innodb_history_list_length	29

Innodb_history_list_length	30

Innodb_history_list_length	16

Innodb_history_list_length	31

Innodb_history_list_length	32

Innodb_history_list_length	4

Innodb_history_list_length	27

Innodb_history_list_length	16

Innodb_history_list_length	40

Innodb_history_list_length	14

Innodb_history_list_length	49

Innodb_history_list_length	24

Innodb_history_list_length	45

Innodb_history_list_length	0

Innodb_history_list_length	20

Innodb_history_list_length	7

Innodb_history_list_length	28

Innodb_history_list_length	59

Innodb_history_list_length	23

Innodb_history_list_length	48

Innodb_history_list_length	16

Innodb_history_list_length	56

Innodb_history_list_length	2

Innodb_history_list_length	30

Innodb_history_list_length	59

Innodb_history_list_length	14

Innodb_history_list_length	57

Innodb_history_list_length	17

Innodb_history_list_length	34

Innodb_history_list_length	8

Innodb_history_list_length	40

Innodb_history_list_length	37

Innodb_history_list_length	57

Innodb_history_list_length	40

Innodb_history_list_length	3

Innodb_history_list_length	4

Innodb_history_list_length	44

Innodb_history_list_length	15

Innodb_history_list_length	44

Innodb_history_list_length	16

Innodb_history_list_length	1

Innodb_history_list_length	21

Innodb_history_list_length	31

Innodb_history_list_length	64

Innodb_history_list_length	25

Innodb_history_list_length	0

Innodb_history_list_length	23

Innodb_history_list_length	41

Innodb_history_list_length	21

Innodb_history_list_length	36

Innodb_history_list_length	40

Innodb_history_list_length	11

Innodb_history_list_length	23

Innodb_history_list_length	2

Innodb_history_list_length	17

Innodb_history_list_length	3

Innodb_history_list_length	44

Innodb_history_list_length	52

Innodb_history_list_length	34

Innodb_history_list_length	0

Innodb_history_list_length	34

Innodb_history_list_length	57

Innodb_history_list_length	48

Innodb_history_list_length	63

Innodb_history_list_length	36

Innodb_history_list_length	63

Innodb_history_list_length	46

Innodb_history_list_length	12

Innodb_history_list_length	52

Innodb_history_list_length	64

Innodb_history_list_length	32

Innodb_history_list_length	4

Innodb_history_list_length	40

Innodb_history_list_length	31

Innodb_history_list_length	53

Innodb_history_list_length	20

Innodb_history_list_length	51

Innodb_history_list_length	10

Innodb_history_list_length	36

Innodb_history_list_length	4

Innodb_history_list_length	23

Innodb_history_list_length	49

Innodb_history_list_length	36

Innodb_history_list_length	46

Innodb_history_list_length	24

Innodb_history_list_length	0

Innodb_history_list_length	22

Innodb_history_list_length	23

Innodb_history_list_length	32

Innodb_history_list_length	49

Innodb_history_list_length	29

Innodb_history_list_length	50

Innodb_history_list_length	44

Innodb_history_list_length	16

Innodb_history_list_length	4

Innodb_history_list_length	34

Innodb_history_list_length	36

Innodb_history_list_length	47

Innodb_history_list_length	23

Innodb_history_list_length	50

Innodb_history_list_length	33

Innodb_history_list_length	10

Innodb_history_list_length	21

Innodb_history_list_length	62

Innodb_history_list_length	52

Innodb_history_list_length	68

Innodb_history_list_length	39

Innodb_history_list_length	11

Innodb_history_list_length	40

Innodb_history_list_length	5

Innodb_history_list_length	50

Innodb_history_list_length	26

Innodb_history_list_length	56

Innodb_history_list_length	85

Innodb_history_list_length	60

With 10.6 TPS and QPS is a bit higher:

openxs@ao756:~/dbs/maria10.5$ sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=openxs --time=300 --report_interval=10 run

sysbench 1.0.20 (using bundled LuaJIT 2.1.0-beta2)

Running the test with following options:

Number of threads: 4

Report intermediate results every 10 second(s)

Initializing random number generator from current time

Initializing worker threads...

Threads started!

[ 10s ] thds: 4 tps: 141.64 qps: 2840.01 (r/w/o: 1988.49/567.84/283.67) lat (ms,95%): 55.82 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 4 tps: 150.71 qps: 3013.92 (r/w/o: 2109.76/602.74/301.42) lat (ms,95%): 55.82 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 4 tps: 159.98 qps: 3200.26 (r/w/o: 2239.96/640.33/319.97) lat (ms,95%): 39.65 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 4 tps: 155.02 qps: 3100.31 (r/w/o: 2170.22/620.06/310.03) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 4 tps: 152.60 qps: 3052.01 (r/w/o: 2136.41/610.40/305.20) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 4 tps: 157.87 qps: 3157.39 (r/w/o: 2210.17/631.48/315.74) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 4 tps: 167.03 qps: 3340.58 (r/w/o: 2338.40/668.12/334.06) lat (ms,95%): 33.72 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 4 tps: 160.80 qps: 3216.08 (r/w/o: 2251.26/643.22/321.61) lat (ms,95%): 33.72 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 4 tps: 162.97 qps: 3257.86 (r/w/o: 2281.02/650.89/325.95) lat (ms,95%): 38.25 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 4 tps: 91.91 qps: 1839.89 (r/w/o: 1287.40/368.66/183.83) lat (ms,95%): 155.80 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 4 tps: 117.70 qps: 2350.33 (r/w/o: 1645.02/470.01/235.30) lat (ms,95%): 77.19 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 4 tps: 154.39 qps: 3091.14 (r/w/o: 2164.22/618.05/308.87) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 130s ] thds: 4 tps: 161.51 qps: 3230.06 (r/w/o: 2261.09/645.95/323.03) lat (ms,95%): 38.94 err/s: 0.00 reconn/s: 0.00

[ 140s ] thds: 4 tps: 162.19 qps: 3244.34 (r/w/o: 2270.79/649.17/324.38) lat (ms,95%): 36.89 err/s: 0.00 reconn/s: 0.00

[ 150s ] thds: 4 tps: 160.80 qps: 3216.08 (r/w/o: 2251.26/643.22/321.61) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 160s ] thds: 4 tps: 162.29 qps: 3245.86 (r/w/o: 2272.10/649.17/324.59) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 170s ] thds: 4 tps: 155.61 qps: 3111.31 (r/w/o: 2178.45/621.64/311.22) lat (ms,95%): 44.98 err/s: 0.00 reconn/s: 0.00

[ 180s ] thds: 4 tps: 156.39 qps: 3128.18 (r/w/o: 2189.45/625.96/312.78) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 190s ] thds: 4 tps: 159.80 qps: 3196.43 (r/w/o: 2237.25/639.59/319.59) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 200s ] thds: 4 tps: 154.61 qps: 3087.67 (r/w/o: 2161.22/617.23/309.22) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 210s ] thds: 4 tps: 157.59 qps: 3155.77 (r/w/o: 2209.41/631.17/315.19) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 220s ] thds: 4 tps: 161.51 qps: 3230.82 (r/w/o: 2261.36/646.44/323.02) lat (ms,95%): 38.94 err/s: 0.00 reconn/s: 0.00

[ 230s ] thds: 4 tps: 160.79 qps: 3215.19 (r/w/o: 2251.05/642.56/321.58) lat (ms,95%): 33.72 err/s: 0.00 reconn/s: 0.00

[ 240s ] thds: 4 tps: 159.19 qps: 3184.43 (r/w/o: 2228.68/637.37/318.38) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 250s ] thds: 4 tps: 61.60 qps: 1232.09 (r/w/o: 862.46/246.42/123.21) lat (ms,95%): 253.35 err/s: 0.00 reconn/s: 0.00

[ 260s ] thds: 4 tps: 145.60 qps: 2911.19 (r/w/o: 2038.39/581.60/291.20) lat (ms,95%): 44.98 err/s: 0.00 reconn/s: 0.00

[ 270s ] thds: 4 tps: 157.37 qps: 3148.28 (r/w/o: 2203.24/630.30/314.75) lat (ms,95%): 43.39 err/s: 0.00 reconn/s: 0.00

[ 280s ] thds: 4 tps: 155.93 qps: 3118.62 (r/w/o: 2183.03/623.72/311.86) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 290s ] thds: 4 tps: 155.20 qps: 3102.26 (r/w/o: 2171.87/619.99/310.40) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

[ 300s ] thds: 4 tps: 157.20 qps: 3144.20 (r/w/o: 2201.40/628.40/314.40) lat (ms,95%): 44.17 err/s: 0.00 reconn/s: 0.00

SQL statistics:

    queries performed:

        read:                            632562

        write:                           180732

        other:                           90366

        total:                           903660

    transactions:                        45183  (150.60 per sec.)

    queries:                             903660 (3011.98 per sec.)

    ignored errors:                      0      (0.00 per sec.)

    reconnects:                          0      (0.00 per sec.)

General statistics:

    total time:                          300.0178s

    total number of events:              45183

Latency (ms):

         min:                                   10.65

         avg:                                   26.55

         max:                                 1029.61

         95th percentile:                       44.17

         sum:                              1199831.60

Threads fairness:

    events (avg/stddev):           11295.7500/4.02

    execution time (avg/stddev):   299.9579/0.00

but history list length gets a lot bigger, up to 12000+:

openxs@ao756:~/dbs/maria10.6$ for i in `seq 1 200`; do bin/mysql -B -e "show global status like '%history%'" | grep history ; sleep 1; done

Innodb_history_list_length	1870

Innodb_history_list_length	66

Innodb_history_list_length	220

Innodb_history_list_length	395

Innodb_history_list_length	512

Innodb_history_list_length	690

Innodb_history_list_length	843

Innodb_history_list_length	1011

Innodb_history_list_length	1162

Innodb_history_list_length	1312

Innodb_history_list_length	1482

Innodb_history_list_length	1637

Innodb_history_list_length	1811

Innodb_history_list_length	1991

Innodb_history_list_length	2139

Innodb_history_list_length	2310

Innodb_history_list_length	2488

Innodb_history_list_length	2653

Innodb_history_list_length	2808

Innodb_history_list_length	2987

Innodb_history_list_length	3136

Innodb_history_list_length	3278

Innodb_history_list_length	3442

Innodb_history_list_length	3620

Innodb_history_list_length	3771

Innodb_history_list_length	3927

Innodb_history_list_length	4109

Innodb_history_list_length	4242

Innodb_history_list_length	4336

Innodb_history_list_length	4497

Innodb_history_list_length	4658

Innodb_history_list_length	4807

Innodb_history_list_length	4976

Innodb_history_list_length	5130

Innodb_history_list_length	5312

Innodb_history_list_length	5460

Innodb_history_list_length	5617

Innodb_history_list_length	5797

Innodb_history_list_length	5970

Innodb_history_list_length	6128

Innodb_history_list_length	6284

Innodb_history_list_length	6456

Innodb_history_list_length	6610

Innodb_history_list_length	6760

Innodb_history_list_length	6919

Innodb_history_list_length	7087

Innodb_history_list_length	7244

Innodb_history_list_length	102

Innodb_history_list_length	262

Innodb_history_list_length	443

Innodb_history_list_length	603

Innodb_history_list_length	788

Innodb_history_list_length	951

Innodb_history_list_length	1106

Innodb_history_list_length	1290

Innodb_history_list_length	1473

Innodb_history_list_length	1631

Innodb_history_list_length	1795

Innodb_history_list_length	1965

Innodb_history_list_length	2142

Innodb_history_list_length	2296

Innodb_history_list_length	2453

Innodb_history_list_length	2617

Innodb_history_list_length	2793

Innodb_history_list_length	2965

Innodb_history_list_length	3120

Innodb_history_list_length	3304

Innodb_history_list_length	3451

Innodb_history_list_length	3620

Innodb_history_list_length	3802

Innodb_history_list_length	3975

Innodb_history_list_length	4136

Innodb_history_list_length	4300

Innodb_history_list_length	4448

Innodb_history_list_length	4624

Innodb_history_list_length	4780

Innodb_history_list_length	4956

Innodb_history_list_length	5133

Innodb_history_list_length	5281

Innodb_history_list_length	5445

Innodb_history_list_length	5619

Innodb_history_list_length	5665

Innodb_history_list_length	5695

Innodb_history_list_length	5739

Innodb_history_list_length	5873

Innodb_history_list_length	5902

Innodb_history_list_length	5929

Innodb_history_list_length	5943

Innodb_history_list_length	6033

Innodb_history_list_length	6053

Innodb_history_list_length	6178

Innodb_history_list_length	6342

Innodb_history_list_length	6506

Innodb_history_list_length	6649

Innodb_history_list_length	6809

Innodb_history_list_length	6965

Innodb_history_list_length	7136

Innodb_history_list_length	7318

Innodb_history_list_length	7428

Innodb_history_list_length	7600

Innodb_history_list_length	7774

Innodb_history_list_length	7909

Innodb_history_list_length	8090

Innodb_history_list_length	8249

Innodb_history_list_length	8407

Innodb_history_list_length	8548

Innodb_history_list_length	8720

Innodb_history_list_length	8879

Innodb_history_list_length	9038

Innodb_history_list_length	9213

Innodb_history_list_length	9387

Innodb_history_list_length	9540

Innodb_history_list_length	9721

Innodb_history_list_length	9899

Innodb_history_list_length	10056

Innodb_history_list_length	10215

Innodb_history_list_length	10356

Innodb_history_list_length	10519

Innodb_history_list_length	10703

Innodb_history_list_length	10866

Innodb_history_list_length	11045

Innodb_history_list_length	11222

Innodb_history_list_length	11376

Innodb_history_list_length	11549

Innodb_history_list_length	11704

Innodb_history_list_length	11870

Innodb_history_list_length	12035

Innodb_history_list_length	12191

Innodb_history_list_length	12373

Innodb_history_list_length	12553

Innodb_history_list_length	45

Innodb_history_list_length	200

Innodb_history_list_length	381

Innodb_history_list_length	522

Innodb_history_list_length	684

Innodb_history_list_length	866

Innodb_history_list_length	1033

Innodb_history_list_length	1181

Innodb_history_list_length	1361

Innodb_history_list_length	1543

Innodb_history_list_length	1684

Innodb_history_list_length	1867

Innodb_history_list_length	2049

Innodb_history_list_length	2186

Innodb_history_list_length	2352

Innodb_history_list_length	2527

Innodb_history_list_length	2663

Innodb_history_list_length	2823

Innodb_history_list_length	3007

Innodb_history_list_length	3157

Innodb_history_list_length	3292

Innodb_history_list_length	3474

Innodb_history_list_length	3623

Innodb_history_list_length	3781

Innodb_history_list_length	3957

Innodb_history_list_length	4093

Innodb_history_list_length	4270

Innodb_history_list_length	4452

Innodb_history_list_length	4600

Innodb_history_list_length	4777

Innodb_history_list_length	4937

Innodb_history_list_length	5082

Innodb_history_list_length	5264

Innodb_history_list_length	5425

Innodb_history_list_length	5559

Innodb_history_list_length	5735

Innodb_history_list_length	5912

Innodb_history_list_length	6058

Innodb_history_list_length	6240

Innodb_history_list_length	6406

Innodb_history_list_length	6526

Innodb_history_list_length	6709

Innodb_history_list_length	6875

Innodb_history_list_length	7018

Innodb_history_list_length	7203

Innodb_history_list_length	7366

Innodb_history_list_length	7511

Innodb_history_list_length	7694

Innodb_history_list_length	7868

Innodb_history_list_length	8011

Innodb_history_list_length	68

Innodb_history_list_length	225

Innodb_history_list_length	381

Innodb_history_list_length	547

Innodb_history_list_length	710

Innodb_history_list_length	851

Innodb_history_list_length	1027

Innodb_history_list_length	1195

Innodb_history_list_length	1347

Innodb_history_list_length	1504

Innodb_history_list_length	1671

Innodb_history_list_length	1814

Innodb_history_list_length	1987

Innodb_history_list_length	2169

Innodb_history_list_length	2316

Innodb_history_list_length	2481

Innodb_history_list_length	2666

Innodb_history_list_length	2815

Innodb_history_list_length	2985

Innodb_history_list_length	3140

openxs@ao756:~/dbs/maria10.6$

But unlike with macOS and SSD, the value is fluctuating a lot in the process.

Comment by Marko Mäkelä [ 2022-09-16 ]

While debugging the initial mtr based test case of ~~MDEV-23801~~, I noticed that multiple purge worker tasks would execute on the same 2 index leaf pages. This kind of scheduling is leading to unnecessary conflicts. The purge work queue should be arranged differently, so that only one task at a time would operate on a particular index tree.

Comment by Marko Mäkelä [ 2022-10-17 ]

While debugging something found out by ~~MDEV-24402~~, I noticed that trx_purge_add_undo_to_history() will be invoked even when trx_t->undo_no==0, that is, no undo log records need to be purged. Optimizing that could improve performance for workloads that include ROLLBACK, either explicitly or implicitly via deadlocks.

Comment by Daniel Black [ 2022-11-15 ]

I'm hoping this is comparable/useful:

10.6 client
Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 4
Server version: 10.6.12-MariaDB MariaDB Server

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> use test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
MariaDB [test]> drop table t2;
Query OK, 0 rows affected (0.027 sec)

MariaDB [test]> create table t2 like t1;
Query OK, 0 rows affected (0.000 sec)

MariaDB [test]> insert into t2 select * from t1; shutdown;
Query OK, 10000000 rows affected (15.029 sec)
Records: 10000000 Duplicates: 0 Warnings: 0

Query OK, 0 rows affected (0.000 sec)

MariaDB [test]> ^DBye

~/repos/build-mariadb-server-10.6
$ while [ ! -S /tmp/${PWD##/}.sock ] ; do sleep 0.001; done; client/mysql -S /tmp/${PWD##/}.sock -e 'show global status like "%history%"';
+----------------------------+-------+
\| Variable_name \| Value \|
+----------------------------+-------+
\| Innodb_history_list_length \| 18 \|
+----------------------------+-------+

10.6-505da21e336f1e46b655f78fc0ad42e6cf17494d server
$ sql/mysqld --no-defaults --datadir=/tmp/${PWD##/}-datadir --socket=/tmp/${PWD##/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose --skip-networking --innodb-buffer-pool-load-at-startup=0
2022-11-15 19:36:38 0 [Note] sql/mysqld (server 10.6.12-MariaDB) starting as process 260244 ...
2022-11-15 19:36:38 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-11-15 19:36:38 0 [Note] InnoDB: Number of pools: 1
2022-11-15 19:36:38 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-11-15 19:36:39 0 [Note] InnoDB: Using liburing
2022-11-15 19:36:39 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-11-15 19:36:39 0 [Note] InnoDB: Completed initialization of buffer pool
2022-11-15 19:36:39 0 [Note] InnoDB: Setting O_DIRECT on file ./ibdata1 failed
2022-11-15 19:36:39 0 [Note] InnoDB: 128 rollback segments are active.
2022-11-15 19:36:39 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-11-15 19:36:39 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-11-15 19:36:39 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-11-15 19:36:39 0 [Note] InnoDB: 10.6.12 started; log sequence number 4395171835; transaction id 122
2022-11-15 19:36:39 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021
2022-11-15 19:36:39 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-11-15 19:36:39 0 [Note] sql/mysqld: ready for connections.
Version: '10.6.12-MariaDB' socket: '/tmp/build-mariadb-server-10.6.sock' port: 0 MariaDB Server

10.5 client
Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 3
Server version: 10.5.19-MariaDB-1:10.5.13+maria~stretch mariadb.org binary distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> use test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
MariaDB [test]> drop table t2;
Query OK, 0 rows affected (0.032 sec)

MariaDB [test]> create table t2 like t1;
Query OK, 0 rows affected (0.003 sec)

MariaDB [test]> insert into t2 select * from t1; shutdown;
Query OK, 10000000 rows affected (44.306 sec)
Records: 10000000 Duplicates: 0 Warnings: 0

Query OK, 0 rows affected (0.000 sec)

MariaDB [test]> ^DBye

~/repos/build-mariadb-server-10.5
$ while [ ! -S /tmp/${PWD##/}.sock ] ; do sleep 0.001; done; client/mysql -S /tmp/${PWD##/}.sock -e 'show global status like "%history%"';
+----------------------------+-------+
\| Variable_name \| Value \|
+----------------------------+-------+
\| Innodb_history_list_length \| 15 \|
+----------------------------+-------+

10.5-dc2741be52913f12f17e04341f17c51875aa5065
$ sql/mysqld --no-defaults --datadir=/tmp/${PWD##/}-datadir --socket=/tmp/${PWD##/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose --skip-networking --innodb-buffer-pool-load-at-startup=0
2022-11-15 19:43:53 0 [Note] sql/mysqld (mysqld 10.5.19-MariaDB-1:10.5.13+maria~stretch) starting as process 270698 ...
2022-11-15 19:43:53 0 [Note] InnoDB: Uses event mutexes
2022-11-15 19:43:53 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-11-15 19:43:53 0 [Note] InnoDB: Number of pools: 1
2022-11-15 19:43:53 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-11-15 19:43:53 0 [Note] InnoDB: Using Linux native AIO
2022-11-15 19:43:53 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-11-15 19:43:53 0 [Note] InnoDB: Completed initialization of buffer pool
2022-11-15 19:43:53 0 [Note] InnoDB: 128 rollback segments are active.
2022-11-15 19:43:53 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-11-15 19:43:53 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-11-15 19:43:53 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-11-15 19:43:53 0 [Note] InnoDB: 10.5.19 started; log sequence number 4035807586; transaction id 175
2022-11-15 19:43:53 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-11-15 19:43:53 0 [Note] Reading of all Master_info entries succeeded
2022-11-15 19:43:53 0 [Note] Added new Master_info '' to hash table
2022-11-15 19:43:53 0 [Note] sql/mysqld: ready for connections.
Version: '10.5.19-MariaDB-1:10.5.13+maria~stretch' socket: '/tmp/build-mariadb-server-10.5.sock' port: 0 mariadb.org binary distribution

Comment by Marko Mäkelä [ 2022-12-12 ]

I am unable to reproduce the problem on my system. The performance of the purge of committed transaction history is rather chaotic. There are no big differences in that subsystem between 10.5 and 10.6. Already in 10.5, ~~MDEV-16678~~ made the purge always acquire metadata locks (MDL).

It is possible that this was already improved in MariaDB Server 10.6.11 by ~~MDEV-24402~~ and some related changes. There also is some rather low-hanging fruit in ~~MDEV-29593~~ that might improve the performance.

Comment by Marko Mäkelä [ 2022-12-15 ]

Based on some testing that axel conducted for ~~MDEV-29986~~ and some other changes, it seems that ~~MDEV-26356~~ might be to blame, after all. The purge of history is being scaled down when the log checkpoint age grows too old, but the page flushing efforts will not be increased based on the size of the purge queue (history list length). After some 2,000 seconds of a TPC-C benchmark, the throughput would drop and become very erratic.

Comment by Marko Mäkelä [ 2023-03-29 ]

Some testing that was conducted in MDEV-30628 shows that the growth of the history list can be a significant problem. It also shows that simply removing the throttling that was added in ~~MDEV-26356~~ is not a solution, because it could make the throughput unpredictable.

Whether or not the growth of the history list in 10.6 is faster than in earlier versions, we definitely must do something about it.

Comment by Marko Mäkelä [ 2023-04-26 ]

I think that I can sufficiently reproduce this with Sysbench oltp_write_only with 256 concurrent connections, 5×1M rows, 10G buffer pool, 4G log on RAM disk. The slow shutdown after the 60-second run reports the following:

2023-04-26 17:08:01 0 [Note] InnoDB: to purge 3703272 transactions

Comment by Marko Mäkelä [ 2023-04-26 ]

It looks like in this test, the history list length increases linearly with the test run time, and it is not very strongly correlated with the number of rows in the table. I got this (okay, a little below 25% of the previous number) for 25% of the time (15 seconds), at only 5×5000 rows:

2023-04-26 17:21:50 0 [Note] InnoDB: to purge 755013 transactions

Roughly the same result after 15 seconds with 5×1000 rows in a 100M log and buffer pool:

2023-04-26 17:26:43 0 [Note] InnoDB: to purge 559389 transactions

After a 5-second run:

2023-04-26 17:29:24 0 [Note] InnoDB: to purge 166864 transactions

This should allow me to rather quickly do a sanity check of any fixes that I can come up with.

Comment by Marko Mäkelä [ 2023-04-27 ]

I thought that PERFORMANCE_SCHEMA might be helpful.

10.8 c15c8ef3e357a3e01f775f20027fdac9b227099f
+-----------------------------------------------+------------+---------+-----------------+----------------+----------------+----------------+
\| EVENT_NAME \| COUNT_STAR \| SECONDS \| SUM_TIMER_WAIT \| MIN_TIMER_WAIT \| AVG_TIMER_WAIT \| MAX_TIMER_WAIT \|
+-----------------------------------------------+------------+---------+-----------------+----------------+----------------+----------------+
\| wait/synch/rwlock/innodb/lock_latch \| 6215175 \| 856.25 \| 856253658812592 \| 5472 \| 137768088 \| 6107062992 \|
\| wait/synch/rwlock/innodb/fil_space_latch \| 1638841 \| 20.10 \| 20099925032040 \| 5472 \| 12264576 \| 32502004656 \|
\| wait/synch/rwlock/sql/MDL_lock::rwlock \| 8054602 \| 15.89 \| 15886522442736 \| 18240 \| 1972200 \| 4513335240 \|
\| wait/synch/mutex/sql/LOCK_table_cache \| 4629542 \| 6.19 \| 6187032736176 \| 24624 \| 1336080 \| 1455395136 \|
\| wait/synch/mutex/innodb/lock_wait_mutex \| 1357429 \| 5.38 \| 5377233425184 \| 24624 \| 3961272 \| 2982393216 \|
\| wait/synch/rwlock/innodb/trx_rseg_latch \| 1125776 \| 4.31 \| 4310187636720 \| 5472 \| 3828576 \| 47491649880 \|
\| wait/synch/mutex/sql/THD::LOCK_thd_data \| 23092489 \| 1.91 \| 1908951926304 \| 16416 \| 82536 \| 342531240 \|
\| wait/synch/rwlock/innodb/dict_operation_lock \| 2218764 \| 0.84 \| 839945463696 \| 5472 \| 378480 \| 7108733112 \|
\| wait/synch/mutex/aria/THR_LOCK_maria \| 116 \| 0.65 \| 652158193512 \| 190608 \| 5622053184 \| 16744253424 \|
\| wait/synch/mutex/innodb/buf_pool_mutex \| 195558 \| 0.59 \| 585145133472 \| 16416 \| 2991816 \| 6540518808 \|
\| wait/synch/rwlock/innodb/log_latch \| 6926126 \| 0.50 \| 498791758200 \| 5472 \| 71592 \| 434032200 \|
\| wait/synch/mutex/innodb/trx_pool_mutex \| 552 \| 0.36 \| 357256405680 \| 29184 \| 647203536 \| 10980590352 \|
\| wait/synch/mutex/sql/THD::LOCK_thd_kill \| 2142689 \| 0.21 \| 211259893440 \| 16416 \| 98496 \| 373227792 \|
\| wait/synch/mutex/innodb/flush_list_mutex \| 229240 \| 0.17 \| 167271419784 \| 16416 \| 729600 \| 1020442272 \|
\| wait/synch/mutex/innodb/buf_dblwr_mutex \| 29905 \| 0.04 \| 41573924928 \| 16416 \| 1389888 \| 1297701216 \|
\| wait/synch/mutex/innodb/tpool_cache_mutex \| 82878 \| 0.02 \| 15246482664 \| 24624 \| 183768 \| 233236704 \|
\| wait/synch/mutex/sql/LOCK_prepared_stmt_count \| 11264 \| 0.01 \| 14544364872 \| 24624 \| 1290936 \| 667165392 \|
\| wait/synch/mutex/innodb/fil_system_mutex \| 51087 \| 0.01 \| 8197669320 \| 16416 \| 160056 \| 148043592 \|
\| wait/synch/rwlock/innodb/trx_purge_latch \| 140106 \| 0.01 \| 5099942760 \| 5472 \| 36024 \| 50621472 \|
\| wait/synch/mutex/innodb/recalc_pool_mutex \| 21818 \| 0.00 \| 4960299600 \| 30096 \| 227088 \| 458380776 \|
+-----------------------------------------------+------------+---------+-----------------+----------------+----------------+----------------+

By far, the most contended latch is lock_sys.latch. It will also be waited by for purge when handling gap locks. This run was with the default innodb_purge_threads=4. With the maximum innodb_purge_threads=32 (and the performance schema enabled) the purge performed a little better:

10.8 c15c8ef3e357a3e01f775f20027fdac9b227099f
2023-04-27 9:26:06 0 [Note] InnoDB: to purge 478370 transactions

With the default innodb_purge_threads=4:

10.8 c15c8ef3e357a3e01f775f20027fdac9b227099f
2023-04-27 9:27:23 0 [Note] InnoDB: to purge 532759 transactions

Comment by Marko Mäkelä [ 2023-04-27 ]

Specifying any nonzero innodb_max_purge_lag while not also specifying nonzero innodb_max_purge_lag_delay will have no impact on the throughput or the history list length at the end of the test.

A test with innodb_max_purge_lag=1000 and innodb_max_purge_lag_delay=1000000 was effective: only 7 transactions to purge at the end of the test. Another 15-second test with innodb_max_purge_lag_delay=10000 failed to uphold the limit: 3,224 transactions waited for purging at the end. Both runs were with the following patch:

diff --git a/storage/innobase/row/row0mysql.cc b/storage/innobase/row/row0mysql.cc

index d27fc964219..daca5a8a178 100644

--- a/storage/innobase/row/row0mysql.cc

+++ b/storage/innobase/row/row0mysql.cc

@@ -75,6 +75,7 @@ row_mysql_delay_if_needed(void)

 /*===========================*/

 	if (srv_dml_needed_delay) {

+		srv_wake_purge_thread_if_not_active();

 		std::this_thread::sleep_for(

 			std::chrono::microseconds(srv_dml_needed_delay));

Without this patch, the history list would grow even more.

Comment by Marko Mäkelä [ 2023-04-27 ]

I submitted a patch and tested a merge of it to 10.8.

For me, the parameter innodb_max_purge_lag_delay=5000 (5ms) seems to work well. Initially I tested 10ms, but I thought that it could be too excessive to delay each inserted, updated, or deleted row by this amount.

I tested innodb_max_purge_lag_delay=5000 with a few values of innodb_max_purge_lag: 100000, 500000, 10000. Each time, the innodb_fast_shutdown=0 shutdown after my 120-second 256-thread oltp_write_only test would report a number of transactions similar to my specified innodb_max_purge_lag.

    queries:                             20181442 (168082.34 per sec.)

2023-04-27 15:47:53 0 [Note] InnoDB: to purge 100254 transactions

    queries:                             21350311 (177826.20 per sec.)

2023-04-27 15:54:02 0 [Note] InnoDB: to purge 487072 transactions

    queries:                             19562304 (162922.14 per sec.)

2023-04-27 15:57:45 0 [Note] InnoDB: to purge 27340 transactions

You can see that the throughput will be limited by the DML throttling. The unthrottled performance for this workload was over 220 thousand queries per second. For the last run, the target limit of 10k transactions was exceeded.

What a reasonable history list length limit might be depends on the workload as well as on the size of the transactions (number of rows modified or inserted). My intuition says that 1 million transactions is much.

Comment by Thirunarayanan Balathandayuthapani [ 2023-04-27 ]

Patch looks OK to me

Comment by Marko Mäkelä [ 2023-04-27 ]

I tested the patch on 10.6 as well. The log_sys.mutex should be more contended compared to the 10.8 log_sys.latch (~~MDEV-27774~~).

    queries:                             21304322 (177438.22 per sec.)

2023-04-27 16:16:49 0 [Note] InnoDB: to purge 1875 transactions

    queries:                             20588467 (171478.40 per sec.)

2023-04-27 16:19:22 0 [Note] InnoDB: to purge 67764 transactions

    queries:                             21584752 (179779.74 per sec.)

2023-04-27 16:21:44 0 [Note] InnoDB: to purge 487757 transactions

Somewhat surprisingly, the throughput was a little better than on 10.8, and the history list length limit was enforced better. Of course, we can’t draw too many conclusions from a RAM disk based microbenchmark that was only run once for each combination.

Comment by Marko Mäkelä [ 2023-04-27 ]

This is not an actual fix, but an improvement of an existing work-around. With this improvement, the combination of innodb_max_purge_lag (the desired maximum number of committed transactions waiting for purge) and innodb_max_purge_lag_delay (maximum delay per DML row operation, in microseconds) should work more reasonably: DML threads will only be delayed if purge can actually proceed (there exist no old read views or transactions that would block progress), and the purge coordinator task will not be suspended as long as the throttling of DML operations is active.

One more possible explanation for this regression is that ~~MDEV-24854~~ changed the parameter innodb_flush_method=O_DIRECT by default. As noted in ~~MDEV-30986~~, with the pre-10.6 default of innodb_flush_method=fsync, InnoDB could make use of the file system cache of the operating system.

Comment by Axel Schwenke [ 2023-04-27 ]

Setting innodb_max_purge_lag_delay is critical. Larger values tend to decrease throughput too much, smaller values let the history list grow. I found a value of 5000 (meaning 5000µs = 5ms delay per DML statement) a good compromise. Throughput still drops to half of that without the brake, but then also the history list will grow indefinitely.

Result: write-only2.pdf

Comment by Axel Schwenke [ 2023-04-28 ]

Adding data for a 5-hour run on TPC-C (sysbench-tpcc). Settings again innodb_max_purge_lag = 500000 and innodb_max_purge_lag_delay = 5000. We see the throttle kick in ~4000 seconds. From there on the numbers are quite stable. The comparison run (this commit has adaptive flushing fixed) has history list growing starting ~8000 second.

Attached: tpcc2.pdf

Comment by Marko Mäkelä [ 2023-08-04 ]

While analyzing ~~MDEV-30100~~, I observed that MariaDB (probably starting with ~~MDEV-12288~~ in 10.3) is unnecessarily adding the undo log of rolled-back transactions to the purge queue, instead of freeing the space directly.

While Sysbench workloads do not typically cause any rollback, this could matter in real-world workloads.

Comment by Marko Mäkelä [ 2023-10-26 ]

~~MDEV-32050~~ removes several points of contention from the purge subsystem and reverts the throttling mechanism that had been introduced in ~~MDEV-26356~~. It also increases the default value of innodb_purge_batch_size in order to reduce the relative time spent on starting and stopping purge worker tasks. That fix should make redundant the throttling mechanism that was revised in this task. Better just configure a larger number of innodb_purge_threads (default: 4, maximum: 32) in case the history list length remains an issue.

Generated at Thu Feb 08 10:08:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.

[MDEV-29401] InnoDB history list length increased in 10.6 compared to 10.5 for the same load Created: 2022-08-27 Updated: 2024-01-02 Resolved: 2023-04-27