Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
10.11.1, 10.5.20, 10.6.13, 10.8.7, 10.9.6, 10.10.3
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
|
...
|
Attachments
Issue Links
- is caused by
-
-
- Closed
-
- is part of
-
MDEV-31376 prepare Q2.1 release (10.5–11.1)
-
- Closed
-
- relates to
-
-
- Stalled
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(4 relates to)
Activity
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$
|
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.
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).
I can confirm this on MariaDB 10.6.13. A huge number of undo log pages will remain despite the slow shutdown.
I can confirm that the fix of MDEV-30671 introduced this. I think that also the 10.5.19 release should be affected.
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.
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).
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.
I filed MDEV-31253 for the scrubbing bug that caused the false alarm.
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.
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
|
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.
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.
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.
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.
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.
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.
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.
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.
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.
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.
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.
valerii, there are two problems with your most recent test:
- 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.
- The innochecksum invocation (when not using innodb_undo_log_truncate=ON) only works reliably if you have the fix of
MDEV-31253present 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.
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.
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.
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?
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.
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.
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.
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.
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.
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.
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.
|
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.
dragle, "your" bugs MDEV-31308 and MDEV-31309 are fixed in https://ci.mariadb.org/35168/
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"?
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.
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.
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.
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.
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:
- Shut down the server with innodb_fast_shutdown=0 so that the undo logs will be empty.
- 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.
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.
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...
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
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...
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)
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.
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.
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.
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.
@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?
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)?
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.
Christopher Mähler I see it has been fixed in 10.5.21 and 10.6.14 which has been released today.
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
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.
So can we then safely upgrade to this version (10.5.21) if our current version (10.5.17) did not have this bug?
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".
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 |
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.
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.
Same story with 10.6.14 as of today:
Yuliyas-Air:server Valerii$ git log -1commit 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 -0400bump the VERSIONwith tuning suggested in the (fixed)
MDEV-29401applied:Yuliyas-Air:~ Valerii$ cd dbs/maria10.6Yuliyas-Air:maria10.6 Valerii$ rm -rf data/Yuliyas-Air:maria10.6 Valerii$ scripts/mysql_install_db --no-defaultsInstalling 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 256OKTo start mariadbd at boot time you have to copysupport-files/mariadb.service to the right place for your systemTwo all-privilege accounts were created.One is root@localhost, it has no password, but you need tobe system 'root' user to connect. Use, for example, sudo mysqlThe second is Valerii@localhost, it has no password either, butyou need to be the system 'Valerii' user to connect.After connecting you can set the password, if you would need to beable to connect as any of these users with a password and without sudoSee the MariaDB Knowledgebase at https://mariadb.com/kbYou can start the MariaDB daemon with:cd '.' ; ./bin/mariadb-safe --datadir='./data'You can test the MariaDB daemon with mysql-test-run.plcd './mysql-test' ; perl mariadb-test-run.plPlease report any problems at https://mariadb.org/jiraThe 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] 3387Yuliyas-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/dataYuliyas-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 preparesysbench 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 moduleYuliyas-Air:maria10.6 Valerii$ cd ~/git/sysbenchYuliyas-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 preparesysbench 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 runsysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)Running the test with following options:Number of threads: 4Report intermediate results every 10 second(s)Initializing random number generator from current timeInitializing 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.00SQL statistics:queries performed:read: 1500254write: 428644other: 214322total: 2143220transactions: 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.5848time elapsed: 100.0023stotal number of events: 107161Latency (ms):min: 1.81avg: 3.73max: 108.7495th percentile: 5.28sum: 399637.95Threads fairness:events (avg/stddev): 26790.2500/49.49execution time (avg/stddev): 99.9095/0.00Yuliyas-Air:sysbench Valerii$ cd -/Users/Valerii/dbs/maria10.6Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1-rw-rw---- 1 Valerii staff 79691776 10 May 18:29 data/ibdata1Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================136 Index page3029 Undo log page34 Inode page0 Insert buffer free list page1532 Freshly allocated page1 Insert buffer bitmap130 System page1 Transaction system page1 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 3029Undo page state: 3 active, 128 cached, 2602 to_purge, 0 prepared, 296 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 023 21 21 73 1503824 39 39 73 1503825 12 12 73 1503826 33 33 73 1503827 8 8 831 1081428 3 3 789 1025729 5 5 960 1248030 4 4 900 11706-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 023 0 0 0 0 0 0 0 0 0 0 21 024 0 0 0 0 0 0 0 0 0 0 39 025 0 0 0 0 0 0 0 0 0 0 12 026 0 0 0 0 0 0 0 0 0 0 33 027 0 0 0 0 0 4 1 0 0 0 3 028 0 0 0 0 0 2 0 0 0 0 1 029 0 0 0 0 0 2 0 0 0 0 3 030 0 0 0 0 0 2 0 0 0 0 2 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-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/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================136 Index page3029 Undo log page34 Inode page0 Insert buffer free list page1532 Freshly allocated page1 Insert buffer bitmap130 System page1 Transaction system page1 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 3029Undo page state: 3 active, 128 cached, 2602 to_purge, 0 prepared, 296 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 023 21 21 73 1503824 39 39 73 1503825 12 12 73 1503826 33 33 73 1503827 8 8 831 1081428 3 3 789 1025729 5 5 960 1248030 4 4 900 11706-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 023 0 0 0 0 0 0 0 0 0 0 21 024 0 0 0 0 0 0 0 0 0 0 39 025 0 0 0 0 0 0 0 0 0 0 12 026 0 0 0 0 0 0 0 0 0 0 33 027 0 0 0 0 0 4 1 0 0 0 3 028 0 0 0 0 0 2 0 0 0 0 1 029 0 0 0 0 0 2 0 0 0 0 3 030 0 0 0 0 0 2 0 0 0 0 2 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-Air:maria10.6 Valerii$ cd -/Users/Valerii/git/sysbenchYuliyas-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 cleanupsysbench 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 preparesysbench 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 runsysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)Running the test with following options:Number of threads: 4Report intermediate results every 10 second(s)Initializing random number generator from current timeInitializing 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.00SQL statistics:queries performed:read: 1369662write: 391332other: 195666total: 1956660transactions: 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.2843time elapsed: 100.0047stotal number of events: 97833Latency (ms):min: 1.97avg: 4.09max: 165.8795th percentile: 7.04sum: 399666.97Threads fairness:events (avg/stddev): 24458.2500/69.78execution time (avg/stddev): 99.9167/0.00Yuliyas-Air:sysbench Valerii$ cd -/Users/Valerii/dbs/maria10.6Yuliyas-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/ibdata1Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================132 Index page6127 Undo log page73 Inode page0 Insert buffer free list page2490 Freshly allocated page3 Insert buffer bitmap131 System page1 Transaction system page3 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 6127Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 031 23 23 73 1503832 34 34 73 1503833 15 15 73 1503834 21 21 73 1503835 1 1 620 806036 7 7 698 908337 11 11 789 1025738 1 1 1191 15483-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 031 0 0 0 0 0 0 0 0 0 0 23 032 0 0 0 0 0 0 0 0 0 0 34 033 0 0 0 0 0 0 0 0 0 0 15 034 0 0 0 0 0 0 0 0 0 0 21 035 0 0 0 0 0 1 0 0 0 0 0 036 0 0 0 0 0 5 1 0 0 0 1 037 0 0 0 0 0 7 0 1 0 0 3 038 0 0 0 0 0 0 0 0 0 0 1 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-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/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================132 Index page6127 Undo log page73 Inode page0 Insert buffer free list page2490 Freshly allocated page3 Insert buffer bitmap131 System page1 Transaction system page3 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 6127Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 031 23 23 73 1503832 34 34 73 1503833 15 15 73 1503834 21 21 73 1503835 1 1 620 806036 7 7 698 908337 11 11 789 1025738 1 1 1191 15483-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 031 0 0 0 0 0 0 0 0 0 0 23 032 0 0 0 0 0 0 0 0 0 0 34 033 0 0 0 0 0 0 0 0 0 0 15 034 0 0 0 0 0 0 0 0 0 0 21 035 0 0 0 0 0 1 0 0 0 0 0 036 0 0 0 0 0 5 1 0 0 0 1 037 0 0 0 0 0 7 0 1 0 0 3 038 0 0 0 0 0 0 0 0 0 0 1 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================132 Index page6127 Undo log page73 Inode page0 Insert buffer free list page2490 Freshly allocated page3 Insert buffer bitmap131 System page1 Transaction system page3 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 6127Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 031 23 23 73 1503832 34 34 73 1503833 15 15 73 1503834 21 21 73 1503835 1 1 620 806036 7 7 698 908337 11 11 789 1025738 1 1 1191 15483-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 031 0 0 0 0 0 0 0 0 0 0 23 032 0 0 0 0 0 0 0 0 0 0 34 033 0 0 0 0 0 0 0 0 0 0 15 034 0 0 0 0 0 0 0 0 0 0 21 035 0 0 0 0 0 1 0 0 0 0 0 036 0 0 0 0 0 5 1 0 0 0 1 037 0 0 0 0 0 7 0 1 0 0 3 038 0 0 0 0 0 0 0 0 0 0 1 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-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/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================132 Index page6127 Undo log page73 Inode page0 Insert buffer free list page2490 Freshly allocated page3 Insert buffer bitmap131 System page1 Transaction system page3 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 6127Undo page state: 7 active, 121 cached, 5687 to_purge, 0 prepared, 312 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 031 23 23 73 1503832 34 34 73 1503833 15 15 73 1503834 21 21 73 1503835 1 1 620 806036 7 7 698 908337 11 11 789 1025738 1 1 1191 15483-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 031 0 0 0 0 0 0 0 0 0 0 23 032 0 0 0 0 0 0 0 0 0 0 34 033 0 0 0 0 0 0 0 0 0 0 15 034 0 0 0 0 0 0 0 0 0 0 21 035 0 0 0 0 0 1 0 0 0 0 0 036 0 0 0 0 0 5 1 0 0 0 1 037 0 0 0 0 0 7 0 1 0 0 3 038 0 0 0 0 0 0 0 0 0 0 1 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-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/sysbenchYuliyas-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 cleanupsysbench 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 preparesysbench 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 runsysbench 1.1.0-df89d34 (using bundled LuaJIT 2.1.0-beta3)Running the test with following options:Number of threads: 4Report intermediate results every 10 second(s)Initializing random number generator from current timeInitializing 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.00SQL statistics:queries performed:read: 1226918write: 350548other: 175274total: 1752740transactions: 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.3249time elapsed: 100.0051stotal number of events: 87637Latency (ms):min: 1.76avg: 4.56max: 167.9295th percentile: 8.28sum: 399658.03Threads fairness:events (avg/stddev): 21909.2500/29.35execution time (avg/stddev): 99.9145/0.00Yuliyas-Air:sysbench Valerii$ cd -/Users/Valerii/dbs/maria10.6Yuliyas-Air:maria10.6 Valerii$ ls -l data/ibdata1-rw-rw---- 1 Valerii staff 213909504 10 May 18:38 data/ibdata1Yuliyas-Air:maria10.6 Valerii$ bin/innochecksum -S data/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================138 Index page10016 Undo log page114 Inode page0 Insert buffer free list page2655 Freshly allocated page1 Insert buffer bitmap130 System page1 Transaction system page1 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 10016Undo page state: 0 active, 129 cached, 9405 to_purge, 0 prepared, 482 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 039 19 19 73 1503840 18 18 73 1503841 14 14 73 1503842 24 24 73 1503843 12 12 947 1232044 12 12 951 1236545 11 11 821 1067546 17 17 782 10176-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 039 0 0 0 0 0 0 0 0 0 0 19 040 0 0 0 0 0 0 0 0 0 0 18 041 0 0 0 0 0 0 0 0 0 0 14 042 0 0 0 0 0 0 0 0 0 0 24 043 0 0 0 0 0 4 1 0 0 0 7 044 0 0 0 0 0 4 1 0 0 0 7 045 0 0 0 0 0 6 1 0 0 0 4 046 0 0 0 0 0 11 1 0 0 0 5 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-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/ibdata1File::data/ibdata1================PAGE TYPE SUMMARY==============#PAGE_COUNT PAGE_TYPE===============================================138 Index page10016 Undo log page114 Inode page0 Insert buffer free list page2655 Freshly allocated page1 Insert buffer bitmap130 System page1 Transaction system page1 File Space Header0 Extent descriptor page0 BLOB page0 Compressed BLOB page0 Page compressed page0 Page compressed encrypted page0 Other type of page===============================================Additional information:Undo page type: 10016Undo page state: 0 active, 129 cached, 9405 to_purge, 0 prepared, 482 otherindex_id #pages #leaf_pages #recs_per_page #bytes_per_page1 1 1 11 8592 1 1 50 31733 1 1 20 14424 1 1 29 12465 1 1 11 36411 1 1 0 012 1 1 0 013 1 1 0 014 1 1 0 015 1 1 0 039 19 19 73 1503840 18 18 73 1503841 14 14 73 1503842 24 24 73 1503843 12 12 947 1232044 12 12 951 1236545 11 11 821 1067546 17 17 782 10176-4294967296 1 1 0 0index_id page_data_bytes_histgram(empty,...,oversized)1 0 1 0 0 0 0 0 0 0 0 0 02 0 0 1 0 0 0 0 0 0 0 0 03 0 1 0 0 0 0 0 0 0 0 0 04 0 1 0 0 0 0 0 0 0 0 0 05 0 1 0 0 0 0 0 0 0 0 0 011 1 0 0 0 0 0 0 0 0 0 0 012 1 0 0 0 0 0 0 0 0 0 0 013 1 0 0 0 0 0 0 0 0 0 0 014 1 0 0 0 0 0 0 0 0 0 0 015 1 0 0 0 0 0 0 0 0 0 0 039 0 0 0 0 0 0 0 0 0 0 19 040 0 0 0 0 0 0 0 0 0 0 18 041 0 0 0 0 0 0 0 0 0 0 14 042 0 0 0 0 0 0 0 0 0 0 24 043 0 0 0 0 0 4 1 0 0 0 7 044 0 0 0 0 0 4 1 0 0 0 7 045 0 0 0 0 0 6 1 0 0 0 4 046 0 0 0 0 0 11 1 0 0 0 5 0-4294967296 1 0 0 0 0 0 0 0 0 0 0 0Yuliyas-Air:maria10.6 Valerii$