MySQL Bugs: #107473: Updating BLOB column slows down purge and causes high trx_rseg_history

Bug #107473	Updating BLOB column slows down purge and causes high trx_rseg_history_len
Submitted:	3 Jun 2022 3:34	Modified:	24 Aug 2022 6:54
Reporter:	Lei Zeng	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	8.0.23, 8.0.29	OS:	CentOS
Assigned to:		CPU Architecture:	Any

Description:
If a table has a column with blob type (blob, mediumblob, longblob) and we keep updating this column with different values (having different size), purge process will become super slow and trx_rseg_history_len will be accumulated quickly. The direct impact is database performance degradation.

This symptom is pretty close to https://bugs.mysql.com/bug.php?id=96466 but it has been fixed in 8.0.19 and I am able to repro this issue on 8.0.23 

How to repeat:
1. create a table with blob columns

CREATE TABLE test1 ( uid int NOT NULL  AUTO_INCREMENT, block_id int NOT NULL DEFAULT '0', bin_data mediumblob NOT NULL, extra_bin_data blob, data_version int unsigned NOT NULL DEFAULT 0,tag_list varchar(128) NOT NULL DEFAULT '',
before_login_bin_data blob, last_save_time timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, PRIMARY KEY (uid) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci ROW_FORMAT=COMPACT;

2. insert 10G data into this table with blob size = 256k (run the following statement 30,000 times)

INSERT INTO test1 (block_id, bin_data, extra_bin_data, before_login_bin_data) VALUES (ROUND(1.0 + 1048.0 * RAND()), repeat(md5(rand()),8192 ), md5(rand()), repeat(md5(rand()),20 ));

3. check trx_rseg_history_len to wait it to be 0

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+-------+
| now()               | name                 | COUNT |
+---------------------+----------------------+-------+
| 2022-06-03 02:55:01 | trx_rseg_history_len |     0 |
+---------------------+----------------------+-------+
1 row in set (0.00 sec)

4. Start 100 threads to run the following customized sysbench script to UPDATE statement on the BLOB columns, size = 300k

#!/usr/bin/env sysbench
require("oltp_common")

function prepare_statements()
   -- do nothing here
end

function event()
   local table_name = "test1"
   local i = sysbench.rand.uniform(1, 1000)
   con:query(string.format("update %s set bin_data = repeat(md5(rand()),8192 ), extra_bin_data='', data_version=506 where uid= %d", table_name, i))
end 

5. Monitor purge and watch it is keep increasing. 

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+-------+
| now()               | name                 | COUNT |
+---------------------+----------------------+-------+
| 2022-06-03 02:32:09 | trx_rseg_history_len |     0 |
+---------------------+----------------------+-------+
1 row in set (0.00 sec)

mysql> select now(),name,COUNT,status from information_schema.innodb_metrics where name like '%purge%';
+---------------------+-----------------------------------+---------+----------+
| now()               | name                              | COUNT   | status   |
+---------------------+-----------------------------------+---------+----------+
| 2022-06-03 02:32:09 | purge_del_mark_records            |    1579 | enabled  |
| 2022-06-03 02:32:09 | purge_upd_exist_or_extern_records | 1606440 | enabled  |
| 2022-06-03 02:32:09 | purge_invoked                     |   12164 | enabled  |
| 2022-06-03 02:32:09 | purge_undo_log_pages              | 1608620 | enabled  |
| 2022-06-03 02:32:09 | purge_dml_delay_usec              |       0 | enabled  |
| 2022-06-03 02:32:09 | purge_stop_count                  |       0 | enabled  |
| 2022-06-03 02:32:09 | purge_resume_count                |       0 | enabled  |
| 2022-06-03 02:32:09 | purge_truncate_history_count      |      96 | enabled  |
| 2022-06-03 02:32:09 | purge_truncate_history_usec       | 2719734 | enabled  |
| 2022-06-03 02:32:09 | innodb_master_purge_usec          |       0 | disabled |
+---------------------+-----------------------------------+---------+----------+
10 rows in set (0.00 sec)

mysql> select sleep(600);

+------------+
| sleep(600) |
+------------+
|          0 |
+------------+
1 row in set (10 min 0.00 sec)

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+--------+
| now()               | name                 | COUNT  |
+---------------------+----------------------+--------+
| 2022-06-03 02:42:09 | trx_rseg_history_len | 275638 |
+---------------------+----------------------+--------+
1 row in set (0.01 sec)

mysql> select now(),name,COUNT,status from information_schema.innodb_metrics where name like '%purge%';
+---------------------+-----------------------------------+---------+----------+
| now()               | name                              | COUNT   | status   |
+---------------------+-----------------------------------+---------+----------+
| 2022-06-03 02:42:09 | purge_del_mark_records            |    1579 | enabled  |
| 2022-06-03 02:42:09 | purge_upd_exist_or_extern_records | 1630995 | enabled  |
| 2022-06-03 02:42:09 | purge_invoked                     |   12299 | enabled  |
| 2022-06-03 02:42:09 | purge_undo_log_pages              | 1630260 | enabled  |
| 2022-06-03 02:42:09 | purge_dml_delay_usec              |       0 | enabled  |
| 2022-06-03 02:42:09 | purge_stop_count                  |       0 | enabled  |
| 2022-06-03 02:42:09 | purge_resume_count                |       0 | enabled  |
| 2022-06-03 02:42:09 | purge_truncate_history_count      |      97 | enabled  |
| 2022-06-03 02:42:09 | purge_truncate_history_usec       | 2727323 | enabled  |
| 2022-06-03 02:42:09 | innodb_master_purge_usec          |       0 | disabled |
+---------------------+-----------------------------------+---------+----------+
10 rows in set (0.00 sec)

mysql> select sleep(600);
+------------+
| sleep(600) |
+------------+
|          0 |
+------------+
1 row in set (10 min 0.00 sec)

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+--------+
| now()               | name                 | COUNT  |
+---------------------+----------------------+--------+
| 2022-06-03 02:52:09 | trx_rseg_history_len | 585616 |
+---------------------+----------------------+--------+
1 row in set (0.00 sec)

mysql> select now(),name,COUNT,status from information_schema.innodb_metrics where name like '%purge%';
+---------------------+-----------------------------------+---------+----------+
| now()               | name                              | COUNT   | status   |
+---------------------+-----------------------------------+---------+----------+
| 2022-06-03 02:52:09 | purge_del_mark_records            |    1579 | enabled  |
| 2022-06-03 02:52:09 | purge_upd_exist_or_extern_records | 1652679 | enabled  |
| 2022-06-03 02:52:09 | purge_invoked                     |   12303 | enabled  |
| 2022-06-03 02:52:09 | purge_undo_log_pages              | 1650260 | enabled  |
| 2022-06-03 02:52:09 | purge_dml_delay_usec              |       0 | enabled  |
| 2022-06-03 02:52:09 | purge_stop_count                  |       0 | enabled  |
| 2022-06-03 02:52:09 | purge_resume_count                |       0 | enabled  |
| 2022-06-03 02:52:09 | purge_truncate_history_count      |      97 | enabled  |
| 2022-06-03 02:52:09 | purge_truncate_history_usec       | 2727323 | enabled  |
| 2022-06-03 02:52:09 | innodb_master_purge_usec          |       0 | disabled |
+---------------------+-----------------------------------+---------+----------+
10 rows in set (0.00 sec)

mysql>

Want to make correct to Step 4. use 'repeat(md5(rand()),9600 )' for 300k BLOB size.

4. Start 100 threads to run the following customized sysbench script to UPDATE statement on the BLOB columns, size = 300k

#!/usr/bin/env sysbench
require("oltp_common")

function prepare_statements()
   -- do nothing here
end

function event()
   local table_name = "test1"
   local i = sysbench.rand.uniform(1, 1000)
   con:query(string.format("update %s set bin_data = repeat(md5(rand()),9600 ), extra_bin_data='', data_version=506 where uid= %d", table_name, i))
end

Tested on the most recent version 8.0.29, see the same issue: trx_rseg_history_len kept increasing and .ibd file grew 10 or 20 times large after running UPDATE statement against BLOB for 20 min

********* Test case #1, Run 100 concurrent UPDATE statements with default purge parameters:
mysql> show variables like '%purge%';
+--------------------------------------+-------+
| Variable_name                        | Value |
+--------------------------------------+-------+
| binlog_expire_logs_auto_purge        | ON    |
| gtid_purged                          |       |
| innodb_max_purge_lag                 | 0     |
| innodb_max_purge_lag_delay           | 0     |
| innodb_purge_batch_size              | 300   |
| innodb_purge_rseg_truncate_frequency | 128   |
| innodb_purge_threads                 | 4     |
| relay_log_purge                      | ON    |
+--------------------------------------+-------+

-rw-r----- 1 mysql mysql 11916017664 Jun  4 04:12 test1.ibd

-rw-r----- 1 mysql mysql 115980894208 Jun  4 04:33 test1.ibd

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+-------+
| now()               | name                 | COUNT |
+---------------------+----------------------+-------+
| 2022-06-04 04:12:23 | trx_rseg_history_len |     0 |
+---------------------+----------------------+-------+

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+--------+
| now()               | name                 | COUNT  |
+---------------------+----------------------+--------+
| 2022-06-04 04:32:42 | trx_rseg_history_len | 367261 |
+---------------------+----------------------+--------+

********* Test case #2, Run 100 concurrent UPDATE statements with customized purge parameters:

mysql>  show variables like '%purge%';
+--------------------------------------+-------+
| Variable_name                        | Value |
+--------------------------------------+-------+
| binlog_expire_logs_auto_purge        | ON    |
| gtid_purged                          |       |
| innodb_max_purge_lag                 | 0     |
| innodb_max_purge_lag_delay           | 0     |
| innodb_purge_batch_size              | 5000  | >>>>>>
| innodb_purge_rseg_truncate_frequency | 128   |
| innodb_purge_threads                 | 12    | >>>>>>
| relay_log_purge                      | ON    |
+--------------------------------------+-------+

-rw-r----- 1 mysql mysql 11916017664 Jun  4 05:08 test1.ibd
-rw-r----- 1 mysql mysql 224315572224 Jun  4 06:20 test1.ibd

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+-------+
| now()               | name                 | COUNT |
+---------------------+----------------------+-------+
| 2022-06-04 05:09:29 | trx_rseg_history_len |     2 |
+---------------------+----------------------+-------+

mysql> select now(),name,COUNT from information_schema.innodb_metrics where name in ('trx_rseg_history_len');
+---------------------+----------------------+--------+
| now()               | name                 | COUNT  |
+---------------------+----------------------+--------+
| 2022-06-04 06:12:42 | trx_rseg_history_len | 536976 |
+---------------------+----------------------+--------+

make correction to 'Test case #2', I used 200 concurrent UPDATE statements with customized purge parameters, instead of 100

Hello Lei Zeng,

Thank you for the report and test case.

regards,
Umesh