[MDEV-31234] InnoDB does not free UNDO after the fix of MDEV-30671, thus shared tablespace (ibdata1) may grow indefinitely for no good reason Created: 2023-05-10  Updated: 2023-09-14  Resolved: 2023-05-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.11.1, 10.5.20, 10.6.13, 10.8.7, 10.9.6, 10.10.3
Fix Version/s: 11.1.1, 11.0.2, 10.5.21, 10.6.14, 10.9.7, 10.10.5, 10.11.4

Type: Bug Priority: Blocker
Reporter: Valerii Kravchuk Assignee: Matthias Leich
Resolution: Fixed Votes: 5
Labels: regression

Attachments: File sbtest-rr.tar.xz    
Issue Links:
Blocks
PartOf
is part of MDEV-31376 prepare Q2.1 release (10.5–11.1) Closed
Problem/Incident
is caused by MDEV-30671 innodb_undo_log_truncate=ON fails to ... Closed
Relates
relates to MDEV-22718 InnoDB: purge_sys.low_limit_no() is n... Stalled
relates to MDEV-31253 Freed data pages are not always being... Closed
relates to MDEV-31343 Another server hang with innodb_undo_... Closed
relates to MDEV-31355 innodb_undo_log_truncate=ON fails to ... Closed
relates to MDEV-31382 SET GLOBAL innodb_undo_log_truncate=O... Closed
relates to MDEV-31389 ibdata1 grows when .idb files are mov... Closed

 Description   

Consider sysbench-based oltp_read_write test similar to those used in MDEV-29401. Looks like 10.6 is not able to free UNDO it in time or at all for the same load.

I ran the following on 10.6.13 built from recent GitHub source:

Yuliyas-Air:~ Valerii$ cd dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ rm -rf data/
Yuliyas-Air:maria10.6 Valerii$ scripts/mysql_install_db --no-defaults
Installing MariaDB/MySQL system tables in './data' ...
2023-05-10 16:14:22 0 [Warning] InnoDB: innodb_open_files 300 should not be greater than the open_files_limit 256
OK
 
To start mariadbd at boot time you have to copy
support-files/mariadb.service to the right place for your system
 
 
Two all-privilege accounts were created.
One is root@localhost, it has no password, but you need to
be system 'root' user to connect. Use, for example, sudo mysql
The second is Valerii@localhost, it has no password either, but
you need to be the system 'Valerii' user to connect.
After connecting you can set the password, if you would need to be
able to connect as any of these users with a password and without sudo
 
See the MariaDB Knowledgebase at https://mariadb.com/kb
 
You can start the MariaDB daemon with:
cd '.' ; ./bin/mariadb-safe --datadir='./data'
 
You can test the MariaDB daemon with mysql-test-run.pl
cd './mysql-test' ; perl mariadb-test-run.pl
 
Please report any problems at https://mariadb.org/jira
 
The latest information about MariaDB is available at https://mariadb.org/.
 
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/
 
Yuliyas-Air:maria10.6 Valerii$ bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M &
[1] 76002
Yuliyas-Air:maria10.6 Valerii$ 230510 16:16:09 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.
230510 16:16:09 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data
 
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'create database sbtest';
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  12582912 10 May 16:14 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-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 --report_interval=10 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest4'...Creating table 'sbtest3'...Creating table 'sbtest2'...
Creating table 'sbtest1'...
 
 
Inserting 100000 records into 'sbtest1'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest4'
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest3'...
Yuliyas-Air:sysbench Valerii$ ls -l data/ibdata1 
ls: data/ibdata1: No such file or directory
Yuliyas-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 --report_interval=10 --time=100 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: 1116.06 qps: 22325.01 (r/w/o: 15628.28/4464.22/2232.51) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 1145.58 qps: 22911.35 (r/w/o: 16037.86/4582.33/2291.17) lat (ms,95%): 4.65 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 1102.88 qps: 22057.62 (r/w/o: 15440.36/4411.50/2205.75) lat (ms,95%): 5.47 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 1041.18 qps: 20826.21 (r/w/o: 14578.43/4165.42/2082.36) lat (ms,95%): 6.09 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 867.21 qps: 17340.72 (r/w/o: 12138.15/3468.14/1734.42) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 1019.78 qps: 20394.57 (r/w/o: 14275.87/4079.13/2039.57) lat (ms,95%): 6.21 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 1159.62 qps: 23195.84 (r/w/o: 16238.01/4638.59/2319.24) lat (ms,95%): 4.74 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 1124.21 qps: 22484.66 (r/w/o: 15739.21/4497.03/2248.42) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 1117.99 qps: 22359.21 (r/w/o: 15651.57/4471.66/2235.98) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1519084
        write:                           434024
        other:                           217012
        total:                           2170120
    transactions:                        108506 (1085.01 per sec.)
    queries:                             2170120 (21700.25 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      1085.0124
    time elapsed:                        100.0044s
    total number of events:              108506
 
Latency (ms):
         min:                                    1.77
         avg:                                    3.68
         max:                                  103.45
         95th percentile:                        5.57
         sum:                               399636.30
 
Threads fairness:
    events (avg/stddev):           27126.5000/11.08
    execution time (avg/stddev):   99.9091/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  79691776 10 May 16:20 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 14009 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     101	Index page
    3050	Undo log page
      38	Inode page
       0	Insert buffer free list page
    1504	Freshly allocated page
       1	Insert buffer bitmap
     168	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 3050
Undo page state: 0 active, 0 cached, 3050 to_purge, 0 prepared, 0 other
...

Note 3050 pages of UNDO, all "to_purge". The same test on 10.5 gives the following:

Yuliyas-Air:maria10.5 Valerii$ rm -rf data/
 
Yuliyas-Air:maria10.5 Valerii$ 
Yuliyas-Air:maria10.5 Valerii$ scripts/mysql_install_db --no-defaults
Installing MariaDB/MySQL system tables in './data' ...
2023-05-10 16:22:15 0 [Warning] InnoDB: innodb_open_files 300 should not be greater than the open_files_limit 256
OK
 
To start mariadbd at boot time you have to copy
support-files/mariadb.service to the right place for your system
 
 
Two all-privilege accounts were created.
One is root@localhost, it has no password, but you need to
be system 'root' user to connect. Use, for example, sudo mysql
The second is Valerii@localhost, it has no password either, but
you need to be the system 'Valerii' user to connect.
After connecting you can set the password, if you would need to be
able to connect as any of these users with a password and without sudo
 
See the MariaDB Knowledgebase at https://mariadb.com/kb
 
You can start the MariaDB daemon with:
cd '.' ; ./bin/mariadb-safe --datadir='./data'
 
You can test the MariaDB daemon with mysql-test-run.pl
cd './mysql-test' ; perl mariadb-test-run.pl
 
Please report any problems at https://mariadb.org/jira
 
The latest information about MariaDB is available at https://mariadb.org/.
 
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/
 
Yuliyas-Air:maria10.5 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  12582912 10 May 16:22 data/ibdata1
Yuliyas-Air:maria10.5 Valerii$ bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M &
[1] 76269
Yuliyas-Air:maria10.5 Valerii$ 230510 16:22:51 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.5/data/Yuliyas-Air.err'.
230510 16:22:51 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.5/data
 
Yuliyas-Air:maria10.5 Valerii$ bin/mysql -e 'create database sbtest';
Yuliyas-Air:maria10.5 Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-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 --report_interval=10 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest1'...Creating table 'sbtest4'...Creating table 'sbtest2'...
 
 
Creating table 'sbtest3'...
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest1'
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest1'...
Yuliyas-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 --report_interval=10 --time=100 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: 930.13 qps: 18608.20 (r/w/o: 13026.62/3720.92/1860.66) lat (ms,95%): 5.67 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 980.93 qps: 19618.58 (r/w/o: 13733.01/3923.72/1961.86) lat (ms,95%): 5.28 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 939.24 qps: 18786.84 (r/w/o: 13150.19/3758.17/1878.48) lat (ms,95%): 5.88 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 902.83 qps: 18054.89 (r/w/o: 12638.68/3610.54/1805.67) lat (ms,95%): 6.91 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 896.09 qps: 17920.59 (r/w/o: 12544.62/3583.78/1792.19) lat (ms,95%): 6.79 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 974.70 qps: 19494.90 (r/w/o: 13646.93/3898.58/1949.39) lat (ms,95%): 5.28 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 955.04 qps: 19098.98 (r/w/o: 13368.72/3820.18/1910.09) lat (ms,95%): 5.57 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 973.13 qps: 19461.73 (r/w/o: 13622.94/3892.53/1946.26) lat (ms,95%): 5.28 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 975.06 qps: 19502.48 (r/w/o: 13652.10/3900.26/1950.13) lat (ms,95%): 5.47 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 914.84 qps: 18297.92 (r/w/o: 12808.48/3659.86/1829.58) lat (ms,95%): 6.21 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1321978
        write:                           377708
        other:                           188854
        total:                           1888540
    transactions:                        94427  (944.21 per sec.)
    queries:                             1888540 (18884.22 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      944.2111
    time elapsed:                        100.0062s
    total number of events:              94427
 
Latency (ms):
         min:                                    1.94
         avg:                                    4.23
         max:                                   98.29
         95th percentile:                        5.88
         sum:                               399536.68
 
Threads fairness:
    events (avg/stddev):           23606.7500/79.99
    execution time (avg/stddev):   99.8842/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ cd ../maria10.5
Yuliyas-Air:maria10.5 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  79691776 10 May 16:25 data/ibdata1
Yuliyas-Air:maria10.5 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     141	Index page
     383	Undo log page
       6	Inode page
       0	Insert buffer free list page
    4201	Freshly allocated page
       1	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 383
Undo page state: 5 active, 378 cached, 0 to_purge, 0 prepared, 0 other
...

Note 0 "to_purge" and just 383 reported ("cached"), wiht the same ibdata1 size.

Now if we repeat the test on 10.6 again we see ibdata1 increased further and number of UNDO pages increased:

Yuliyas-Air:maria10.6 Valerii$ bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M &
[1] 76809
Yuliyas-Air:maria10.6 Valerii$ 230510 16:41:42 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.
230510 16:41:42 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data
 
Yuliyas-Air:maria10.6 Valerii$ ./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --report_interval=10 --time=100 cleanup
-bash: ./src/sysbench: No such file or directory
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 cleanup
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Dropping table 'sbtest1'...
Dropping table 'sbtest2'...
Dropping table 'sbtest3'...
Dropping table 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest1'...Creating table 'sbtest2'...Creating table 'sbtest3'...
 
 
Creating table 'sbtest4'...
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest1'
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 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: 1089.98 qps: 21805.61 (r/w/o: 15265.03/4360.22/2180.36) lat (ms,95%): 5.28 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 1159.46 qps: 23188.84 (r/w/o: 16232.40/4637.53/2318.91) lat (ms,95%): 4.65 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 1146.60 qps: 22929.39 (r/w/o: 16049.79/4586.40/2293.20) lat (ms,95%): 5.00 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 1164.29 qps: 23290.07 (r/w/o: 16303.01/4658.47/2328.59) lat (ms,95%): 4.82 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 1114.27 qps: 22281.81 (r/w/o: 15597.58/4455.78/2228.44) lat (ms,95%): 5.18 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 1143.25 qps: 22867.82 (r/w/o: 16007.31/4573.90/2286.60) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 1177.78 qps: 23553.43 (r/w/o: 16487.64/4710.23/2355.56) lat (ms,95%): 4.65 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 1119.55 qps: 22391.45 (r/w/o: 15674.17/4478.19/2239.10) lat (ms,95%): 5.00 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 1133.05 qps: 22657.43 (r/w/o: 15859.15/4532.19/2266.09) lat (ms,95%): 4.91 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 1134.62 qps: 22697.08 (r/w/o: 15889.03/4538.80/2269.25) lat (ms,95%): 4.74 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1593704
        write:                           455344
        other:                           227672
        total:                           2276720
    transactions:                        113836 (1138.30 per sec.)
    queries:                             2276720 (22765.98 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      1138.2991
    time elapsed:                        100.0054s
    total number of events:              113836
 
Latency (ms):
         min:                                    1.78
         avg:                                    3.51
         max:                                  189.23
         95th percentile:                        4.91
         sum:                               399628.71
 
Threads fairness:
    events (avg/stddev):           28459.0000/51.09
    execution time (avg/stddev):   99.9072/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  146800640 10 May 16:44 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     132	Index page
    7414	Undo log page
      91	Inode page
       0	Insert buffer free list page
    1185	Freshly allocated page
       3	Insert buffer bitmap
     130	System page
       1	Transaction system page
       4	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 7414
Undo page state: 0 active, 0 cached, 7378 to_purge, 0 prepared, 36 other
...

and even if we wait for long enugh time for History list length to get back to 0, still UNDO is not freed:

Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     132	Index page
    7414	Undo log page
      91	Inode page
       0	Insert buffer free list page
    1185	Freshly allocated page
       3	Insert buffer bitmap
     130	System page
       1	Transaction system page
       4	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 7414
Undo page state: 0 active, 0 cached, 7378 to_purge, 0 prepared, 36 other
...

unlike on 10.5, where we end up with the same ibdata1 size and just a little more undo cached after a second run:

Yuliyas-Air:maria10.5 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  79691776 10 May 16:51 data/ibdata1
Yuliyas-Air:maria10.5 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     141	Index page
     519	Undo log page
       7	Inode page
       0	Insert buffer free list page
    4064	Freshly allocated page
       1	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 519
Undo page state: 5 active, 493 cached, 9 to_purge, 0 prepared, 12 other
...



 Comments   
Comment by Valerii Kravchuk [ 2023-05-10 ]

Same story with 10.6.14 as of today:

Yuliyas-Air:server Valerii$ git log -1
commit afe44ef2126d74c11407266cf7d0225ac0392e61 (HEAD -> 10.6, origin/bb-10.6-bumpversion, origin/10.6)
Author: Daniel Bartholomew <db@dbart.us>
Date:   Wed May 10 08:45:08 2023 -0400
 
    bump the VERSION

with tuning suggested in the (fixed) MDEV-29401 applied:

Yuliyas-Air:~ Valerii$ cd dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ rm -rf data/
Yuliyas-Air:maria10.6 Valerii$ scripts/mysql_install_db --no-defaults
Installing MariaDB/MySQL system tables in './data' ...
2023-05-10 18:25:00 0 [Warning] InnoDB: innodb_open_files 300 should not be greater than the open_files_limit 256
 
OK
 
To start mariadbd at boot time you have to copy
support-files/mariadb.service to the right place for your system
 
 
Two all-privilege accounts were created.
One is root@localhost, it has no password, but you need to
be system 'root' user to connect. Use, for example, sudo mysql
The second is Valerii@localhost, it has no password either, but
you need to be the system 'Valerii' user to connect.
After connecting you can set the password, if you would need to be
able to connect as any of these users with a password and without sudo
 
See the MariaDB Knowledgebase at https://mariadb.com/kb
 
You can start the MariaDB daemon with:
cd '.' ; ./bin/mariadb-safe --datadir='./data'
 
You can test the MariaDB daemon with mysql-test-run.pl
cd './mysql-test' ; perl mariadb-test-run.pl
 
Please report any problems at https://mariadb.org/jira
 
The latest information about MariaDB is available at https://mariadb.org/.
 
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/
 
Yuliyas-Air:maria10.6 Valerii$ 
Yuliyas-Air:maria10.6 Valerii$ bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M &
[1] 3387
Yuliyas-Air:maria10.6 Valerii$ 230510 18:25:23 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.
230510 18:25:23 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data
 
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'select version()'
+-----------------+
| version()       |
+-----------------+
| 10.6.14-MariaDB |
+-----------------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'create database sbtest;'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "History%"'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 6     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ~/git/sysbench/src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
FATAL: Cannot find benchmark 'oltp_read_write': no such built-in test, file or module
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest1'...Creating table 'sbtest3'...Creating table 'sbtest2'...Creating table 'sbtest4'...
 
 
 
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest1'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest4'
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 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: 1130.75 qps: 22619.94 (r/w/o: 15834.83/4523.21/2261.90) lat (ms,95%): 5.00 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 1058.67 qps: 21175.70 (r/w/o: 14822.75/4235.60/2117.35) lat (ms,95%): 5.67 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 1129.88 qps: 22595.45 (r/w/o: 15816.96/4518.73/2259.76) lat (ms,95%): 4.41 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 1032.51 qps: 20648.74 (r/w/o: 14454.07/4129.75/2064.92) lat (ms,95%): 5.67 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 1024.65 qps: 20495.53 (r/w/o: 14347.52/4098.61/2049.40) lat (ms,95%): 5.47 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 988.26 qps: 19764.99 (r/w/o: 13835.43/3953.04/1976.52) lat (ms,95%): 6.43 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 1045.45 qps: 20908.07 (r/w/o: 14635.38/4181.79/2090.90) lat (ms,95%): 5.77 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 1171.56 qps: 23432.09 (r/w/o: 16402.71/4686.26/2343.13) lat (ms,95%): 4.33 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 939.60 qps: 18791.84 (r/w/o: 13154.26/3758.39/1879.19) lat (ms,95%): 6.91 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1500254
        write:                           428644
        other:                           214322
        total:                           2143220
    transactions:                        107161 (1071.58 per sec.)
    queries:                             2143220 (21431.70 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      1071.5848
    time elapsed:                        100.0023s
    total number of events:              107161
 
Latency (ms):
         min:                                    1.81
         avg:                                    3.73
         max:                                  108.74
         95th percentile:                        5.28
         sum:                               399637.95
 
Threads fairness:
    events (avg/stddev):           26790.2500/49.49
    execution time (avg/stddev):   99.9095/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  79691776 10 May 18:29 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     136	Index page
    3029	Undo log page
      34	Inode page
       0	Insert buffer free list page
    1532	Freshly allocated page
       1	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 3029
Undo page state: 3 active, 128 cached, 2602 to_purge, 0 prepared, 296 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
23		21		21		73		15038
24		39		39		73		15038
25		12		12		73		15038
26		33		33		73		15038
27		8		8		831		10814
28		3		3		789		10257
29		5		5		960		12480
30		4		4		900		11706
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
23		0	0	0	0	0	0	0	0	0	0	21	0
24		0	0	0	0	0	0	0	0	0	0	39	0
25		0	0	0	0	0	0	0	0	0	0	12	0
26		0	0	0	0	0	0	0	0	0	0	33	0
27		0	0	0	0	0	4	1	0	0	0	3	0
28		0	0	0	0	0	2	0	0	0	0	1	0
29		0	0	0	0	0	2	0	0	0	0	3	0
30		0	0	0	0	0	2	0	0	0	0	2	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 14841 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     136	Index page
    3029	Undo log page
      34	Inode page
       0	Insert buffer free list page
    1532	Freshly allocated page
       1	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 3029
Undo page state: 3 active, 128 cached, 2602 to_purge, 0 prepared, 296 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
23		21		21		73		15038
24		39		39		73		15038
25		12		12		73		15038
26		33		33		73		15038
27		8		8		831		10814
28		3		3		789		10257
29		5		5		960		12480
30		4		4		900		11706
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
23		0	0	0	0	0	0	0	0	0	0	21	0
24		0	0	0	0	0	0	0	0	0	0	39	0
25		0	0	0	0	0	0	0	0	0	0	12	0
26		0	0	0	0	0	0	0	0	0	0	33	0
27		0	0	0	0	0	4	1	0	0	0	3	0
28		0	0	0	0	0	2	0	0	0	0	1	0
29		0	0	0	0	0	2	0	0	0	0	3	0
30		0	0	0	0	0	2	0	0	0	0	2	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ cd -
/Users/Valerii/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 cleanup
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Dropping table 'sbtest1'...
Dropping table 'sbtest2'...
Dropping table 'sbtest3'...
Dropping table 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest2'...Creating table 'sbtest1'...Creating table 'sbtest4'...Creating table 'sbtest3'...
 
 
 
Inserting 100000 records into 'sbtest1'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest4'
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 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: 1122.63 qps: 22457.48 (r/w/o: 15721.31/4490.52/2245.66) lat (ms,95%): 4.82 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 1046.27 qps: 20924.06 (r/w/o: 14646.42/4185.09/2092.55) lat (ms,95%): 5.47 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 1058.16 qps: 21161.99 (r/w/o: 14813.03/4232.64/2116.32) lat (ms,95%): 5.28 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 1039.24 qps: 20789.53 (r/w/o: 14552.88/4158.17/2078.48) lat (ms,95%): 5.47 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 976.35 qps: 19524.75 (r/w/o: 13667.54/3904.51/1952.71) lat (ms,95%): 7.43 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 999.26 qps: 19985.57 (r/w/o: 13990.12/3996.93/1998.52) lat (ms,95%): 5.99 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 756.65 qps: 15133.11 (r/w/o: 10593.40/3026.40/1513.30) lat (ms,95%): 11.24 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 1003.70 qps: 20071.70 (r/w/o: 14049.47/4014.82/2007.41) lat (ms,95%): 7.56 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 853.51 qps: 17070.48 (r/w/o: 11949.42/3414.14/1706.92) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 926.72 qps: 18534.87 (r/w/o: 12974.23/3707.29/1853.35) lat (ms,95%): 8.13 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1369662
        write:                           391332
        other:                           195666
        total:                           1956660
    transactions:                        97833  (978.28 per sec.)
    queries:                             1956660 (19565.69 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      978.2843
    time elapsed:                        100.0047s
    total number of events:              97833
 
Latency (ms):
         min:                                    1.97
         avg:                                    4.09
         max:                                  165.87
         95th percentile:                        7.04
         sum:                               399666.97
 
Threads fairness:
    events (avg/stddev):           24458.2500/69.78
    execution time (avg/stddev):   99.9167/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 9514  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 9514  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 9514  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  146800640 10 May 18:32 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     132	Index page
    6127	Undo log page
      73	Inode page
       0	Insert buffer free list page
    2490	Freshly allocated page
       3	Insert buffer bitmap
     131	System page
       1	Transaction system page
       3	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 6127
Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
31		23		23		73		15038
32		34		34		73		15038
33		15		15		73		15038
34		21		21		73		15038
35		1		1		620		8060
36		7		7		698		9083
37		11		11		789		10257
38		1		1		1191		15483
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
31		0	0	0	0	0	0	0	0	0	0	23	0
32		0	0	0	0	0	0	0	0	0	0	34	0
33		0	0	0	0	0	0	0	0	0	0	15	0
34		0	0	0	0	0	0	0	0	0	0	21	0
35		0	0	0	0	0	1	0	0	0	0	0	0
36		0	0	0	0	0	5	1	0	0	0	1	0
37		0	0	0	0	0	7	0	1	0	0	3	0
38		0	0	0	0	0	0	0	0	0	0	1	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 9514  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     132	Index page
    6127	Undo log page
      73	Inode page
       0	Insert buffer free list page
    2490	Freshly allocated page
       3	Insert buffer bitmap
     131	System page
       1	Transaction system page
       3	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 6127
Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
31		23		23		73		15038
32		34		34		73		15038
33		15		15		73		15038
34		21		21		73		15038
35		1		1		620		8060
36		7		7		698		9083
37		11		11		789		10257
38		1		1		1191		15483
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
31		0	0	0	0	0	0	0	0	0	0	23	0
32		0	0	0	0	0	0	0	0	0	0	34	0
33		0	0	0	0	0	0	0	0	0	0	15	0
34		0	0	0	0	0	0	0	0	0	0	21	0
35		0	0	0	0	0	1	0	0	0	0	0	0
36		0	0	0	0	0	5	1	0	0	0	1	0
37		0	0	0	0	0	7	0	1	0	0	3	0
38		0	0	0	0	0	0	0	0	0	0	1	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     132	Index page
    6127	Undo log page
      73	Inode page
       0	Insert buffer free list page
    2490	Freshly allocated page
       3	Insert buffer bitmap
     131	System page
       1	Transaction system page
       3	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 6127
Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
31		23		23		73		15038
32		34		34		73		15038
33		15		15		73		15038
34		21		21		73		15038
35		1		1		620		8060
36		7		7		698		9083
37		11		11		789		10257
38		1		1		1191		15483
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
31		0	0	0	0	0	0	0	0	0	0	23	0
32		0	0	0	0	0	0	0	0	0	0	34	0
33		0	0	0	0	0	0	0	0	0	0	15	0
34		0	0	0	0	0	0	0	0	0	0	21	0
35		0	0	0	0	0	1	0	0	0	0	0	0
36		0	0	0	0	0	5	1	0	0	0	1	0
37		0	0	0	0	0	7	0	1	0	0	3	0
38		0	0	0	0	0	0	0	0	0	0	1	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_max_purge_lag%"'
+----------------------------+------------+
| Variable_name              | Value      |
+----------------------------+------------+
| innodb_max_purge_lag       | 0          |
| innodb_max_purge_lag_delay | 0          |
| innodb_max_purge_lag_wait  | 4294967295 |
+----------------------------+------------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag = 500000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag_delay = 5000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_max_purge_lag%"'
+----------------------------+------------+
| Variable_name              | Value      |
+----------------------------+------------+
| innodb_max_purge_lag       | 500000     |
| innodb_max_purge_lag_delay | 5000       |
| innodb_max_purge_lag_wait  | 4294967295 |
+----------------------------+------------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     132	Index page
    6127	Undo log page
      73	Inode page
       0	Insert buffer free list page
    2490	Freshly allocated page
       3	Insert buffer bitmap
     131	System page
       1	Transaction system page
       3	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 6127
Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
31		23		23		73		15038
32		34		34		73		15038
33		15		15		73		15038
34		21		21		73		15038
35		1		1		620		8060
36		7		7		698		9083
37		11		11		789		10257
38		1		1		1191		15483
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
31		0	0	0	0	0	0	0	0	0	0	23	0
32		0	0	0	0	0	0	0	0	0	0	34	0
33		0	0	0	0	0	0	0	0	0	0	15	0
34		0	0	0	0	0	0	0	0	0	0	21	0
35		0	0	0	0	0	1	0	0	0	0	0	0
36		0	0	0	0	0	5	1	0	0	0	1	0
37		0	0	0	0	0	7	0	1	0	0	3	0
38		0	0	0	0	0	0	0	0	0	0	1	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ cd -
/Users/Valerii/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 cleanup
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Dropping table 'sbtest1'...
Dropping table 'sbtest2'...
Dropping table 'sbtest3'...
Dropping table 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest4'...Creating table 'sbtest1'...Creating table 'sbtest2'...Creating table 'sbtest3'...
 
 
 
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest1'
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 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: 963.28 qps: 19271.53 (r/w/o: 13491.44/3853.13/1926.96) lat (ms,95%): 6.67 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 1032.93 qps: 20657.49 (r/w/o: 14459.78/4131.84/2065.87) lat (ms,95%): 5.88 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 804.67 qps: 16090.49 (r/w/o: 11262.67/3218.58/1609.24) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 793.27 qps: 15868.29 (r/w/o: 11108.58/3173.08/1586.64) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 771.14 qps: 15419.91 (r/w/o: 10793.20/3084.54/1542.17) lat (ms,95%): 10.46 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 892.86 qps: 17861.77 (r/w/o: 12504.02/3571.93/1785.82) lat (ms,95%): 7.70 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 890.88 qps: 17817.21 (r/w/o: 12472.25/3563.20/1781.75) lat (ms,95%): 8.28 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 926.31 qps: 18524.86 (r/w/o: 12967.08/3705.15/1852.63) lat (ms,95%): 7.56 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 799.88 qps: 15995.53 (r/w/o: 11196.37/3199.41/1599.75) lat (ms,95%): 9.91 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 888.00 qps: 17757.17 (r/w/o: 12429.58/3551.99/1775.60) lat (ms,95%): 8.28 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1226918
        write:                           350548
        other:                           175274
        total:                           1752740
    transactions:                        87637  (876.32 per sec.)
    queries:                             1752740 (17526.50 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      876.3249
    time elapsed:                        100.0051s
    total number of events:              87637
 
Latency (ms):
         min:                                    1.76
         avg:                                    4.56
         max:                                  167.92
         95th percentile:                        8.28
         sum:                               399658.03
 
Threads fairness:
    events (avg/stddev):           21909.2500/29.35
    execution time (avg/stddev):   99.9145/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  213909504 10 May 18:38 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     138	Index page
   10016	Undo log page
     114	Inode page
       0	Insert buffer free list page
    2655	Freshly allocated page
       1	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 10016
Undo page state: 0 active, 129 cached, 9405 to_purge, 0 prepared, 482 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
39		19		19		73		15038
40		18		18		73		15038
41		14		14		73		15038
42		24		24		73		15038
43		12		12		947		12320
44		12		12		951		12365
45		11		11		821		10675
46		17		17		782		10176
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
39		0	0	0	0	0	0	0	0	0	0	19	0
40		0	0	0	0	0	0	0	0	0	0	18	0
41		0	0	0	0	0	0	0	0	0	0	14	0
42		0	0	0	0	0	0	0	0	0	0	24	0
43		0	0	0	0	0	4	1	0	0	0	7	0
44		0	0	0	0	0	4	1	0	0	0	7	0
45		0	0	0	0	0	6	1	0	0	0	4	0
46		0	0	0	0	0	11	1	0	0	0	5	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_max_purge_lag%"'
+----------------------------+------------+
| Variable_name              | Value      |
+----------------------------+------------+
| innodb_max_purge_lag       | 500000     |
| innodb_max_purge_lag_delay | 5000       |
| innodb_max_purge_lag_wait  | 4294967295 |
+----------------------------+------------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 4752  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     138	Index page
   10016	Undo log page
     114	Inode page
       0	Insert buffer free list page
    2655	Freshly allocated page
       1	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 10016
Undo page state: 0 active, 129 cached, 9405 to_purge, 0 prepared, 482 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
39		19		19		73		15038
40		18		18		73		15038
41		14		14		73		15038
42		24		24		73		15038
43		12		12		947		12320
44		12		12		951		12365
45		11		11		821		10675
46		17		17		782		10176
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
39		0	0	0	0	0	0	0	0	0	0	19	0
40		0	0	0	0	0	0	0	0	0	0	18	0
41		0	0	0	0	0	0	0	0	0	0	14	0
42		0	0	0	0	0	0	0	0	0	0	24	0
43		0	0	0	0	0	4	1	0	0	0	7	0
44		0	0	0	0	0	4	1	0	0	0	7	0
45		0	0	0	0	0	6	1	0	0	0	4	0
46		0	0	0	0	0	11	1	0	0	0	5	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ 

Comment by Valerii Kravchuk [ 2023-05-10 ]

Moreover, if we enable separate undo tablespaces with truncation, the growth seem to witch there. Consider this test with 10.6.14:

Yuliyas-Air:maria10.6 Valerii$ rm -rf data/*
Yuliyas-Air:maria10.6 Valerii$ scripts/mysql_install_db --no-defaults --innodb_undo_tablespaces=3
Installing MariaDB/MySQL system tables in './data' ...
2023-05-10 18:52:18 0 [Warning] InnoDB: innodb_open_files 300 should not be greater than the open_files_limit 256
OK
 
To start mariadbd at boot time you have to copy
support-files/mariadb.service to the right place for your system
 
 
Two all-privilege accounts were created.
One is root@localhost, it has no password, but you need to
be system 'root' user to connect. Use, for example, sudo mysql
The second is Valerii@localhost, it has no password either, but
you need to be the system 'Valerii' user to connect.
After connecting you can set the password, if you would need to be
able to connect as any of these users with a password and without sudo
 
See the MariaDB Knowledgebase at https://mariadb.com/kb
 
You can start the MariaDB daemon with:
cd '.' ; ./bin/mariadb-safe --datadir='./data'
 
You can test the MariaDB daemon with mysql-test-run.pl
cd './mysql-test' ; perl mariadb-test-run.pl
 
Please report any problems at https://mariadb.org/jira
 
The latest information about MariaDB is available at https://mariadb.org/.
 
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/
 
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ib*
-rw-r-----  1 Valerii  staff        811 10 May 18:52 data/ib_buffer_pool
-rw-rw----  1 Valerii  staff  100663296 10 May 18:52 data/ib_logfile0
-rw-rw----  1 Valerii  staff   12582912 10 May 18:52 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  10485760 10 May 18:52 data/undo001
-rw-rw----  1 Valerii  staff  10485760 10 May 18:52 data/undo002
-rw-rw----  1 Valerii  staff  10485760 10 May 18:52 data/undo003

Now the test:

Yuliyas-Air:maria10.6 Valerii$ 230510 18:56:11 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.
230510 18:56:11 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data
 
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_undo%"'
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_undo_directory    | ./    |
| innodb_undo_log_truncate | ON    |
| innodb_undo_tablespaces  | 3     |
+--------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag = 500000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag_delay = 5000'
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'create database sbtest'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_undo%"'
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_undo_directory    | ./    |
| innodb_undo_log_truncate | ON    |
| innodb_undo_tablespaces  | 3     |
+--------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_max_purge_lag%"'
+----------------------------+------------+
| Variable_name              | Value      |
+----------------------------+------------+
| innodb_max_purge_lag       | 500000     |
| innodb_max_purge_lag_delay | 5000       |
| innodb_max_purge_lag_wait  | 4294967295 |
+----------------------------+------------+
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest2'...Creating table 'sbtest4'...Creating table 'sbtest1'...
Creating table 'sbtest3'...
 
 
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest1'
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest2'...
Yuliyas-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 --report_interval=10 --time=100 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: 1117.48 qps: 22354.71 (r/w/o: 15649.46/4469.90/2235.35) lat (ms,95%): 5.18 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 936.98 qps: 18738.88 (r/w/o: 13116.61/3748.32/1873.96) lat (ms,95%): 7.70 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 819.80 qps: 16395.62 (r/w/o: 11477.24/3278.78/1639.59) lat (ms,95%): 9.56 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 1009.97 qps: 20196.07 (r/w/o: 14136.23/4039.89/2019.95) lat (ms,95%): 6.21 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 927.21 qps: 18547.92 (r/w/o: 12984.39/3709.13/1854.41) lat (ms,95%): 7.56 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 778.95 qps: 15577.53 (r/w/o: 10904.15/3115.49/1557.89) lat (ms,95%): 10.27 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 645.73 qps: 12917.02 (r/w/o: 9042.44/2583.12/1291.46) lat (ms,95%): 14.46 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 848.32 qps: 16966.18 (r/w/o: 11876.44/3393.10/1696.65) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 992.91 qps: 19855.23 (r/w/o: 13897.76/3971.65/1985.82) lat (ms,95%): 6.43 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 3 tps: 973.68 qps: 19474.76 (r/w/o: 13632.39/3895.21/1947.16) lat (ms,95%): 6.79 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1267266
        write:                           362076
        other:                           181038
        total:                           1810380
    transactions:                        90519  (904.90 per sec.)
    queries:                             1810380 (18097.95 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      904.8974
    time elapsed:                        100.0323s
    total number of events:              90519
 
Latency (ms):
         min:                                    1.78
         avg:                                    4.42
         max:                                  162.14
         95th percentile:                        8.13
         sum:                               399692.62
 
Threads fairness:
    events (avg/stddev):           22629.7500/61.71
    execution time (avg/stddev):   99.9232/0.01
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ib*
-rw-r-----  1 Valerii  staff        819 10 May 18:55 data/ib_buffer_pool
-rw-rw----  1 Valerii  staff  100663296 10 May 18:59 data/ib_logfile0
-rw-rw----  1 Valerii  staff   12582912 10 May 18:59 data/ibdata1
-rw-rw----  1 Valerii  staff   12582912 10 May 18:58 data/ibtmp1
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  13631488 10 May 18:58 data/undo001
-rw-rw----  1 Valerii  staff  15728640 10 May 18:59 data/undo002
-rw-rw----  1 Valerii  staff  13631488 10 May 18:59 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  13631488 10 May 18:58 data/undo001
-rw-rw----  1 Valerii  staff  15728640 10 May 18:59 data/undo002
-rw-rw----  1 Valerii  staff  13631488 10 May 18:59 data/undo003
Yuliyas-Air:maria10.6 Valerii$ cd -
/Users/Valerii/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 cleanup
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Dropping table 'sbtest1'...
Dropping table 'sbtest2'...
Dropping table 'sbtest3'...
Dropping table 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest4'...Creating table 'sbtest2'...Creating table 'sbtest1'...Creating table 'sbtest3'...
 
 
 
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest1'
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest3'...
Yuliyas-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 --report_interval=10 --time=100 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: 686.71 qps: 13738.81 (r/w/o: 9618.05/2746.94/1373.82) lat (ms,95%): 12.75 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 681.92 qps: 13636.07 (r/w/o: 9544.63/2727.59/1363.85) lat (ms,95%): 11.65 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 895.23 qps: 17905.21 (r/w/o: 12533.86/3580.90/1790.45) lat (ms,95%): 7.98 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 928.12 qps: 18564.48 (r/w/o: 12995.74/3712.50/1856.25) lat (ms,95%): 7.30 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 958.65 qps: 19171.62 (r/w/o: 13419.35/3834.98/1917.29) lat (ms,95%): 7.30 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 938.44 qps: 18770.96 (r/w/o: 13139.84/3754.25/1876.88) lat (ms,95%): 7.43 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 993.94 qps: 19876.75 (r/w/o: 13913.93/3974.95/1987.88) lat (ms,95%): 6.67 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 984.14 qps: 19683.09 (r/w/o: 13778.35/3936.46/1968.28) lat (ms,95%): 7.17 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 979.44 qps: 19589.27 (r/w/o: 13712.61/3917.77/1958.89) lat (ms,95%): 6.79 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 888.01 qps: 17759.24 (r/w/o: 12430.87/3552.55/1775.82) lat (ms,95%): 7.98 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1250900
        write:                           357400
        other:                           178700
        total:                           1787000
    transactions:                        89350  (893.45 per sec.)
    queries:                             1787000 (17868.93 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      893.4466
    time elapsed:                        100.0060s
    total number of events:              89350
 
Latency (ms):
         min:                                    2.30
         avg:                                    4.47
         max:                                  324.42
         95th percentile:                        7.98
         sum:                               399661.57
 
Threads fairness:
    events (avg/stddev):           22337.5000/44.33
    execution time (avg/stddev):   99.9154/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ib*
-rw-r-----  1 Valerii  staff        819 10 May 18:55 data/ib_buffer_pool
-rw-rw----  1 Valerii  staff  100663296 10 May 19:02 data/ib_logfile0
-rw-rw----  1 Valerii  staff   12582912 10 May 19:02 data/ibdata1
-rw-rw----  1 Valerii  staff   12582912 10 May 18:58 data/ibtmp1
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  13631488 10 May 18:58 data/undo001
-rw-rw----  1 Valerii  staff  27262976 10 May 19:02 data/undo002
-rw-rw----  1 Valerii  staff  15728640 10 May 19:02 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  13631488 10 May 18:58 data/undo001
-rw-rw----  1 Valerii  staff  27262976 10 May 19:02 data/undo002
-rw-rw----  1 Valerii  staff  15728640 10 May 19:02 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo002 
 
File::data/undo002
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
    1223	Undo log page
      15	Inode page
       0	Insert buffer free list page
     382	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 1223
Undo page state: 3 active, 77 cached, 1137 to_purge, 0 prepared, 6 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ 

All 3 undo tablespaces grew and contain "to_purge" pages:

Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo001 
 
File::data/undo001
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     402	Undo log page
       6	Inode page
       0	Insert buffer free list page
     379	Freshly allocated page
       1	Insert buffer bitmap
      43	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 402
Undo page state: 0 active, 29 cached, 369 to_purge, 0 prepared, 4 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo002
 
File::data/undo002
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
    1223	Undo log page
      15	Inode page
       0	Insert buffer free list page
     382	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 1223
Undo page state: 3 active, 77 cached, 1137 to_purge, 0 prepared, 6 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo003
 
File::data/undo003
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     545	Undo log page
       7	Inode page
       0	Insert buffer free list page
     364	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 545
Undo page state: 0 active, 42 cached, 499 to_purge, 0 prepared, 4 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ 

Comment by Christopher Mähler [ 2023-05-11 ]

We observed a similar problem on a system after updating from MariaDB 10.9.5 to 10.9.6. After updating to 10.9.6 the ibdata1 was fast and constantly growing:

innochecksum ibdata1 
Undo page type: 5474513
Undo page state: 1 active, 78 cached, 5472837 to_purge, 0 prepared, 1597 other

We had to downgrade to 10.9.5 to prevent a full filesystem.

Comment by Marko Mäkelä [ 2023-05-12 ]

valerii, I think that it is possible that some of the pages that innochecksum reports as undo log pages have actually been freed. I tried a variation of your test, with a 1GiB buffer pool and a slow shutdown. After that, innochecksum -S ibdata1 reported the following:

mariadb-10.6.12

      11	Index page
     337	Undo log page
      13	Inode page
       0	Insert buffer free list page
   28818	Freshly allocated page
       2	Insert buffer bitmap
     255	System page
       1	Transaction system page
       2	File Space Header
       1	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page

Then I repeated the same test with innodb_buffer_pool_size=100M and still innodb_log_file_size=1G. The total size of the data directory is about 1.6GiB, leaving about 600MiB for the actual data files. With that, I got a similar result as you:

mariadb-10.6.12

      11	Index page
   25557	Undo log page
     307	Inode page
       0	Insert buffer free list page
    3430	Freshly allocated page
       2	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       1	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page

Due to the smaller buffer pool, the MDEV-15528 optimization could not kick in, and later-to-be-freed undo log pages had to be written out to the data files.

Finally, I retained the same small buffer pool size and added innodb_immediate_scrub_data_uncompressed=ON to enable the zeroing-out of freed pages (MDEV-8139):

mariadb-10.6.12

      11	Index page
     431	Undo log page
     303	Inode page
       0	Insert buffer free list page
   28559	Freshly allocated page
       2	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       2	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page

That the files grow eagerly (despite MDEV-13013) and do not shrink is a known problem, to be partly fixed by MDEV-14795 and MDEV-28699, and in the case of undo tablespaces already worked around by innodb_undo_log_truncate=ON (which requires multiple innodb_undo_tablespaces).

Comment by Marko Mäkelä [ 2023-05-12 ]

I can confirm this on MariaDB 10.6.13. A huge number of undo log pages will remain despite the slow shutdown.

Comment by Marko Mäkelä [ 2023-05-12 ]

I can confirm that the fix of MDEV-30671 introduced this. I think that also the 10.5.19 release should be affected.

Comment by Marko Mäkelä [ 2023-05-12 ]

MDEV-30671 was an important correctness fix: undo tablespace truncation definitely was broken. It seems that the fix to this "garbage collector" (to prevent the premature freeing of undo log pages) could be causing a persistent "memory leak" (undo pages will not be freed), but I am not yet sure about that.

This is dependent on the load and somewhat sporadic. I am trying to create a minimal-sized test for reproducing this so that I can analyze it better and understand the exact cause. On my 40-thread system, a 2-second oltp_read_write test with 72 connections and 4×1000 rows followed by a slow shutdown often ends in 0 undo log pages, but occasionally more. I have observed 1414 and 1426 pages. If I use 96 or more concurrent connections, each and every run will end up with some 14xx seemingly leaked undo log pages.

Comment by Marko Mäkelä [ 2023-05-12 ]

sbtest-rr.tar.xz is a copy of a data directory that I created under rr record and on which I executed mariadbd in order to shrink the redo log file. There were some connection errors during the test, but the main thing is that 6 undo log pages will remain after a slow shutdown. This was created with 2 tables containing 2 records each. Next, I will check if those undo log pages are still attached to anything. If not, in rr replay I will be able to check what they used to be attached to and how they got detached (leaked).

Comment by Marko Mäkelä [ 2023-05-12 ]

sbtest-rr.tar.xz is actually a false alarm for this bug. The 6 undo log pages were actually marked as free in the page allocation bitmap.

od -Ax -w32 -t x1 sbtest-rr/ibdata1 |grep '[048c]000\( ..\)\{24\} 00 02'

4b4000 00 00 00 00 00 00 01 2d ff ff ff ff ff ff ff ff 00 00 00 00 00 00 7f dc 00 02 00 00 00 00 00 00
4cc000 00 00 00 00 00 00 01 33 ff ff ff ff ff ff ff ff 00 00 00 00 00 00 87 56 00 02 00 00 00 00 00 00
4d0000 00 00 00 00 00 00 01 34 ff ff ff ff ff ff ff ff 00 00 00 00 00 00 8e 8c 00 02 00 00 00 00 00 00
4d4000 00 00 00 00 00 00 01 35 ff ff ff ff ff ff ff ff 00 00 00 00 00 00 98 71 00 02 00 00 00 00 00 00
4d8000 00 00 00 00 00 00 01 36 ff ff ff ff ff ff ff ff 00 00 00 00 00 00 9d aa 00 02 00 00 00 00 00 00
4dc000 00 00 00 00 00 00 01 37 ff ff ff ff ff ff ff ff 00 00 00 00 00 00 a0 fa 00 02 00 00 00 00 00 00

od -Ax -t x1 -j 0x158 -N 8 sbtest-rr/ibdata1

000158 aa ae ea ff ff ff 00 00

The allocation bitmap bytes 0xae, 0xea, 0xff correspond to these page numbers 0x12d, 0x133, and 0x134 through 0x137. In the rr replay trace, I see that fil_system.sys_space->freed_ranges includes these pages. For some reason, the pages were not zeroed out before shutdown even though innodb_immediate_scrub_data_uncompressed=ON was set. This does not explain the reported bug, but I must fix that so that I can more conveniently analyze the bug.

Comment by Marko Mäkelä [ 2023-05-12 ]

I filed MDEV-31253 for the scrubbing bug that caused the false alarm.

Comment by Marko Mäkelä [ 2023-05-12 ]

So far, I have been unsuccessful with rr. Old-fashioned instrumentation to the rescue:

@@ -485,7 +476,14 @@ trx_purge_truncate_rseg_history(trx_rseg_t& rseg,
       rseg.needs_purge > (purge_sys.head.trx_no
                           ? purge_sys.head.trx_no
                           : purge_sys.tail.trx_no))
-    /* We cannot free the entire undo page. */;
+    /* We cannot free the entire undo page. */
+    { if (srv_shutdown_state != SRV_SHUTDOWN_NONE)
+        ib::warn() << "cannot free " << rseg_hdr->page.id()
+                   << ":"
+                   << mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG)
+                   << ","
+                   << mach_read_from_2(TRX_UNDO_SEG_HDR + TRX_UNDO_STATE +
+                                       b->page.frame); }
   else
   {
     const uint32_t seg_size=

For my shrunk test with 2 tables and 2 rows each, this reveals that another source of false alarms is the undo log caching: all not-freed undo log segments are in state TRX_UNDO_CACHED. Before MDEV-29593, such undo log segments were not being freed at all. The rollback segment header pages would carry the page type 6 (FIL_PAGE_TYPE_SYS), and I believe that the ‘leaked’ undo log pages would belong to them.

I will temporarily disable the TRX_UNDO_CACHED logic to narrow down the search.

Comment by Marko Mäkelä [ 2023-05-12 ]

Disabling TRX_UNDO_CACHED seems to be this simple:

diff --git a/storage/innobase/trx/trx0undo.cc b/storage/innobase/trx/trx0undo.cc
index 20434d9fb9c..c78ac0afd4a 100644
--- a/storage/innobase/trx/trx0undo.cc
+++ b/storage/innobase/trx/trx0undo.cc
@@ -1481,13 +1481,7 @@ trx_undo_set_state_at_finish(
   /* This function is invoked during transaction commit, which is not
   allowed to fail. If we get a corrupted undo header, we will crash here. */
   ut_a(block);
-  const uint16_t state = undo->size == 1 &&
-    TRX_UNDO_PAGE_REUSE_LIMIT >
-    mach_read_from_2(TRX_UNDO_PAGE_HDR + TRX_UNDO_PAGE_FREE +
-                     block->page.frame)
-    ? TRX_UNDO_CACHED
-    : TRX_UNDO_TO_PURGE;
-
+  const uint16_t state= TRX_UNDO_TO_PURGE;
   undo->state= state;
   mtr->write<2>(*block, TRX_UNDO_SEG_HDR + TRX_UNDO_STATE + block->page.frame,
                 state);

After this change, my 1-second 2×2-row benchmark produced 1826 orphan undo log pages instead of 11 or less. With rr I still had no luck. The diagnostic message from my previous patch would indicate that freeing the undo log segments fails due to the conditions on rseg that were added in MDEV-30671.

An interesting tidbit is that one regression test would fail due to the two patches:

innodb.recovery_shutdown 'innodb'        w41 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2023-05-12 16:40:20
line
2023-05-12 16:40:18 0 [Warning] InnoDB: cannot free [page id: space=0, page number=47]:0,4

I can reproduce this on the first try with

./mtr --rr --parallel=auto innodb.recovery_shutdown{,,,,,,,,,,,,}

The trace mysqld.1.rr/mariadbd-1 includes some data that should help debug this regression:

(rr) p rseg
$1 = (trx_rseg_t &) @0x55b576f21680: {space = 0x55b578cd7940, latch = {
    writer = {lock = std::atomic<unsigned int> = { 2147483649 }}, 
    readers = std::atomic<unsigned int> = { 2147483648 }}, page_no = 47, 
  history_size = 1, needs_purge = 22, ref = std::atomic<unsigned int> = { 2 }, 
  curr_size = 3, undo_list = {count = 1, start = 0x55b578d20010, 
    end = 0x55b578d20010, node = &trx_undo_t::undo_list}, undo_cached = {
    count = 0, start = 0x0, end = 0x0, node = &trx_undo_t::undo_list}, 
  last_page_no = 4294967295, last_commit_and_offset = 24206847997116424}
(rr) p purge_sys.head.trx_no
$2 = 86
(rr) p purge_sys.tail.trx_no
$3 = 86

It is failing due to the reference count. But, that is again a false alarm because it is an XA PREPARE transaction:

(rr) watch -l rseg.ref._M_i
Hardware watchpoint 2: -location rseg.ref._M_i
(rr) reverse-continue
Continuing.
[Switching to Thread 1452979.1452979]
 
Thread 1 hit Breakpoint 1, sql_print_warning (
    format=format@entry=0x55b576074f30 "Found %d prepared XA transactions")
    at /mariadb/10.6/sql/log.cc:9269
9269	{
(rr) 
Continuing.
 
Thread 1 hit Hardware watchpoint 2: -location rseg.ref._M_i
 
Old value = 2
New value = 0
0x000055b576c9d719 in std::__atomic_base<unsigned int>::fetch_add (
    __m=std::memory_order_seq_cst, __i=2, this=<optimized out>)
    at /usr/include/c++/12/bits/atomic_base.h:616
616	      fetch_add(__int_type __i,
(rr) bt
#0  0x000055b576c9d719 in std::__atomic_base<unsigned int>::fetch_add (
    __m=std::memory_order_seq_cst, __i=2, this=<optimized out>)
    at /usr/include/c++/12/bits/atomic_base.h:616
#1  trx_rseg_t::acquire (this=<optimized out>)
    at /mariadb/10.6/storage/innobase/include/trx0rseg.h:136
#2  trx_resurrect (rows_to_undo=<synthetic pointer>, 
    start_time_micro=29597343636, start_time=1683899014, rseg=<optimized out>, 
    undo=0x55b578d20010) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:679
#3  trx_lists_init_at_db_start ()
    at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:750
#4  0x000055b576c843f1 in srv_start (create_new_db=<optimized out>)
    at /mariadb/10.6/storage/innobase/srv/srv0start.cc:1482

Comment by Marko Mäkelä [ 2023-05-12 ]

According to some more detailed diagnostic output that I added, in my test the undo log segment is not being freed because rseg.needs_purge is larger than either of purge_sys.head.trx_no or purge_sys.tail.trx_no. A comment in MDEV-22718 refers to a source code comment in trx_purge_truncate_history():

  if (head.trx_no >= purge_sys.low_limit_no())
  {
    /* This is sometimes necessary. TODO: find out why. */
    head.trx_no= purge_sys.low_limit_no();
    head.undo_no= 0;
  }

I think that in order to fix this regression, we must solve this mystery.

Comment by Marko Mäkelä [ 2023-05-12 ]

I was wondering if the following simple change could help.

@@ -482,9 +473,7 @@ trx_purge_truncate_rseg_history(trx_rseg_t& rseg,
 
   if (mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG) ||
       rseg.is_referenced() ||
-      rseg.needs_purge > (purge_sys.head.trx_no
-                          ? purge_sys.head.trx_no
-                          : purge_sys.tail.trx_no))
+      rseg.needs_purge > purge_sys.low_limit_no())
     /* We cannot free the entire undo page. */;
   else
   {

It did not work out. Even if I disabled the use of TRX_UNDO_CACHED, the slow shutdown would leave undo log pages behind. Besides, the correctness of such a change would have to be carefully reviewed and tested. It was just a wild experiment.

If I remove the condition on rseg.needs_purge altogether (and reintroduce the corruption bug MDEV-30671), all undo log pages will be freed in the test.

Comment by Marko Mäkelä [ 2023-05-15 ]

I experimented various things today, because I failed to reproduce this with rr record. I observed that at the end of the Sysbench workload, there will be many transaction rollbacks due to the server being shut down under workload. Related to that, one of my experiments was to modify trx_purge_add_undo_to_history() so that it would not add empty transactions (trx->undo_no == 0) to the purge history list. That would lead to various assertion failures.

Finally, using some modified code (which may have included some incorrect changes), I generated an rr replay trace of a failure to free some undo log pages. In the trace, the function trx_purge_truncate_rseg_history() seems to be decreasing the history list length and invoking flst_remove(rseg_hdr, …) also in the case when it would not invoke trx_purge_free_segment() due to the MDEV-30671 safety check being violated. Fixing this (if that is a valid finding to start with) would not be easy. We’d have to keep track of the not-yet-freeable undo log pages using the existing persistent data structures. Also the purge_sys.tail and purge_sys.head must be consistent with the persistent data structures.

Comment by Marko Mäkelä [ 2023-05-16 ]

With a patch to trx_undo_set_state_at_finish() to never use TRX_UNDO_CACHED, I got lucky and produced an rr replay trace where 10 undo log pages will be leaked. They belong to only two rollback segments:

rollback segment undo page number
112 0x1a1
111 0x1b2
111 0x21e
112 0x21f
111 0x29f
112 0x2b0
112 0x323
111 0x32e
112 0x3a3
111 0x3b4

I already checked that trx_purge_free_segment() was called on rollback segment 112 before the server was shut down, but I did not debug in detail yet why these undo log pages were not freed.

Comment by Anders Melchiorsen [ 2023-05-17 ]

You have probably realized this but we also have this issue with version 10.11.3. I guess all fix versions of MDEV-30671 are affected.

Thank you for the frequent updates.

Comment by Marko Mäkelä [ 2023-05-17 ]

jixam, right. I have updated the affected versions.

Based on my debugging so far, this may be an pre-existing error in lower-level code that was somehow exposed by the fix of MDEV-30671.

For both rollback segments that the 10 leaked undo pages in my small rr replay trace belong to, trx_purge_free_segment() will actually be called. Today I will find out why the 10 undo pages were never freed during the run, or why they were detached from (or never attached to) the doubly linked list in the rollback segment header.

Comment by Marko Mäkelä [ 2023-05-17 ]

In the rr replay trace that I created yesterday, the call to trx_purge_free_segment() in rollback segment 112 is invoked on page 0x42b, which had been allocated by trx_undo_assign_low because trx_undo_reuse_cached() encounters an empty rseg.undo_cached list. All the 5 leaked pages for rollback segment 112 were allocated in the same place. Next, I will find out when exactly the first allocated page 0x1a1 was last touched, and when we should have placed it to the rseg.undo_cached list to ensure proper reuse.

Unfortunately, based on what I have seen so far, I am afraid that those affected users who used innodb_undo_tablespaces=0 and got the ibdata1 file growing because of this must dump and reload the database. It might be possible to implement some clean-up action on top of MDEV-19229 and MDEV-14795, to mark the leaked undo log pages as freed.

Users of multiple innodb_undo_tablespaces should be able to reclaim the space by setting innodb_undo_log_truncate=ON.

Comment by Marko Mäkelä [ 2023-05-17 ]

On transaction commit, trx_purge_add_undo_to_history() both clears the TRX_RSEG + TRX_RSEG_UNDO_SLOTS entry and prepends the page to the TRX_RSEG + TRX_RSEG_HISTORY list in the rollback segment header page. That is, the further undo log page allocations in trx_undo_assign_low() are entirely correct, after all.

All 6 pages associated with the persistent list of rollback segment 122 will be processed during shutdown, by trx_purge_remove_log_hdr(). It looks like in the following case:

  if (mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG) ||
      rseg.is_referenced() ||
      rseg.needs_purge > (purge_sys.head.trx_no
                          ? purge_sys.head.trx_no
                          : purge_sys.tail.trx_no))
    /* We cannot free the entire undo log segment. */;

we must neither remove the entry from the persistent TRX_RSEG + TRX_RSEG_HISTORY list nor decrement rseg.history_size. At the point of execution where the 5 pages of rollback segment 112 are being leaked, we have rseg.needs_purge=0x5e9, which is 1 less than trx_sys..m_max_trx_id. During the last call (freeing the undo log page 0x42b), both purge_sys.head.trx_no and purge_sys.tail.trx_no have been advanced to the maximum 0x5ea, and that page will be freed.

Without https://rr-project.org and hardware data watchpoints (backed by the venerable 80386 debug registers) the root cause of this bug would have been very difficult to find, since there are so many areas where things could potentially have gone wrong.

Comment by Marko Mäkelä [ 2023-05-17 ]

With the following patch, my own testing on 10.6 looks fine:

diff --git a/storage/innobase/trx/trx0purge.cc b/storage/innobase/trx/trx0purge.cc
index b04e71ba871..687d1af5ba4 100644
--- a/storage/innobase/trx/trx0purge.cc
+++ b/storage/innobase/trx/trx0purge.cc
@@ -480,11 +480,7 @@ trx_purge_truncate_rseg_history(trx_rseg_t& rseg,
 
   rseg_hdr->fix();
 
-  if (mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG) ||
-      rseg.is_referenced() ||
-      rseg.needs_purge > (purge_sys.head.trx_no
-                          ? purge_sys.head.trx_no
-                          : purge_sys.tail.trx_no))
+  if (mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG))
     /* We cannot free the entire undo page. */;
   else
   {
@@ -613,8 +609,9 @@ TRANSACTIONAL_TARGET static void trx_purge_truncate_history()
     {
       ut_ad(rseg.is_persistent());
       rseg.latch.wr_lock(SRW_LOCK_CALL);
-      if (dberr_t e= trx_purge_truncate_rseg_history(rseg, head))
-        err= e;
+      if (!rseg.is_referenced() && rseg.needs_purge <= head.trx_no)
+        if (dberr_t e= trx_purge_truncate_rseg_history(rseg, head))
+          err= e;
       rseg.latch.wr_unlock();
     }
 
diff --git a/storage/innobase/trx/trx0undo.cc b/storage/innobase/trx/trx0undo.cc
index 20434d9fb9c..85ae27c9865 100644
--- a/storage/innobase/trx/trx0undo.cc
+++ b/storage/innobase/trx/trx0undo.cc
@@ -1481,12 +1481,7 @@ trx_undo_set_state_at_finish(
   /* This function is invoked during transaction commit, which is not
   allowed to fail. If we get a corrupted undo header, we will crash here. */
   ut_a(block);
-  const uint16_t state = undo->size == 1 &&
-    TRX_UNDO_PAGE_REUSE_LIMIT >
-    mach_read_from_2(TRX_UNDO_PAGE_HDR + TRX_UNDO_PAGE_FREE +
-                     block->page.frame)
-    ? TRX_UNDO_CACHED
-    : TRX_UNDO_TO_PURGE;
+  const uint16_t state = TRX_UNDO_TO_PURGE;
 
   undo->state= state;
   mtr->write<2>(*block, TRX_UNDO_SEG_HDR + TRX_UNDO_STATE + block->page.frame,

The last hunk is there only for test purposes, to prevent false alarms due to TRX_UNDO_CACHED, or alternatively, to make the leaks more prominent during my testing.

Some additional changes will be necessary in order to avoid a hang in case XA PREPARE transactions will survive a slow shutdown (innodb_fast_shutdown=0).

It is possible that even with this fix, more undo log pages will be allocated and the system or undo tablespaces will grow. This is inevitable due to the fix of MDEV-30671. A possible remedy might be to use the purge throttling mechanism that was improved in MDEV-29401.

Comment by Valerii Kravchuk [ 2023-05-17 ]

I've built current 10.6:

Yuliyas-Air:server Valerii$ git log -1
commit a3e5b5c4db47cd29dc090d27db1d7f915cf774f6 (HEAD -> 10.6, origin/10.6)
Merge: f522b0f2303 c9eff1a144b
Author: Marko Mäkelä <marko.makela@mariadb.com>
Date:   Mon May 15 09:02:32 2023 +0300
 
    Merge 10.5 into 10.6

with few fixes suggested by Marko:

Yuliyas-Air:server Valerii$ git diff
...
diff --git a/storage/innobase/trx/trx0purge.cc b/storage/innobase/trx/trx0purge.cc
index b04e71ba871..687d1af5ba4 100644
--- a/storage/innobase/trx/trx0purge.cc
+++ b/storage/innobase/trx/trx0purge.cc
@@ -480,11 +480,7 @@ trx_purge_truncate_rseg_history(trx_rseg_t& rseg,
 
   rseg_hdr->fix();
 
-  if (mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG) ||
-      rseg.is_referenced() ||
-      rseg.needs_purge > (purge_sys.head.trx_no
-                          ? purge_sys.head.trx_no
-                          : purge_sys.tail.trx_no))
+  if (mach_read_from_2(b->page.frame + hdr_addr.boffset + TRX_UNDO_NEXT_LOG))
     /* We cannot free the entire undo page. */;
   else
   {
@@ -613,8 +609,9 @@ TRANSACTIONAL_TARGET static void trx_purge_truncate_history()
     {
       ut_ad(rseg.is_persistent());
       rseg.latch.wr_lock(SRW_LOCK_CALL);
-      if (dberr_t e= trx_purge_truncate_rseg_history(rseg, head))
-        err= e;
+      if (!rseg.is_referenced() && rseg.needs_purge <= head.trx_no)
+        if (dberr_t e= trx_purge_truncate_rseg_history(rseg, head))
+          err= e;
       rseg.latch.wr_unlock();
     }
 
diff --git a/storage/innobase/trx/trx0undo.cc b/storage/innobase/trx/trx0undo.cc
index 20434d9fb9c..85ae27c9865 100644
--- a/storage/innobase/trx/trx0undo.cc
+++ b/storage/innobase/trx/trx0undo.cc
@@ -1481,12 +1481,7 @@ trx_undo_set_state_at_finish(
   /* This function is invoked during transaction commit, which is not
   allowed to fail. If we get a corrupted undo header, we will crash here. */
   ut_a(block);
-  const uint16_t state = undo->size == 1 &&
-    TRX_UNDO_PAGE_REUSE_LIMIT >
-    mach_read_from_2(TRX_UNDO_PAGE_HDR + TRX_UNDO_PAGE_FREE +
-                     block->page.frame)
-    ? TRX_UNDO_CACHED
-    : TRX_UNDO_TO_PURGE;
+  const uint16_t state = TRX_UNDO_TO_PURGE;
 
   undo->state= state;
   mtr->write<2>(*block, TRX_UNDO_SEG_HDR + TRX_UNDO_STATE + block->page.frame,

and re-run the test with multiple undo tablespaces and truncation enabled:

Yuliyas-Air:maria10.6 Valerii$ bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M --innodb_undo_log_truncate=1 --innodb_undo_tablespaces=3 &
[1] 54377
Yuliyas-Air:maria10.6 Valerii$ 230517 16:43:34 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.
230517 16:43:34 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data
 
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  10485760 17 May 16:41 data/undo001
-rw-rw----  1 Valerii  staff  10485760 17 May 16:41 data/undo002
-rw-rw----  1 Valerii  staff  10485760 17 May 16:41 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag = 500000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag_delay = 5000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'create database sbtest'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_undo%"'
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_undo_directory    | ./    |
| innodb_undo_log_truncate | ON    |
| innodb_undo_tablespaces  | 3     |
+--------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_max_purge_lag%"'
+----------------------------+------------+
| Variable_name              | Value      |
+----------------------------+------------+
| innodb_max_purge_lag       | 500000     |
| innodb_max_purge_lag_delay | 5000       |
| innodb_max_purge_lag_wait  | 4294967295 |
+----------------------------+------------+
Yuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest4'...Creating table 'sbtest1'...Creating table 'sbtest2'...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 'sbtest4'...
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest3'...
Yuliyas-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 --report_interval=10 --time=100 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: 721.48 qps: 14434.61 (r/w/o: 10105.36/2885.90/1443.35) lat (ms,95%): 13.70 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 675.94 qps: 13520.01 (r/w/o: 9463.99/2704.14/1351.87) lat (ms,95%): 15.55 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 779.73 qps: 15594.28 (r/w/o: 10916.28/3118.54/1559.47) lat (ms,95%): 10.27 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 700.25 qps: 14004.93 (r/w/o: 9803.05/2801.39/1400.49) lat (ms,95%): 15.00 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 695.70 qps: 13913.56 (r/w/o: 9739.77/2782.39/1391.40) lat (ms,95%): 16.71 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 854.39 qps: 17088.28 (r/w/o: 11961.92/3417.58/1708.79) lat (ms,95%): 10.84 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 778.34 qps: 15566.79 (r/w/o: 10896.62/3113.48/1556.69) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 694.39 qps: 13886.06 (r/w/o: 9719.84/2777.45/1388.78) lat (ms,95%): 17.32 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 792.50 qps: 15852.40 (r/w/o: 11096.73/3170.68/1584.99) lat (ms,95%): 10.27 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 789.84 qps: 15796.18 (r/w/o: 11057.81/3158.68/1579.69) lat (ms,95%): 14.46 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1047662
        write:                           299332
        other:                           149666
        total:                           1496660
    transactions:                        74833  (747.57 per sec.)
    queries:                             1496660 (14951.43 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      747.5714
    time elapsed:                        100.1015s
    total number of events:              74833
 
Latency (ms):
         min:                                    1.82
         avg:                                    5.35
         max:                                  722.42
         95th percentile:                       13.22
         sum:                               400115.68
 
Threads fairness:
    events (avg/stddev):           18708.2500/97.29
    execution time (avg/stddev):   100.0289/0.00

Note a bit lower TPS and QPS (maybe a coincidence). I've got this result after sysbench run completed:

Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  13631488 17 May 16:48 data/undo001
-rw-rw----  1 Valerii  staff  12582912 17 May 16:48 data/undo002
-rw-rw----  1 Valerii  staff  12582912 17 May 16:48 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo001 
 
File::data/undo001
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     587	Undo log page
       8	Inode page
       0	Insert buffer free list page
     192	Freshly allocated page
       1	Insert buffer bitmap
      43	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 587
Undo page state: 0 active, 0 cached, 587 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo002 
 
File::data/undo002
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     588	Undo log page
       8	Inode page
       0	Insert buffer free list page
     128	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 588
Undo page state: 0 active, 0 cached, 588 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo003 
 
File::data/undo003
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     588	Undo log page
       8	Inode page
       0	Insert buffer free list page
     128	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 588
Undo page state: 0 active, 0 cached, 588 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)

So, undo* files increased and there are pages to purge. After slow shutdown:

Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_fast_shutdown = 0'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'shutdown'
Yuliyas-Air:maria10.6 Valerii$ tail data/Yuliyas-Air.err 
2023-05-17 16:50:05 0 [Note] InnoDB: Truncated .//undo003
2023-05-17 16:50:05 0 [Note] InnoDB: Starting shutdown...
2023-05-17 16:50:06 0 [Note] InnoDB: Dumping buffer pool(s) to /Users/Valerii/dbs/maria10.6/data/ib_buffer_pool
2023-05-17 16:50:06 0 [Note] InnoDB: Restricted to 2007 pages due to innodb_buf_pool_dump_pct=25
2023-05-17 16:50:06 0 [Note] InnoDB: Buffer pool(s) dump completed at 230517 16:50:06
2023-05-17 16:50:06 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2023-05-17 16:50:06 0 [Note] InnoDB: Shutdown completed; log sequence number 342784548; transaction id 150044
2023-05-17 16:50:06 0 [Note] /Users/Valerii/dbs/maria10.6/bin/mariadbd: Shutdown complete
 
230517 16:50:06 mysqld_safe mysqld from pid file /Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.pid ended
[1]+  Done                    bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M --innodb_undo_log_truncate=1 --innodb_undo_tablespaces=3
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  10485760 17 May 16:50 data/undo001
-rw-rw----  1 Valerii  staff  10485760 17 May 16:50 data/undo002
-rw-rw----  1 Valerii  staff  10485760 17 May 16:50 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo001 
 
File::data/undo001
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     587	Undo log page
       8	Inode page
       0	Insert buffer free list page
       0	Freshly allocated page
       1	Insert buffer bitmap
      43	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 587
Undo page state: 0 active, 0 cached, 587 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo002 
 
File::data/undo002
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     588	Undo log page
       8	Inode page
       0	Insert buffer free list page
       0	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 588
Undo page state: 0 active, 0 cached, 588 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo003 
 
File::data/undo003
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
     588	Undo log page
       8	Inode page
       0	Insert buffer free list page
       0	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 588
Undo page state: 0 active, 0 cached, 588 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)

I see truncation happened, but innochecksum -S still reports pages "to_purge". I am waiting for comments on what of the above is the expected result of the patch and what I missed.

Comment by Valerii Kravchuk [ 2023-05-17 ]

Actually I missed one setting needed to free undo pages in dedicated tablespaces during a normal run (not at shutdown), this one:

https://mariadb.com/kb/en/innodb-system-variables/#innodb_immediate_scrub_data_uncompressed

With it in place, the test:

Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global variables like "innodb_%scrub%"'
+------------------------------------------+-------+
| Variable_name                            | Value |
+------------------------------------------+-------+
| innodb_immediate_scrub_data_uncompressed | ON    |
+------------------------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  10485760 17 May 17:20 data/undo001
-rw-rw----  1 Valerii  staff  10485760 17 May 17:20 data/undo002
-rw-rw----  1 Valerii  staff  10485760 17 May 17:20 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo001 
 
File::data/undo001
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
      28	Undo log page
       8	Inode page
       0	Insert buffer free list page
     559	Freshly allocated page
       1	Insert buffer bitmap
      43	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 28
Undo page state: 0 active, 0 cached, 28 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo002 
 
File::data/undo002
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
      14	Undo log page
       8	Inode page
       0	Insert buffer free list page
     574	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 14
Undo page state: 0 active, 0 cached, 14 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo003 
 
File::data/undo003
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
      28	Undo log page
       8	Inode page
       0	Insert buffer free list page
     560	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 28
Undo page state: 0 active, 0 cached, 28 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ ./src/sysbench oltp_read_write --threads=4 --tables=4 --table-size=100000 --db-driver=mysql --mysql-socket=/tmp/mysql.sock --mysql-user=Valerii --report_interval=10 --time=100 cleanup
-bash: ./src/sysbench: No such file or directory
Yuliyas-Air:maria10.6 Valerii$ cd -
/Users/Valerii/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 cleanup
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Dropping table 'sbtest1'...
Dropping table 'sbtest2'...
Dropping table 'sbtest3'...
Dropping table 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest3'...Creating table 'sbtest1'...Creating table 'sbtest2'...Creating table 'sbtest4'...
 
 
 
Inserting 100000 records into 'sbtest3'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest1'
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest1'...
Yuliyas-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 --report_interval=10 --time=100 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: 759.17 qps: 15188.63 (r/w/o: 10632.83/3037.07/1518.73) lat (ms,95%): 11.04 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 722.91 qps: 14456.94 (r/w/o: 10119.90/2891.23/1445.81) lat (ms,95%): 13.22 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 531.19 qps: 10625.17 (r/w/o: 7437.71/2125.07/1062.39) lat (ms,95%): 17.32 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 749.33 qps: 14984.62 (r/w/o: 10488.97/2997.00/1498.65) lat (ms,95%): 14.46 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 767.51 qps: 15352.44 (r/w/o: 10746.87/3070.55/1535.02) lat (ms,95%): 13.22 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 553.50 qps: 11069.28 (r/w/o: 7748.69/2213.60/1107.00) lat (ms,95%): 17.32 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 772.26 qps: 15443.88 (r/w/o: 10810.42/3088.94/1544.52) lat (ms,95%): 12.52 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 770.30 qps: 15408.07 (r/w/o: 10786.15/3081.31/1540.61) lat (ms,95%): 12.52 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 591.62 qps: 11830.55 (r/w/o: 8280.82/2366.49/1183.24) lat (ms,95%): 11.04 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 1 tps: 754.00 qps: 15076.29 (r/w/o: 10552.76/3015.92/1507.61) lat (ms,95%): 15.27 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            976108
        write:                           278888
        other:                           139444
        total:                           1394440
    transactions:                        69722  (697.18 per sec.)
    queries:                             1394440 (13943.52 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      697.1761
    time elapsed:                        100.0063s
    total number of events:              69722
 
Latency (ms):
         min:                                    1.89
         avg:                                    5.73
         max:                                  486.36
         95th percentile:                       13.70
         sum:                               399718.65
 
Threads fairness:
    events (avg/stddev):           17430.5000/111.47
    execution time (avg/stddev):   99.9297/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  71303168 17 May 17:23 data/undo001
-rw-rw----  1 Valerii  staff  71303168 17 May 17:23 data/undo002
-rw-rw----  1 Valerii  staff  71303168 17 May 17:23 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 11351 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 11351 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 11351 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 11351 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 11351 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 11351 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/undo*
-rw-rw----  1 Valerii  staff  10485760 17 May 17:24 data/undo001
-rw-rw----  1 Valerii  staff  10485760 17 May 17:24 data/undo002
-rw-rw----  1 Valerii  staff  10485760 17 May 17:24 data/undo003
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo001 
 
File::data/undo001
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
      13	Undo log page
       8	Inode page
       0	Insert buffer free list page
     574	Freshly allocated page
       1	Insert buffer bitmap
      43	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 13
Undo page state: 0 active, 0 cached, 13 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo002 
 
File::data/undo002
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
      14	Undo log page
       8	Inode page
       0	Insert buffer free list page
     574	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 14
Undo page state: 0 active, 0 cached, 14 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/undo003 
 
File::data/undo003
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
       0	Index page
      14	Undo log page
       8	Inode page
       0	Insert buffer free list page
     574	Freshly allocated page
       1	Insert buffer bitmap
      42	System page
       0	Transaction system page
       1	File Space Header
       0	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 14
Undo page state: 0 active, 0 cached, 14 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
 
index_id	page_data_bytes_histgram(empty,...,oversized)
Yuliyas-Air:maria10.6 Valerii$ 

demonstrates the expected result of the fix. I still see few "to_purge" pages remaining, but most are freed when History list length goes down to 0, as expected.

Comment by Marko Mäkelä [ 2023-05-17 ]

valerii, there are two problems with your most recent test:

  1. I believe that using the setting innodb_undo_log_truncate=ON (which requires innodb_undo_tablespaces>1 to be set) will hide or work around this problem. Hence, the test is not good for validating this fix. You would have to pay attention to the maximum size of the undo00* files.
  2. The innochecksum invocation (when not using innodb_undo_log_truncate=ON) only works reliably if you have the fix of MDEV-31253 present and set the parameter --innodb-immediate-scrub-data-uncompressed=1. There could be some other tool for checking how many pages are actually allocated inside the data file.

Can you conduct some more tests that monitor the ibdata1 file size, as per the original description? If it is growing more than before MDEV-30671 was fixed, I believe that the remaining additional growth is inevitable and may be worked around by setting the parameters that were improved in MDEV-29401.

Comment by Daniel Ragle [ 2023-05-17 ]

In regards to this comment: "Users of multiple innodb_undo_tablespaces should be able to reclaim the space by setting innodb_undo_log_truncate=ON."

If this is in fact the same bug we saw, this is not true. I ran a 10.6.13 box throughout the past weekend with 4 undo table spaces and truncate=ON, and max size set to 750M. When I shut it down on Monday all the undo tables had grown to well over 1G; one of them was 11G (I don't remember all the individual totals, but remember the overall was over 20G in total). This was a read-only replica server.

IOW, I had to do a dump/rebuild to clear the tables. I did that all on Monday and reverted that machine to `10.6.12`. It's been running since late Monday (with the same replication stream) and so far the undo spaces are all at about 130M each, with ibdata1 at about 80M.

Comment by Valerii Kravchuk [ 2023-05-17 ]

Now back to my original test case, with UNDO in shared ibdata1. With the fix suggested Ive got the following after 2 runs of sysbench tests on the fresh datadir:

Yuliyas-Air:maria10.6 Valerii$ bin/mysqld_safe --no-defaults --innodb_flush_log_at_trx_commit=0 --innodb_buffer_pool_size=128M --innodb-immediate_scrub_data_uncompressed=1  &
[1] 56551
Yuliyas-Air:maria10.6 Valerii$ 230517 18:04:43 mysqld_safe Logging to '/Users/Valerii/dbs/maria10.6/data/Yuliyas-Air.err'.
230517 18:04:43 mysqld_safe Starting mariadbd daemon with databases from /Users/Valerii/dbs/maria10.6/data
 
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  12582912 17 May 18:03 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag_delay = 5000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'set global innodb_max_purge_lag = 500000'
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 6     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'create database sbtest'
Yuliyas-Air:maria10.6 Valerii$ cd -
/Users/Valerii/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 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 'sbtest3'
Inserting 100000 records into 'sbtest1'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest4'
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest2'...
Yuliyas-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 --report_interval=10 --time=100 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: 784.13 qps: 15689.24 (r/w/o: 10983.45/3137.13/1568.66) lat (ms,95%): 7.98 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 732.46 qps: 14647.55 (r/w/o: 10253.37/2929.25/1464.92) lat (ms,95%): 15.83 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 711.87 qps: 14238.53 (r/w/o: 9966.93/2847.87/1423.73) lat (ms,95%): 11.65 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 773.05 qps: 15460.59 (r/w/o: 10822.69/3091.80/1546.10) lat (ms,95%): 13.22 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 752.70 qps: 15054.81 (r/w/o: 10538.04/3011.38/1505.39) lat (ms,95%): 10.46 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 750.67 qps: 15013.17 (r/w/o: 10509.36/3002.47/1501.34) lat (ms,95%): 11.45 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 811.32 qps: 16225.32 (r/w/o: 11357.42/3245.26/1622.63) lat (ms,95%): 9.91 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 699.69 qps: 13994.94 (r/w/o: 9796.62/2798.95/1399.37) lat (ms,95%): 16.41 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 759.91 qps: 15196.86 (r/w/o: 10637.41/3039.63/1519.82) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 744.33 qps: 14886.09 (r/w/o: 10420.71/2976.72/1488.66) lat (ms,95%): 11.87 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            1052898
        write:                           300828
        other:                           150414
        total:                           1504140
    transactions:                        75207  (752.03 per sec.)
    queries:                             1504140 (15040.50 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      752.0252
    time elapsed:                        100.0060s
    total number of events:              75207
 
Latency (ms):
         min:                                    1.75
         avg:                                    5.32
         max:                                  727.88
         95th percentile:                       11.65
         sum:                               399733.43
 
Threads fairness:
    events (avg/stddev):           18801.7500/87.07
    execution time (avg/stddev):   99.9334/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 71950 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  1220542464 17 May 18:08 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     139	Index page
   71388	Undo log page
     842	Inode page
       0	Insert buffer free list page
    1986	Freshly allocated page
       5	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       4	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 71388
Undo page state: 5 active, 0 cached, 71383 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
23		19		19		73		15038
24		35		35		73		15038
25		42		42		73		15038
26		32		32		73		15038
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
23		0	0	0	0	0	0	0	0	0	0	19	0
24		0	0	0	0	0	0	0	0	0	0	35	0
25		0	0	0	0	0	0	0	0	0	0	42	0
26		0	0	0	0	0	0	0	0	0	0	32	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 55669 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 3038  |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  1220542464 17 May 18:09 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
      11	Index page
     423	Undo log page
     973	Inode page
       0	Insert buffer free list page
   72947	Freshly allocated page
       5	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       5	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 423
Undo page state: 0 active, 0 cached, 423 to_purge, 0 prepared, 0 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ cd -
/Users/Valerii/git/sysbench
Yuliyas-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 --report_interval=10 --time=100 cleanup
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Dropping table 'sbtest1'...
Dropping table 'sbtest2'...
Dropping table 'sbtest3'...
Dropping table 'sbtest4'...
Yuliyas-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 --report_interval=10 --time=100 prepare
sysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)
 
Initializing worker threads...
 
Creating table 'sbtest4'...Creating table 'sbtest2'...Creating table 'sbtest1'...Creating table 'sbtest3'...
 
 
 
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest1'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest4'...
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest3'...
Yuliyas-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 --report_interval=10 --time=100 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: 819.13 qps: 16387.17 (r/w/o: 11471.87/3276.63/1638.67) lat (ms,95%): 8.58 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 775.49 qps: 15508.42 (r/w/o: 10855.58/3101.86/1550.98) lat (ms,95%): 7.84 err/s: 0.00 reconn/s: 0.00
[ 30s ] thds: 4 tps: 681.57 qps: 13633.81 (r/w/o: 9544.18/2726.48/1363.14) lat (ms,95%): 12.75 err/s: 0.00 reconn/s: 0.00
[ 40s ] thds: 4 tps: 470.61 qps: 9412.66 (r/w/o: 6589.22/1882.23/941.22) lat (ms,95%): 20.74 err/s: 0.00 reconn/s: 0.00
[ 50s ] thds: 4 tps: 443.27 qps: 8861.61 (r/w/o: 6201.72/1773.46/886.43) lat (ms,95%): 18.61 err/s: 0.00 reconn/s: 0.00
[ 60s ] thds: 4 tps: 635.23 qps: 12705.13 (r/w/o: 8894.07/2540.51/1270.55) lat (ms,95%): 14.21 err/s: 0.00 reconn/s: 0.00
[ 70s ] thds: 4 tps: 810.99 qps: 16223.54 (r/w/o: 11356.99/3244.57/1621.98) lat (ms,95%): 8.43 err/s: 0.00 reconn/s: 0.00
[ 80s ] thds: 4 tps: 704.00 qps: 14079.39 (r/w/o: 9855.59/2815.80/1408.00) lat (ms,95%): 15.55 err/s: 0.00 reconn/s: 0.00
[ 90s ] thds: 4 tps: 780.59 qps: 15610.61 (r/w/o: 10927.47/3121.96/1561.18) lat (ms,95%): 10.46 err/s: 0.00 reconn/s: 0.00
[ 100s ] thds: 4 tps: 818.28 qps: 16366.57 (r/w/o: 11456.87/3273.13/1636.57) lat (ms,95%): 10.65 err/s: 0.00 reconn/s: 0.00
SQL statistics:
    queries performed:
        read:                            971572
        write:                           277592
        other:                           138796
        total:                           1387960
    transactions:                        69398  (693.95 per sec.)
    queries:                             1387960 (13878.95 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
Throughput:
    events/s (eps):                      693.9477
    time elapsed:                        100.0046s
    total number of events:              69398
 
Latency (ms):
         min:                                    1.83
         avg:                                    5.76
         max:                                  738.14
         95th percentile:                       13.22
         sum:                               399746.31
 
Threads fairness:
    events (avg/stddev):           17349.5000/103.55
    execution time (avg/stddev):   99.9366/0.00
 
Yuliyas-Air:sysbench Valerii$ cd -
/Users/Valerii/dbs/maria10.6
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  1220542464 17 May 18:11 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 67410 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 67410 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 67410 |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
     139	Index page
   65213	Undo log page
     820	Inode page
       0	Insert buffer free list page
    8183	Freshly allocated page
       5	Insert buffer bitmap
     130	System page
       1	Transaction system page
       1	File Space Header
       4	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 65213
Undo page state: 0 active, 0 cached, 64943 to_purge, 0 prepared, 270 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
31		29		29		73		15038
32		36		36		73		15038
33		21		21		73		15038
34		34		34		73		15038
35		3		3		1182		15370
37		3		2		836		11035
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
31		0	0	0	0	0	0	0	0	0	0	29	0
32		0	0	0	0	0	0	0	0	0	0	36	0
33		0	0	0	0	0	0	0	0	0	0	21	0
34		0	0	0	0	0	0	0	0	0	0	34	0
35		0	0	0	0	0	0	0	0	0	0	3	0
37		0	0	1	0	0	0	0	0	0	0	2	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ bin/mysql -e 'show global status like "innodb_%history%"'
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_history_list_length | 0     |
+----------------------------+-------+
Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1 
-rw-rw----  1 Valerii  staff  1220542464 17 May 18:12 data/ibdata1
Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1 
 
File::data/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT	PAGE_TYPE
===============================================
      11	Index page
     789	Undo log page
     935	Inode page
       0	Insert buffer free list page
   72607	Freshly allocated page
       5	Insert buffer bitmap
     138	System page
       1	Transaction system page
       2	File Space Header
       8	Extent descriptor page
       0	BLOB page
       0	Compressed BLOB page
       0	Page compressed page
       0	Page compressed encrypted page
       0	Other type of page
 
===============================================
Additional information:
Undo page type: 789
Undo page state: 0 active, 0 cached, 787 to_purge, 0 prepared, 2 other
index_id	#pages		#leaf_pages	#recs_per_page	#bytes_per_page
1		1		1		11		859
2		1		1		50		3173
3		1		1		20		1442
4		1		1		29		1246
5		1		1		11		364
11		1		1		0		0
12		1		1		0		0
13		1		1		0		0
14		1		1		0		0
15		1		1		0		0
-4294967296		1		1		0		0
 
index_id	page_data_bytes_histgram(empty,...,oversized)
1		0	1	0	0	0	0	0	0	0	0	0	0
2		0	0	1	0	0	0	0	0	0	0	0	0
3		0	1	0	0	0	0	0	0	0	0	0	0
4		0	1	0	0	0	0	0	0	0	0	0	0
5		0	1	0	0	0	0	0	0	0	0	0	0
11		1	0	0	0	0	0	0	0	0	0	0	0
12		1	0	0	0	0	0	0	0	0	0	0	0
13		1	0	0	0	0	0	0	0	0	0	0	0
14		1	0	0	0	0	0	0	0	0	0	0	0
15		1	0	0	0	0	0	0	0	0	0	0	0
-4294967296		1	0	0	0	0	0	0	0	0	0	0	0
Yuliyas-Air:maria10.6 Valerii$ 

From the above, basically, as soon as History list length goes down to 0, almost all UNDO pages are freed and ibdata1 does NOT grow indefinitely with every test any more, only up to the largest amount of UNDO needed at some time.

Two concerns remain:

1. Still some small number of "to_purge" pages are reported, maybe that's about the missing fix to the innochecksum utility.

2. Performance. 694 TPS with the fix while originally I had 1085 TPS with 10.6.13.

Comment by Marko Mäkelä [ 2023-05-17 ]

dragle, your observation may be related to a different bug that we are unable to reproduce so far. It would be interesting to know what is preventing the undo tablespace truncation from taking place. Did you observe the history list length?

Comment by Marko Mäkelä [ 2023-05-17 ]

valerii, was your observed performance drop due to --innodb-immediate-scrub-data-uncompressed=1 (MDEV-8139)? That parameter is basically disabling an optimization that was improved in MDEV-15528.

Comment by Valerii Kravchuk [ 2023-05-17 ]

Even without --innodb-immediate-scrub-data-uncompressed=1 (see https://jira.mariadb.org/browse/MDEV-31234?focusedCommentId=258889&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-258889), I've got ~748 TPS (with undo spaces), while previously (see https://jira.mariadb.org/browse/MDEV-31234?focusedCommentId=258352&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-258352) I had 905 TPS.

Not that I tried many times or the comparison is clean, but as I had values printed every 10 seconds it was NOT just a random or temporary difference. I suspect a trend here.

Comment by Daniel Ragle [ 2023-05-18 ]

The History List Length fluctuated seemingly normally throughout the weekend; in fact it was mostly zero, especially once the Replica caught up with the Master. On Saturday as the Undo Tablespaces were growing I tried a few guesses to get the spaces to clear; including these, but nothing reduced them, they continued to grow.

Set innodb_purge_rseg_truncate_frequency = 1.
Set innodb_max_purge_lag_wait=0 (it returned nearly immediately).
Stop both slave threads and wait for several minutes.
Set innodb_max_purge_lag and innodb_max_purge_lag_delay.
Stop/start the server (with innodb_fast_shutdown=0).

My settings when I gave up on Monday were:

innodb_max_purge_lag=1000
innodb_max_purge_lag_delay=5000
innodb_max_undo_log_size=750M
innodb_undo_tablespaces=4
innodb_undo_log_truncate=ON

Perhaps of note, I left these settings in place when I reverted to 10.6.12 and the replica could then not keep up--not even close, it was consistently getting farther behind. I had to reset innodb_max_purge_lag and innodb_max_purge_lag_delay back to their defaults for the replica to keep up again. (But with those same settings on 10.6.13 replication kept up without a problem).

I'll play with it a little more on a virtual system this morning and see if I can come up with anything further.

Comment by Daniel Ragle [ 2023-05-18 ]

I'm able to recreate the issue in a virtual environment. Here's what I did.

Create this table:

CREATE TABLE undo_test (
    id INT(10) UNSIGNED NOT NULL AUTO_INCREMENT,
    process_date DATE NOT NULL,
    flag1 TINYINT(1) UNSIGNED NOT NULL,
    flag2 TINYINT(1) UNSIGNED NOT NULL,
    label varchar(20) NOT NULL,
    PRIMARY KEY (id),
    KEY procdate (process_date),
    KEY flag1 (flag1),
    KEY flag2 (flag2)
) ENGINE=InnoDB ROW_FORMAT=DYNAMIC;

and fill it with 1 million random records (flags set randomly to 1 or 0; process_date set to 10 different dates sequentially, I.E., 100,000 records for each date, and label set to 20 random characters a .. z A .. Z 0 .. 9).

Now setup two threads to run simultaneously. The first alternates back and forth between a full table update:

        UPDATE undo_test
            SET flag1 = IF ( flag1 = 0, 1, 0 ),
                flag2 = IF ( flag2 = 0, 1, 0 )

and when that query completes the thread then proceeds to update about 30,000 records individually (one-at-a-time), using the same query as above only with a single ID specified. Basically it selects the records via:

SELECT id FROM undo_test WHERE label LIKE 'a%'

SELECT id FROM undo_test WHERE label LIKE 'b%'

etc. So update the whole table with a single query, update one-at-a-time the approximately 30,000 records where label LIKE 'a%', update the whole table with the single query, update the approximately 30,000 records where label LIKE 'b%', etc. When we hit '9%' we just repeat.

In the second thread, I performed this sequence repeatedly:

1. Delete the oldest records in the table 10,000 records at a time until they are all gone.

DELETE FROM velocitynorep.undo_test WHERE process_date = '2023-05-17' LIMIT 10000;

2. Insert a new set of 100,000 randomly generated records with the next available date.

3. Execute a transaction (which only queries records; this is with isolation level=REPEATABLE READ):

START TRANSACTION;
SELECT label, flag1, flag2 FROM undo_test WHERE flag1 = 1 AND flag2 = 1;
SELECT label, flag1, flag2 FROM undo_test WHERE flag1 = 0 AND flag2 = 0;
SELECT label, flag1, flag2 FROM undo_test WHERE flag1 = 0 AND flag2 = 1;
SELECT label, flag1, flag2 FROM undo_test WHERE flag1 = 1 AND flag2 = 0;
COMMIT;

In between each SELECT I slept 10 seconds, so the whole transaction lasts 40 seconds.

These settings for undo table spaces:

innodb_max_undo_log_size=500M
innodb_undo_tablespaces=4
innodb_undo_log_truncate=ON

While the two update threads were running, I ran a separate monitor that reported the history length and the size of the four undo tables once every 5 seconds:

SELECT FILE_SIZE FROM information_schema.INNODB_SYS_TABLESPACES WHERE NAME = "innodb_undo001";
SELECT FILE_SIZE FROM information_schema.INNODB_SYS_TABLESPACES WHERE NAME = "innodb_undo002";
SELECT FILE_SIZE FROM information_schema.INNODB_SYS_TABLESPACES WHERE NAME = "innodb_undo003";
SELECT FILE_SIZE FROM information_schema.INNODB_SYS_TABLESPACES WHERE NAME = "innodb_undo004";
SELECT count FROM information_schema.INNODB_METRICS WHERE name = 'trx_rseg_history_len';

On 10.6.13, after about an hour of the two queries running, the four undo tables were all over 500M (the rest over 600M, one over 1G). The history length fluctuated, generally averaging in the 20k-30k range; I did see it hit zero twice (and probably more, since I was only polling every 5 seconds). After the hour I stopped the two update threads, the History Length returned to zero immediately. I then started a thread that simply updates one of the records (using the same query above) every 2 seconds. I.E., to simulate a trickle of updates. I waited 5 minutes. The History Length remained at one or zero the entire time, but the undo tables remained at their full size (but did not grow further).

Note that on 10.6.13 I had to innodb_monitor_enable=trx_rseg_history_len to get the history length to be reported in INNODB_METRICS.

I stopped and started the DB (with innodb_fast_shutdown=0). Started the trickle thread. Waited another 5 minutes. The undo tables remained at their full size (but did not grow further).

I executed:

SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
SET GLOBAL innodb_max_purge_lag_wait=0;

And waited another 5 minutes. Again, The undo tables remained at their full size (but did not grow further).

I dumped and reinitialized InnoDB and repeated the entire test a second time, with the same results.

Interestingly, in each of the two tests on 10.6.13, one of the undo spaces stopped growing after about 20 minutes, while the other three continued to grow for the full time. But even the one that stopped growing had exceeded 500M before it stopped.

As I write, I'm repeating the test using 10.6.12 (the only change was that I had to query the size of the tables from the FS instead of innodb_sys_tablespaces). So far it's been running about 40 minutes, but the largest undo table is only a little over 100M. The tables are definitely not growing anywhere near the rate they did on 10.6.13.

As I'm new to the truncation parameters, it may be helpful for me to know exactly when the tables should truncate. I.E., does it require a DB restart? Or can it happen while the DB is running? I did stop/start the DB as part of the test, and the tables were not reduced, but going forward it will be helpful to know when I should expect the reduction to happen.

Comment by Daniel Ragle [ 2023-05-18 ]

After running the test on 10.6.12 for about two hours, the four undo spaces had only grown to a little over 100M. I stopped the test at that point.

And looks like I answered my own question: I reset the test on 10.6.12 with innodb_max_undo_log_size=20M, and sure enough all four of the tables truncated at some point after they exceeded 20M, no restart required. It didn't happen immediately, since the system was busy with the queries I outlined earlier, but usually within 1 minute of them exceeding the max size.

Comment by Marko Mäkelä [ 2023-05-19 ]

dragle, between 10.6.12 and 10.6.13 there were multiple changes related to undo logs. The innodb_max_purge_lag and innodb_max_purge_lag_delay were improved in MDEV-29401. MDEV-29593 should reduce the growth of undo log tablespaces and improve performance when there are lots of small transactions. MDEV-26782 is a similar change that affects undo logs for temporary tables.

MDEV-30671 (which caused this bug) fixes corruption caused by premature purging of history. In a server where both MDEV-30671 and this MDEV-31234 have been fixed, I could expect that the history list is longer than it used to be, because the unsafe (too early) purging has been blocked. Without the fix of MDEV-31234, the history list length could reach 0 even though something could not be freed due to the rseg.needs_purge condition. The undo tablespace truncation should still be blocked in this case. Having fewer long-running transactions or old read views could help here.

The need to execute innodb_monitor_enable=trx_rseg_history_len is an unintentional regression that I will file and fix. This could also be accessed via a status variable that was added in MDEV-18582 quite a while ago.

Comment by Marko Mäkelä [ 2023-05-19 ]

MDEV-31308 covers the accidentally disabled monitor counter.

Comment by Matthias Leich [ 2023-05-19 ]

origin/bb-10.6-MDEV-31234 1e1e0e98080faf23a2a1ff78bae1df60340f1183 2023-05-17T17:44:35+03:00
build type: RelWithDebInfo
behaved well in RQG testing. The bad effects observed occur when testing other trees too.

Comment by Marko Mäkelä [ 2023-05-19 ]

In case someone wants to test a development snapshot with this fix, here you will for some time find packages to download (once the builds complete):
10.5: https://ci.mariadb.org/35151/
10.6: https://ci.mariadb.org/35153/

dragle, I would appreciate your feedback on this.

Comment by Marko Mäkelä [ 2023-05-19 ]

dragle, "your" bugs MDEV-31308 and MDEV-31309 are fixed in https://ci.mariadb.org/35168/

Comment by Daniel Ragle [ 2023-05-19 ]

Thank you. I've been working with this today. I can confirm that undo table spaces are now getting truncated when they exceed the max size setting, that's great.

But I'm still confused about what I'm seeing in testing.

This knowledge would probably help me. The documentation says "InnoDB keeps a list of transactions with delete-marked index records due to UPDATE and DELETE statements. The length of this list is purge_lag ...". That's not the same as the History Length List, right? Is there a way for me to report the current "purge_lag"?

Comment by Marko Mäkelä [ 2023-05-22 ]

dragle, the innodb_max_purge_lag and innodb_max_purge_lag_wait are measured in the same unit as the length of the history list: number of committed or rolled back transactions whose history needs to be purged. Starting with MDEV-12288 (when not using the MDEV-515 bulk insert mechanism), also INSERT operations will be followed by a purge of history.

Before MariaDB Server 10.3, there were two persistent undo logs: one for inserts and another for updates or deletes (or inserts that replaced a previously delete-marked purgeable record). Moving to a single undo log in MDEV-12288 fixed the infamous MySQL Bug #55283 in MariaDB Server if MariaDB ever was affected by that.

Comment by Marko Mäkelä [ 2023-05-22 ]

I tested innodb_undo_log_truncate=ON once more. When the database is initialized using a server version that includes this fix, the undo log tablespaces will be truncated just fine.

If I initialize the database using an affected release (I used MariaDB Server 10.6.13), run some workload, and then upgrade to a server that contains the fix, the undo tablespaces will not be truncated. I am investigating the exact root cause and will see if it is possible to fix this.

Comment by Marko Mäkelä [ 2023-05-22 ]

The following sanity check will prevent undo tablespaces from being truncated if they contain undo log pages that were not freed due to this bug:

diff --git a/storage/innobase/trx/trx0purge.cc b/storage/innobase/trx/trx0purge.cc
index 6541ede447e..cd070a77859 100644
--- a/storage/innobase/trx/trx0purge.cc
+++ b/storage/innobase/trx/trx0purge.cc
@@ -664,9 +664,6 @@ TRANSACTIONAL_TARGET static void trx_purge_truncate_history()
       }
 
       ut_ad(rseg.curr_size > cached);
-      if (rseg.curr_size > cached + 1)
-        goto not_free;
-
       rseg.latch.rd_unlock();
     }
 

The rseg.curr_size reflects the field TRX_RSEG_HISTORY_SIZE in the rollback segment header. Due to the bug in the fix of MDEV-30671, trx_purge_truncate_rseg_history() would remove entries from the TRX_RSEG_HISTORY list without subtracting the length of TRX_UNDO_PAGE_LIST from TRX_RSEG_HISTORY_SIZE. That is, the rseg.history_size or the history list length would be shrunk prematurely, and if freeing of the undo log pages was deemed unsafe, we would simply never free the pages.

When this unnecessarily strict sanity fix is removed, I can observe that after an upgrade from an affected build, and starting a workload, the undo tablespaces will be truncated in a round-robin fashion, starting from the first undo tablespace whose size exceeds the specified (soft) max_undo_log_size.

After some more testing, I will push a follow-up fix.

Comment by Marko Mäkelä [ 2023-05-22 ]

I realized that simply removing the condition would break existing undo log truncation tests. I was thinking that a safer fix for upgrades must require a special invocation with SET GLOBAL innodb_undo_log_truncate=ON, innodb_fast_shutdown=0; followed by shutdown.

However, it later turned out that this may be unsafe. The test innodb.undo_truncate_recover would occasionally hit a debug assertion failure when using this type of a fix.

Comment by Marko Mäkelä [ 2023-05-22 ]

Sorry for the back and forth.

I overlooked the fact that my attempt to allow undo log truncation to work after an upgrade will cause the test innodb.undo_log_truncate to occasionally fail, only on 10.6 but not 10.5. On my local system, I had built and tested a Debug version of 10.5 but only a RelWithDebInfo of 10.6. My bad.

A working solution for truncating the undo logs that were contaminated by this bug is to make use of MDEV-19229:

  1. Shut down the server with innodb_fast_shutdown=0 so that the undo logs will be empty.
  2. Restart with a different innodb_undo_tablespaces, so that the undo log tablespaces will be created from the scratch. I tested this on a 10.6 Enterprise Server build that includes MDEV-19229.
Comment by Marko Mäkelä [ 2023-05-23 ]

Because MDEV-19229 will not be available to many affected users, I debugged my attempted upgrade fix deeper. The test innodb.undo_truncate_recover is inserting 30,000 rows into a table and then updating each row twice. Between the user transaction commit and the undo tablespace truncation, there had not been enough calls to the function row_purge(). So, the test revealed a real problem, which could have been caught by the MDEV-24402 CHECK TABLE…EXTENDED.

The good news is that with a small tweak, both the test will pass (row_purge() will be executed for all 90,000 rows) and the undo log truncate after an upgrade from a release that is affected by this bug is possible:

diff --git a/storage/innobase/trx/trx0purge.cc b/storage/innobase/trx/trx0purge.cc
index e8d81ff49cd..583a603e69e 100644
--- a/storage/innobase/trx/trx0purge.cc
+++ b/storage/innobase/trx/trx0purge.cc
@@ -664,7 +664,8 @@ TRANSACTIONAL_TARGET static void trx_purge_truncate_history()
       }
 
       ut_ad(rseg.curr_size > cached);
-      if (rseg.curr_size > cached + 1)
+      if (rseg.curr_size > cached + 1 &&
+          (rseg.history_size || srv_fast_shutdown || srv_undo_sources))
         goto not_free;
 
       rseg.latch.rd_unlock();

The added condition on rseg.history_size will ensure that the purge of history will run to completion on each rollback segment in the undo tablespace before the tablespace will be truncated.

With the above patch, some undo log tablespaces that had been created with MariaDB Server 10.6.13 could be truncated again. The minimal procedure for this is as follows, provided that the server was running with innodb_undo_tablespaces=2 or more:

--error ER_DUP_ENTRY
INSERT INTO mysql.innodb_table_stats values('','',default,0,0,0),('','',default,0,0,0);
SET GLOBAL innodb_undo_log_truncate=ON, innodb_fast_shutdown=0;
SHUTDOWN;

The purpose of the INSERT statement is to create a dummy InnoDB transaction that will be rolled back due to a duplicate key error. It ensures that there will be some history to purge during shutdown. If there had been a prior shutdown with innodb_fast_shutdown=0, also this slow shutdown would not process any undo logs and the undo tablespace files would not be truncated.

Comment by Marko Mäkelä [ 2023-05-23 ]

I pushed the upgrade fix.

Comment by Dominik Shaim [ 2023-05-23 ]

When will be approximately published official/regular update mariadb 10.6.14?

This critical issue is causing growing ibdata1 approximately 50 GB per day.. So disaster seriously...

Comment by Ralf Gebhardt [ 2023-05-23 ]

shaim, you can find the planned dates for next releases here: https://jira.mariadb.org/projects/MDEV?selectedItem=com.atlassian.jira.jira-projects-plugin:release-page&status=unreleased

Comment by Dominik Shaim [ 2023-05-23 ]

Ralf, I know this, but this is critical update, it must be published ASAP, 2023/07/27 is really too late, ibdata1 is growing 50GB per day...

Comment by Manuel Arostegui [ 2023-05-23 ]

I agree with shaim this looks critical enough (we are not affected though, but I can totally understand how it must feel if you are)

Comment by Marcin Wanat [ 2023-05-25 ]

I agree with Dominik too. This bug is so critical that make this release unusable on production. We were hit by this bug too after our undo logs grew to few TB within few days.

If someone have separate undo logs (innodb_undo_tablespaces) then temporary solution is to set innodb_fast_shutdown=0, shutdown server and change value of innodb_undo_tablespaces before starting server again. This will force MariaDB to clear all previous undo logs.

Comment by Marko Mäkelä [ 2023-06-01 ]

I filed MDEV-31382 for the anomaly that I noticed (and worked around with the dummy INSERT transaction) in my suggested upgrade procedure:

--error ER_DUP_ENTRY
INSERT INTO mysql.innodb_table_stats values('','',default,0,0,0),('','',default,0,0,0);
SET GLOBAL innodb_undo_log_truncate=ON, innodb_fast_shutdown=0;
SHUTDOWN;

This should help users of innodb_undo_tablespaces>1 to reclaim space after running an affected version.

Yesterday, MDEV-31376 was filed for unscheduled releases, to address this and some other regressions.

Comment by Marcin Wanat [ 2023-06-01 ]

marko Just letting you know that on 10.11.3 when setting innodb_undo_log_truncate=ON, it results in one undo log file to stop growing (and modification time stop changing), but remaining ones will still grow indefinitely. It looks like MariaDB try to clean this file, but this never finish resulting in server using only remaining undo files.

Comment by Marko Mäkelä [ 2023-06-01 ]

forke, yes, that is one of the symptoms of this bug. One undo log tablespace would be chosen for truncation, but the truncation would never complete due to this bug. A challenge for debugging and fixing this bug was that much of the time (including during the two regression tests), the undo log truncation would work just fine. Only under more write intensive workload (enough concurrent connections doing writes) the bug would appear. During stress testing using random SQL, I do not think it is feasible to monitor database file sizes, because the workloads are going to be so random. Until recently, our internal performance tests did not monitor the file sizes, so this serious regression was not detected in time.

Comment by Stephan Vos [ 2023-06-06 ]

@Marko Mäkelä, would upgrading from 10.5.17 to 10.5.20 cause us to have this issue as well?
We have innodb_undo_tablespaces=0 and it seems that if you hit the issue(bug) with this setting then you are basically stuck?

Comment by Christopher Mähler [ 2023-06-07 ]

Ok, this critical bug will not be fixed with the next release? We really have to wait for the next Q3 releases (2023-07-27)?

Comment by Stephan Vos [ 2023-06-07 ]

It seems if you have the issue and innodb_undo_tablespaces=0 then you are basically stuck and have to dump and recreate the database.
If not then there seems to be away of temporarily fixing it until you can either downgrade or upgrade to the fix version.

I will skip 10.5.20 as the risk for encountering this is much too great and upgrade to 10.5.19 and then to the fix version after that.

Comment by Stephan Vos [ 2023-06-07 ]

Christopher Mähler I see it has been fixed in 10.5.21 and 10.6.14 which has been released today.

Comment by Marcin Wanat [ 2023-06-07 ]

marko, we are testing just released 10.11.4. It looks like UNDO logs still grow indefinitely with innodb_undo_log_truncate = OFF.
With innodb_undo_log_truncate = ON undo logs are 10MB most of the time time, but performance penalty is huge (128 core server with 30 replication threads has trouble keeping up with ROW based replication, simple updates often take more than 1 second.

Also when we have innodb_undo_log_truncate = OFF and undo logs grow to few GB each, and then we change it to innodb_undo_log_truncate = ON, then server hangs completely - all threads are filled with unfinished transactions. Even SHOW GLOBAL STATUS or SHOW ENGINE INNODB STATUS:

MariaDB [(none)]> SHOW PROCESSLIST;
+---------+-------------+---------------------------+---------+--------------+------+---------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
| Id      | User        | Host                      | db      | Command      | Time | State                                                                     | Info                                                                                                 | Progress |
+---------+-------------+---------------------------+---------+--------------+------+---------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+
| 1254146 | pmm         | localhost:62740           | NULL    | Query        |  124 | Filling schema table                                                      | SHOW GLOBAL STATUS                                                                                   |    0.000 |
| 1254148 | pmm         | localhost:62752           | NULL    | Query        |  121 | starting                                                                  | SHOW ENGINE INNODB STATUS                                                                            |    0.000 |
| 1254149 | pmm         | localhost:62768           | NULL    | Query        |  119 | Filling schema table                                                      | SHOW GLOBAL STATUS                                                                                   |    0.000 |
| 1254152 | pmm         | localhost:14546           | NULL    | Query        |  114 | Filling schema table                                                      | SHOW GLOBAL STATUS                                                                                   |    0.000 |
| 1254153 | pmm         | localhost:14550           | NULL    | Query        |  111 | starting                                                                  | SHOW ENGINE INNODB STATUS                                                                            |    0.000 |
| 1254247 | root        | localhost                 | NULL    | Query        |    0 | starting                                                                  | SHOW PROCESSLIST                                                                                     |    0.000 |
+---------+-------------+---------------------------+---------+--------------+------+---------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+----------+

Server is hanged now for over 15minutes with one core 100% usage and nothing else.
Last entry in err log is:
2023-06-07 20:04:45 0 [Note] InnoDB: Truncating .//undo007

Comment by Marcin Wanat [ 2023-06-08 ]

Update: With 10.11.4, undo logs finally stopped growing and are now at 50GB, so the problem with undo logs growing indefinitely looks like fixed with this release.
But the problem with server hanging completely when enabling innodb_undo_log_truncate = ON when logs are already huge still exists, but it is not as critical as previous bug.

Comment by Stephan Vos [ 2023-06-08 ]

So can we then safely upgrade to this version (10.5.21) if our current version (10.5.17) did not have this bug?

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

forke, can you file a new bug with stack traces of the server during the hang? We fixed one hang in MDEV-31343. A fix of the bug MDEV-31355 was not included in these releases; that could be helpful.

stephanvos, the special upgrade procedure (with slow shutdown) is needed only for upgrading from a version that is listed in "Affects Version/s".

Comment by Gerwin [ 2023-07-19 ]

It should be fixed in 10.6.14. But in our situation it's not in the Shared table space. The undo files keep growing and are not truncated. Is this related?

innodb_max_undo_log_size 1073741824
innodb_undo_tablespaces 6

-rw-r-----. 1 mysql mysql  42G Jul 19 05:12 undo006
-rw-r-----. 1 mysql mysql  26G Jul 19 09:57 undo002
-rw-r-----. 1 mysql mysql  21G Jul 19 09:57 undo003
-rw-r-----. 1 mysql mysql  13G Jul 19 09:57 undo004
-rw-r-----. 1 mysql mysql 1.8G Jul 19 09:57 undo005
-rw-r-----. 1 mysql mysql  34G Jul 19 09:57 undo001

Comment by Marcin Wanat [ 2023-07-19 ]

rodehoed We have experienced the same issue on 10.6.14 with one slave with the greatest load. For some reason max undo logs history grows indefinitely and mariadb never clean it despite that we have no single transaction running for more than 10sec.
We have found temporary solution:
Every 6 hours we run script with STOP SLAVE; wait 60sec, START SLAVE;
During these 60sec MariaDB starts cleaning old undo logs and prevent from undo logs growing indefinitely.
I hope that problems with undo logs will be finally fixed in upcoming release.

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

rodehoed, the innodb_max_undo_log_size is only a soft limit. Nothing can be purged if it is not safe to do so; in fact, the check that was implemented in MDEV-30671 turned out to be insufficient, and MDEV-31355 revised it further.

There is a known open issue MDEV-30628 which may be explained by the fact that the purge of committed transaction history can’t keep up with high-concurrency write workloads. MDEV-29401 improved an existing DML throttling mechanism, to help reduce the history list size. Did you try setting those parameters?

You might also be impacted by MDEV-31382.

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