Yuliyas-Air:mysql-test Valerii$ ./mtr --mysqld='--innodb_flush_log_at_trx_commit=0' --mysqld='--innodb_buffer_pool_size=128M' --mysqld='--innodb_flush_method=fsync' --suite=innodb pt_large_restart
|
Logging: ./mtr --mysqld=--innodb_flush_log_at_trx_commit=0 --mysqld=--innodb_buffer_pool_size=128M --mysqld=--innodb_flush_method=fsync --suite=innodb pt_large_restart
|
VS config:
|
vardir: /Users/Valerii/dbs/maria10.6/mysql-test/var
|
Checking leftover processes...
|
Removing old var directory...
|
Creating var directory '/Users/Valerii/dbs/maria10.6/mysql-test/var'...
|
Checking supported features...
|
MariaDB Version 10.6.16-MariaDB
|
- SSL connections supported
|
Collecting tests...
|
Installing system database...
|
|
==============================================================================
|
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
set default_storage_engine=innodb;
|
set use_stat_tables=NEVER||
|
create table tp (id int, c1 date, c2 int, c3 text, primary key(id, c1)) partition by range (to_days(c1)) (partition p1 values less than (734874), partition p2 values less than (735240), partition prest values less than (1000000))||
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:07:05.130335
|
for i in 1..50000 do execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-02", 1, repeat("a", 2000))'); execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-01", 2, repeat("b", 2000))'); end for||
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
18582582
|
show table status like 'tp';||
|
Name tp
|
Engine InnoDB
|
Version 10
|
Row_format Dynamic
|
Rows 86817
|
Avg_row_length 2847
|
Data_length 247234560
|
Max_data_length 0
|
Index_length 0
|
Data_free 5242880
|
Auto_increment NULL
|
Create_time 2023-08-30 10:07:05
|
Update_time 2023-08-30 10:07:23
|
Check_time NULL
|
Collation latin1_swedish_ci
|
Checksum NULL
|
Create_options partitioned
|
Comment
|
Max_index_length 0
|
Temporary N
|
set global innodb_fast_shutdown = 0;
|
show engine innodb status;;
|
Type InnoDB
|
Name
|
Status
|
=====================================
|
2023-08-30 10:07:27 0x700008fb5000 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 0 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
|
srv_master_thread log flush and writes: 1
|
----------
|
SEMAPHORES
|
----------
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 200033
|
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
1370 OS file reads, 14 OS file writes, 3 OS fsyncs
|
0.00 reads/s, 3362 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 0, seg size 2, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
0.00 hash searches/s, 0.00 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 464769912
|
Log flushed up to 464769912
|
Pages flushed up to 464769912
|
Last checkpoint at 464769900
|
0 pending log flushes, 0 pending chkp writes
|
4 log i/o's done, 4.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 136314880
|
Dictionary memory allocated 851728
|
Buffer pool size 8030
|
Free buffers 6540
|
Database pages 1490
|
Old database pages 570
|
Modified db pages 0
|
Percent of dirty pages(LRU & free pages): 0.000
|
Max dirty pages percent: 90.000
|
Pending reads 3
|
Pending writes: LRU 0, flush list 0
|
Pages made young 0, not young 0
|
0.00 youngs/s, 0.00 non-youngs/s
|
Pages read 1359, created 131, written 0
|
1359000.00 reads/s, 131000.00 creates/s, 0.00 writes/s
|
Buffer pool hit rate 0 / 1000, young-making rate 0 / 1000 not 0 / 1000
|
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
|
LRU len: 1490, unzip_LRU len: 0
|
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 0, updated 0, deleted 0, read 0
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
|
Number of system rows inserted 0, updated 0, deleted 0, read 0
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:07:27.311170
|
analyze format=json select distinct(c1) from tp partition (prest)
|
as t1||
|
ANALYZE
|
{
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 466.623,
|
"temporary_table": {
|
"table": {
|
"table_name": "t1",
|
"partitions": ["prest"],
|
"access_type": "index",
|
"key": "PRIMARY",
|
"key_length": "7",
|
"used_key_parts": ["id", "c1"],
|
"r_loops": 1,
|
"rows": 39558,
|
"r_rows": 100000,
|
"r_table_time_ms": 438.096,
|
"r_other_time_ms": 28.501,
|
"r_engine_stats": {
|
"pages_accessed": 25002,
|
"pages_read_count": 23584,
|
"pages_read_time_ms": 278.379
|
},
|
"filtered": 100,
|
"r_filtered": 100,
|
"using_index": true
|
}
|
}
|
}
|
}
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
484037
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:07:27.795496
|
analyze format=json select distinct(c1) from tp partition (prest)
|
as t1||
|
ANALYZE
|
{
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 369.276,
|
"temporary_table": {
|
"table": {
|
"table_name": "t1",
|
"partitions": ["prest"],
|
"access_type": "index",
|
"key": "PRIMARY",
|
"key_length": "7",
|
"used_key_parts": ["id", "c1"],
|
"r_loops": 1,
|
"rows": 39558,
|
"r_rows": 100000,
|
"r_table_time_ms": 341.428,
|
"r_other_time_ms": 27.843,
|
"r_engine_stats": {
|
"pages_accessed": 25002,
|
"pages_read_count": 19989,
|
"pages_read_time_ms": 194.047
|
},
|
"filtered": 100,
|
"r_filtered": 100,
|
"using_index": true
|
}
|
}
|
}
|
}
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
369933
|
show engine innodb status;||
|
Type InnoDB
|
Name
|
Status
|
=====================================
|
2023-08-30 10:07:28 0x700008fb5000 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 1 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
|
srv_master_thread log flush and writes: 1
|
----------
|
SEMAPHORES
|
----------
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 200034
|
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION (0x10eddebc0), not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
45834 OS file reads, 14 OS file writes, 3 OS fsyncs
|
44419.58 reads/s, 16057 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 0, seg size 2, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
0.00 hash searches/s, 0.00 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 464769912
|
Log flushed up to 464769912
|
Pages flushed up to 464769912
|
Last checkpoint at 464769900
|
0 pending log flushes, 0 pending chkp writes
|
4 log i/o's done, 0.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 136314880
|
Dictionary memory allocated 860056
|
Buffer pool size 8030
|
Free buffers 0
|
Database pages 8030
|
Old database pages 2983
|
Modified db pages 0
|
Percent of dirty pages(LRU & free pages): 0.000
|
Max dirty pages percent: 90.000
|
Pending reads 0
|
Pending writes: LRU 0, flush list 0
|
Pages made young 0, not young 54743
|
0.00 youngs/s, 54688.31 non-youngs/s
|
Pages read 45820, created 131, written 0
|
44416.58 reads/s, 0.00 creates/s, 0.00 writes/s
|
Buffer pool hit rate 111 / 1000, young-making rate 0 / 1000 not 1094 / 1000
|
Pages read ahead 94.91/s, evicted without access 650.35/s, Random read ahead 0.00/s
|
LRU len: 8030, unzip_LRU len: 0
|
I/O sum[0]:cur[43581], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 0, updated 0, deleted 0, read 200000
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 199800.20 reads/s
|
Number of system rows inserted 0, updated 0, deleted 0, read 0
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:07:28.166151
|
drop table tp||
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
50530
|
innodb.pt_large_restart 'innodb' [ pass ] 23117
|
--------------------------------------------------------------------------
|
The servers were restarted 0 times
|
Spent 23.117 of 39 seconds executing testcases
|
|
Completed: All 1 tests were successful.
|
|
Yuliyas-Air:mysql-test Valerii$ cd ../../maria10.5/mysql-test/
|
Yuliyas-Air:mysql-test Valerii$ ./mtr --mysqld='--innodb_flush_log_at_trx_commit=0' --mysqld='--innodb_buffer_pool_size=128M' --mysqld='--innodb_flush_method=fsync' --suite=innodb pt_large_restart
|
Logging: ./mtr --mysqld=--innodb_flush_log_at_trx_commit=0 --mysqld=--innodb_buffer_pool_size=128M --mysqld=--innodb_flush_method=fsync --suite=innodb pt_large_restart
|
VS config:
|
vardir: /Users/Valerii/dbs/maria10.5/mysql-test/var
|
Checking leftover processes...
|
Removing old var directory...
|
Creating var directory '/Users/Valerii/dbs/maria10.5/mysql-test/var'...
|
Checking supported features...
|
MariaDB Version 10.5.23-MariaDB
|
- SSL connections supported
|
Collecting tests...
|
Installing system database...
|
|
==============================================================================
|
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
set default_storage_engine=innodb;
|
set use_stat_tables=NEVER||
|
create table tp (id int, c1 date, c2 int, c3 text, primary key(id, c1)) partition by range (to_days(c1)) (partition p1 values less than (734874), partition p2 values less than (735240), partition prest values less than (1000000))||
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:15:20.113234
|
for i in 1..50000 do execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-02", 1, repeat("a", 2000))'); execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-01", 2, repeat("b", 2000))'); end for||
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
25757048
|
show table status like 'tp';||
|
Name tp
|
Engine InnoDB
|
Version 10
|
Row_format Dynamic
|
Rows 111912
|
Avg_row_length 3991
|
Data_length 446660608
|
Max_data_length 0
|
Index_length 0
|
Data_free 5242880
|
Auto_increment NULL
|
Create_time 2023-08-30 10:15:20
|
Update_time 2023-08-30 10:15:45
|
Check_time NULL
|
Collation latin1_swedish_ci
|
Checksum NULL
|
Create_options partitioned
|
Comment
|
Max_index_length 0
|
Temporary N
|
set global innodb_fast_shutdown = 0;
|
show engine innodb status;;
|
Type InnoDB
|
Name
|
Status
|
=====================================
|
2023-08-30 10:15:47 0x70000dbaa000 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 0 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
|
srv_master_thread log flush and writes: 1
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 0
|
OS WAIT ARRAY INFO: signal count 0
|
RW-shared spins 0, rounds 0, OS waits 0
|
RW-excl spins 0, rounds 0, OS waits 0
|
RW-sx spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 200034
|
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
2043 OS file reads, 14 OS file writes, 3 OS fsyncs
|
0.00 reads/s, 3321 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 0, seg size 2, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
0.00 hash searches/s, 42000.00 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 464009697
|
Log flushed up to 464009697
|
Pages flushed up to 464009697
|
Last checkpoint at 464009685
|
0 pending log flushes, 0 pending chkp writes
|
4 log i/o's done, 4.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 136314880
|
Dictionary memory allocated 854472
|
Buffer pool size 8065
|
Free buffers 5903
|
Database pages 2162
|
Old database pages 818
|
Modified db pages 0
|
Percent of dirty pages(LRU & free pages): 0.000
|
Max dirty pages percent: 90.000
|
Pending reads 0
|
Pending writes: LRU 0, flush list 0
|
Pages made young 0, not young 0
|
0.00 youngs/s, 0.00 non-youngs/s
|
Pages read 2031, created 131, written 0
|
2031000.00 reads/s, 131000.00 creates/s, 0.00 writes/s
|
Buffer pool hit rate 0 / 1000, young-making rate 0 / 1000 not 0 / 1000
|
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
|
LRU len: 2162, unzip_LRU len: 0
|
I/O sum[0]:cur[3], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 0, updated 0, deleted 0, read 0
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
|
Number of system rows inserted 0, updated 0, deleted 0, read 0
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:15:47.588935
|
analyze format=json select distinct(c1) from tp partition (prest)
|
as t1||
|
ANALYZE
|
{
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 437.1784201,
|
"temporary_table": {
|
"table": {
|
"table_name": "t1",
|
"partitions": ["prest"],
|
"access_type": "index",
|
"key": "PRIMARY",
|
"key_length": "7",
|
"used_key_parts": ["id", "c1"],
|
"r_loops": 1,
|
"rows": 93759,
|
"r_rows": 100000,
|
"r_table_time_ms": 412.3089944,
|
"r_other_time_ms": 24.29974713,
|
"filtered": 100,
|
"r_filtered": 100,
|
"using_index": true
|
}
|
}
|
}
|
}
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
481717
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:15:48.079117
|
analyze format=json select distinct(c1) from tp partition (prest)
|
as t1||
|
ANALYZE
|
{
|
"query_block": {
|
"select_id": 1,
|
"r_loops": 1,
|
"r_total_time_ms": 317.290521,
|
"temporary_table": {
|
"table": {
|
"table_name": "t1",
|
"partitions": ["prest"],
|
"access_type": "index",
|
"key": "PRIMARY",
|
"key_length": "7",
|
"used_key_parts": ["id", "c1"],
|
"r_loops": 1,
|
"rows": 93759,
|
"r_rows": 100000,
|
"r_table_time_ms": 293.7305725,
|
"r_other_time_ms": 23.55006024,
|
"filtered": 100,
|
"r_filtered": 100,
|
"using_index": true
|
}
|
}
|
}
|
}
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
317477
|
show engine innodb status;||
|
Type InnoDB
|
Name
|
Status
|
=====================================
|
2023-08-30 10:15:48 0x70000dbaa000 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 1 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 2 srv_idle
|
srv_master_thread log flush and writes: 2
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 0
|
OS WAIT ARRAY INFO: signal count 0
|
RW-shared spins 0, rounds 0, OS waits 0
|
RW-excl spins 0, rounds 0, OS waits 0
|
RW-sx spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 200034
|
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 281479483957424, not started
|
0 lock struct(s), heap size 1128, 0 row lock(s)
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync) log: 0; buffer pool: 0
|
46068 OS file reads, 14 OS file writes, 3 OS fsyncs
|
43981.02 reads/s, 16360 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
|
-------------------------------------
|
INSERT BUFFER AND ADAPTIVE HASH INDEX
|
-------------------------------------
|
Ibuf: size 1, free list len 0, seg size 2, 0 merges
|
merged operations:
|
insert 0, delete mark 0, delete 0
|
discarded operations:
|
insert 0, delete mark 0, delete 0
|
0.00 hash searches/s, 5.99 non-hash searches/s
|
---
|
LOG
|
---
|
Log sequence number 464009697
|
Log flushed up to 464009697
|
Pages flushed up to 464009697
|
Last checkpoint at 464009685
|
0 pending log flushes, 0 pending chkp writes
|
4 log i/o's done, 0.00 log i/o's/second
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 136314880
|
Dictionary memory allocated 856936
|
Buffer pool size 8065
|
Free buffers 0
|
Database pages 8065
|
Old database pages 2996
|
Modified db pages 0
|
Percent of dirty pages(LRU & free pages): 0.000
|
Max dirty pages percent: 90.000
|
Pending reads 0
|
Pending writes: LRU 0, flush list 0
|
Pages made young 0, not young 55074
|
0.00 youngs/s, 55018.98 non-youngs/s
|
Pages read 46056, created 131, written 0
|
43981.02 reads/s, 0.00 creates/s, 0.00 writes/s
|
Buffer pool hit rate 390 / 1000, young-making rate 0 / 1000 not 761 / 1000
|
Pages read ahead 61.94/s, evicted without access 608.39/s, Random read ahead 0.00/s
|
LRU len: 8065, unzip_LRU len: 0
|
I/O sum[0]:cur[43967], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
Process ID=0, Main thread ID=0, state: sleeping
|
Number of rows inserted 0, updated 0, deleted 0, read 200000
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 199800.20 reads/s
|
Number of system rows inserted 0, updated 0, deleted 0, read 0
|
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
select @now := now(6)||
|
@now := now(6)
|
2023-08-30 10:15:48.397502
|
drop table tp||
|
select timestampdiff(microsecond, @now, now(6))||
|
timestampdiff(microsecond, @now, now(6))
|
55132
|
innodb.pt_large_restart 'innodb' [ pass ] 28375
|
--------------------------------------------------------------------------
|
The servers were restarted 0 times
|
Spent 28.375 of 36 seconds executing testcases
|
|
Completed: All 1 tests were successful.
|
It turned out that History list length does NOT matter much, as we can see with the following modified test (on the same slow I/O bout platform):
openxs@ao756:~/dbs/maria10.5/mysql-test$ cat suite/innodb/t/pt_large.test
source include/have_innodb.inc;
source include/have_partition.inc;
set default_storage_engine=innodb;
delimiter ||;
set use_stat_tables=NEVER||
create table tp (id int, c1 date, c2 int, c3 text, primary key(id, c1)) partition by range (to_days(c1)) (partition p1 values less than (734874), partition p2 values less than (735240), partition prest values less than (1000000))||
select @now := now(6)||
for i in 1..50000 do execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-02", 1, repeat("a", 2000))'); execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-01", 2, repeat("b", 2000))'); end for||
select timestampdiff(microsecond, @now, now(6))||
--query_vertical show table status like 'tp';
delimiter ;||
# try to force restart with flushing pages to disk
set global innodb_fast_shutdown = 0;
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
--shutdown_server 300
--source include/wait_until_disconnected.inc
--enable_reconnect
--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
--source include/wait_until_connected_again.inc
--query_vertical show engine innodb status;
#SELECT variable_name, variable_value
#FROM information_schema.global_status
#WHERE variable_name like 'INNODB_BUFFER_POOL_PAGES_%';
delimiter ||;
select @now := now(6)||
analyze format=json select distinct(c1) from tp partition (prest)
as t1||
select timestampdiff(microsecond, @now, now(6))||
select @now := now(6)||
analyze format=json select distinct(c1) from tp partition (prest)
as t1||
select timestampdiff(microsecond, @now, now(6))||
--query_vertical show engine innodb status;
select @now := now(6)||
drop table tp||
select timestampdiff(microsecond, @now, now(6))||
The idea is to force slow shutdown, flush to disk etc and restart of server before running the queries.
On 10.5.20 we see:
openxs@ao756:~/dbs/maria10.5/mysql-test$ ./mtr --mysqld='--innodb_flush_log_at_trx_commit=0' --mysqld='--innodb_buffer_pool_size=128M' --suite=innodb pt_large
Logging: ./mtr --mysqld=--innodb_flush_log_at_trx_commit=0 --mysqld=--innodb_buffer_pool_size=128M --suite=innodb pt_large
VS config:
vardir: /home/openxs/dbs/maria10.5/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/dbs/maria10.5/mysql-test/var'...
Checking supported features...
MariaDB Version 10.5.20-MariaDB
- SSL connections supported
Collecting tests...
Installing system database...
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
set default_storage_engine=innodb;
set use_stat_tables=NEVER||
create table tp (id int, c1 date, c2 int, c3 text, primary key(id, c1)) partition by range (to_days(c1)) (partition p1 values less than (734874), partition p2 values less than (735240), partition prest values less than (1000000))||
select @now := now(6)||
@now := now(6)
2023-04-03 12:27:43.424711
for i in 1..50000 do execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-02", 1, repeat("a", 2000))'); execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-01", 2, repeat("b", 2000))'); end for||
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
103444271
show table status like 'tp';||
Name tp
Engine InnoDB
Version 10
Row_format Dynamic
Rows 87753
Avg_row_length 5245
Data_length 460292096
Max_data_length 0
Index_length 0
Data_free 5242880
Auto_increment NULL
Create_time 2023-04-03 12:27:43
Update_time 2023-04-03 12:29:26
Check_time NULL
Collation latin1_swedish_ci
Checksum NULL
Create_options partitioned
Comment
Max_index_length 0
Temporary N
set global innodb_fast_shutdown = 0;
show engine innodb status;;
Type InnoDB
Name
Status
=====================================
2023-04-03 12:29:28 0x7fc3a51d2640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 0 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 1
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 0
OS WAIT ARRAY INFO: signal count 0
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 200034
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
Pending flushes (fsync) log: 0; buffer pool: 0
2043 OS file reads, 2 OS file writes, 2 OS fsyncs
0.00 reads/s, 3321 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
0.00 hash searches/s, 42000.00 non-hash searches/s
---
LOG
---
Log sequence number 464002612
Log flushed up to 464002612
Pages flushed up to 464002612
Last checkpoint at 464002600
0 pending log flushes, 0 pending chkp writes
4 log i/o's done, 4.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 136314880
Dictionary memory allocated 854112
Buffer pool size 8065
Free buffers 5903
Database pages 2162
Old database pages 818
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 90.000
Pending reads 0
Pending writes: LRU 0, flush list 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2031, created 131, written 0
2031000.00 reads/s, 131000.00 creates/s, 0.00 writes/s
Buffer pool hit rate 0 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 2162, unzip_LRU len: 0
I/O sum[0]:cur[3], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 read views open inside InnoDB
Process ID=0, Main thread ID=0, state: sleeping
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
select @now := now(6)||
@now := now(6)
2023-04-03 12:29:28.511571
analyze format=json select distinct(c1) from tp partition (prest)
as t1||
ANALYZE
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": 496.7287184,
"temporary_table": {
"table": {
"table_name": "t1",
"partitions": ["prest"],
"access_type": "index",
"key": "PRIMARY",
"key_length": "7",
"used_key_parts": ["id", "c1"],
"r_loops": 1,
"rows": 93759,
"r_rows": 100000,
"r_table_time_ms": 449.9474815,
"r_other_time_ms": 46.75662559,
"filtered": 100,
"r_filtered": 100,
"using_index": true
}
}
}
}
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
513072
select @now := now(6)||
@now := now(6)
2023-04-03 12:29:29.025214
analyze format=json select distinct(c1) from tp partition (prest)
as t1||
ANALYZE
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": 394.4953433,
"temporary_table": {
"table": {
"table_name": "t1",
"partitions": ["prest"],
"access_type": "index",
"key": "PRIMARY",
"key_length": "7",
"used_key_parts": ["id", "c1"],
"r_loops": 1,
"rows": 93759,
"r_rows": 100000,
"r_table_time_ms": 350.1508022,
"r_other_time_ms": 44.33199987,
"filtered": 100,
"r_filtered": 100,
"using_index": true
}
}
}
}
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
394410
show engine innodb status;||
Type InnoDB
Name
Status
=====================================
2023-04-03 12:29:29 0x7fc3a51d2640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 1 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 2 srv_idle
srv_master_thread log flush and writes: 2
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 0
OS WAIT ARRAY INFO: signal count 0
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 200034
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421953253392592, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
Pending flushes (fsync) log: 0; buffer pool: 0
46063 OS file reads, 2 OS file writes, 2 OS fsyncs
43976.02 reads/s, 16384 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
0.00 hash searches/s, 5.99 non-hash searches/s
---
LOG
---
Log sequence number 464002612
Log flushed up to 464002612
Pages flushed up to 464002612
Last checkpoint at 464002600
0 pending log flushes, 0 pending chkp writes
4 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 136314880
Dictionary memory allocated 856536
Buffer pool size 8065
Free buffers 0
Database pages 8065
Old database pages 2996
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 90.000
Pending reads 0
Pending writes: LRU 0, flush list 0
Pages made young 0, not young 55074
0.00 youngs/s, 55018.98 non-youngs/s
Pages read 46051, created 131, written 0
43976.02 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 390 / 1000, young-making rate 0 / 1000 not 761 / 1000
Pages read ahead 0.00/s, evicted without access 608.39/s, Random read ahead 0.00/s
LRU len: 8065, unzip_LRU len: 0
I/O sum[0]:cur[44024], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 read views open inside InnoDB
Process ID=0, Main thread ID=0, state: sleeping
Number of rows inserted 0, updated 0, deleted 0, read 200000
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 199800.20 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
select @now := now(6)||
@now := now(6)
2023-04-03 12:29:29.420947
drop table tp||
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
237882
innodb.pt_large 'innodb' [ pass ] 106435
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 106.435 of 115 seconds executing testcases
Completed: All 1 tests were successful.
While on 10.6:
openxs@ao756:~/dbs/maria10.6/mysql-test$ ./mtr --mysqld='--innodb_flush_log_at_trx_commit=0' --mysqld='--innodb_buffer_pool_size=128M' --suite=innodb pt_large
Logging: ./mtr --mysqld=--innodb_flush_log_at_trx_commit=0 --mysqld=--innodb_buffer_pool_size=128M --suite=innodb pt_large
VS config:
vardir: /home/openxs/dbs/maria10.6/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/dbs/maria10.6/mysql-test/var'...
Checking supported features...
MariaDB Version 10.6.13-MariaDB
- SSL connections supported
Collecting tests...
Installing system database...
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
set default_storage_engine=innodb;
set use_stat_tables=NEVER||
create table tp (id int, c1 date, c2 int, c3 text, primary key(id, c1)) partition by range (to_days(c1)) (partition p1 values less than (734874), partition p2 values less than (735240), partition prest values less than (1000000))||
select @now := now(6)||
@now := now(6)
2023-04-03 12:22:11.874366
for i in 1..50000 do execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-02", 1, repeat("a", 2000))'); execute immediate concat('insert into tp (id, c1, c2, c3) values (', i,', "2023-01-01", 2, repeat("b", 2000))'); end for||
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
124212858
show table status like 'tp';||
Name tp
Engine InnoDB
Version 10
Row_format Dynamic
Rows 97522
Avg_row_length 4773
Data_length 465551360
Max_data_length 0
Index_length 0
Data_free 5242880
Auto_increment NULL
Create_time 2023-04-03 12:22:11
Update_time 2023-04-03 12:24:16
Check_time NULL
Collation latin1_swedish_ci
Checksum NULL
Create_options partitioned
Comment
Max_index_length 0
Temporary N
set global innodb_fast_shutdown = 0;
show engine innodb status;;
Type InnoDB
Name
Status
=====================================
2023-04-03 12:24:19 0x7f17b44e8640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 0 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 1
----------
SEMAPHORES
----------
------------
TRANSACTIONS
------------
Trx id counter 200051
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
--------
FILE I/O
--------
Pending flushes (fsync) log: 0; buffer pool: 0
810 OS file reads, 2 OS file writes, 2 OS fsyncs
0.00 reads/s, 8336 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 464734981
Log flushed up to 464734981
Pages flushed up to 464734981
Last checkpoint at 464734969
0 pending log flushes, 0 pending chkp writes
4 log i/o's done, 4.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 136314880
Dictionary memory allocated 848424
Buffer pool size 8112
Free buffers 7185
Database pages 927
Old database pages 362
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 90.000
Pending reads 491
Pending writes: LRU 0, flush list 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 796, created 131, written 0
796000.00 reads/s, 131000.00 creates/s, 0.00 writes/s
Buffer pool hit rate 299 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 927, unzip_LRU len: 0
I/O sum[0]:cur[1], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 read views open inside InnoDB
Process ID=0, Main thread ID=0, state: sleeping
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
select @now := now(6)||
@now := now(6)
2023-04-03 12:24:19.910352
analyze format=json select distinct(c1) from tp partition (prest)
as t1||
ANALYZE
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": 27885.85776,
"temporary_table": {
"table": {
"table_name": "t1",
"partitions": ["prest"],
"access_type": "index",
"key": "PRIMARY",
"key_length": "7",
"used_key_parts": ["id", "c1"],
"r_loops": 1,
"rows": 96653,
"r_rows": 100000,
"r_table_time_ms": 27748.48687,
"r_other_time_ms": 137.3572726,
"filtered": 100,
"r_filtered": 100,
"using_index": true
}
}
}
}
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
27874349
select @now := now(6)||
@now := now(6)
2023-04-03 12:24:47.785130
analyze format=json select distinct(c1) from tp partition (prest)
as t1||
ANALYZE
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": 23906.68441,
"temporary_table": {
"table": {
"table_name": "t1",
"partitions": ["prest"],
"access_type": "index",
"key": "PRIMARY",
"key_length": "7",
"used_key_parts": ["id", "c1"],
"r_loops": 1,
"rows": 96653,
"r_rows": 100000,
"r_table_time_ms": 23770.49161,
"r_other_time_ms": 136.1816679,
"filtered": 100,
"r_filtered": 100,
"using_index": true
}
}
}
}
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
23888900
show engine innodb status;||
Type InnoDB
Name
Status
=====================================
2023-04-03 12:25:11 0x7f17b44e8640 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 52 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 52 srv_idle
srv_master_thread log flush and writes: 52
----------
SEMAPHORES
----------
------------
TRANSACTIONS
------------
Trx id counter 200052
Purge done for trx's n:o < 0 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION (0x7f17b4790b80), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
Pending flushes (fsync) log: 0; buffer pool: 0
46058 OS file reads, 2 OS file writes, 2 OS fsyncs
870.14 reads/s, 15932 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 464734981
Log flushed up to 464734981
Pages flushed up to 464734981
Last checkpoint at 464734969
0 pending log flushes, 0 pending chkp writes
4 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 136314880
Dictionary memory allocated 855336
Buffer pool size 8112
Free buffers 0
Database pages 8112
Old database pages 3014
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 90.000
Pending reads 0
Pending writes: LRU 0, flush list 0
Pages made young 1, not young 54991
0.02 youngs/s, 1057.50 non-youngs/s
Pages read 46044, created 131, written 0
870.14 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 373 / 1000, young-making rate 0 / 1000 not 761 / 1000
Pages read ahead 0.00/s, evicted without access 11.79/s, Random read ahead 0.00/s
LRU len: 8112, unzip_LRU len: 0
I/O sum[38108]:cur[5894], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 read views open inside InnoDB
Process ID=0, Main thread ID=0, state: sleeping
Number of rows inserted 0, updated 0, deleted 0, read 200000
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3846.08 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
select @now := now(6)||
@now := now(6)
2023-04-03 12:25:11.675455
drop table tp||
select timestampdiff(microsecond, @now, now(6))||
timestampdiff(microsecond, @now, now(6))
146517
innodb.pt_large 'innodb' [ pass ] 180017
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 180.017 of 200 seconds executing testcases
Completed: All 1 tests were successful.