Bug #82213 Innodb reports warning while innodb_undo_log_truncate is enabled
Submitted: 13 Jul 2016 9:03 Modified: 17 Nov 2017 15:44
Reporter: zhai weixiang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7, 5.7.13 OS:Any
Assigned to: CPU Architecture:Any

[13 Jul 2016 9:03] zhai weixiang
Description:
Before truncating undo log, some warnings are printed in error log:

2016-07-13T08:51:56.992237Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4454960! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-13T08:51:56.993195Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4454693! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-13T08:51:56.993360Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4454698! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-13T08:51:56.993589Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4454706! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-13T08:51:56.993665Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4454708! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-13T08:52:08.228917Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 1
2016-07-13T08:52:09.280900Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 1
2016-07-13T08:52:36.359238Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 2
2016-07-13T08:52:37.174400Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 2
2016-07-13T08:52:43.983261Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 3
2016-07-13T08:52:44.564133Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 3
2016-07-13T08:52:47.012312Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 4
2016-07-13T08:52:47.426031Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 4

How to repeat:
I run the test on 5.7.13

1. Start a transaction and select something with RR isolation, to make sure that a read view is opened. 
2. Run heavy dml workload, wait for a while until innodb_max_undo_log_size is satisfied.
3. Commit the transaction. then check the error log

Suggested fix:
I don't know, still debug the code...
[13 Jul 2016 9:04] zhai weixiang
Change category
[14 Jul 2016 8:49] MySQL Verification Team
Hello Zhai,

Thank you for the bug report.
I tried with default conf with no luck so far. 
Could you please provide exact conf file used in your environment, and if possible repeatable test case?

Also, noticed similar bugs Bug #50772 / Bug #61567 / Bug #44923 / Bug #62759 and Bug #21685 etc 

Thanks,
Umesh
[14 Jul 2016 9:34] zhai weixiang
My configure file:

[mysqld_safe]
pid-file=/u01/my57/run/mysqld.pid

[mysql]
port=13606
prompt=\\u@\\d \\r:\\m:\\s>
default-character-set=utf8
no-auto-rehash

[client]
port=13606
socket=/u01/my57/run/mysql.sock

[mysqld]
#dir
basedir=/u01/my57
datadir=/u01/my57/data
tmpdir=/u01/my57/tmp
lc_messages_dir=/u01/my57/share
log-error=/u01/my57/log/alert.log
slow_query_log_file=/u01/my57/log/slow.log
general_log_file=/u01/my57/log/general.log
socket=/u01/my57/run/mysql.sock
core-file
innodb_data_home_dir=/u01/my57/data
innodb_log_group_home_dir=/u01/my57/data
innodb_data_file_path = ibdata1:4G;ibdata2:16M:autoextend
innodb_buffer_pool_size=32G
innodb_buffer_pool_instances=8
innodb_buffer_pool_load_at_startup=OFF
innodb_page_cleaners=1
innodb_log_files_in_group=4
innodb_log_file_size=4G
innodb_log_buffer_size=32M
innodb_flush_log_at_trx_commit=2
innodb_max_dirty_pages_pct=60
innodb_thread_concurrency=32
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_open_files=60000
innodb_file_per_table=1
innodb_flush_method=O_DIRECT
innodb_adaptive_flushing=ON
innodb_flush_neighbors=0
innodb_old_blocks_time=1000
innodb_stats_on_metadata=0
innodb_read_ahead_threshold=0
innodb_use_native_aio=1
innodb_rollback_on_timeout=0
innodb_purge_threads=1
innodb_strict_mode=1
transaction-isolation=READ-COMMITTED
innodb_disable_sort_file_cache=ON
innodb_io_capacity_max=6000
innodb_io_capacity=2000
innodb_lru_scan_depth=2048
innodb_undo_tablespaces=20
innodb_sync_array_size=16
innodb_print_all_deadlocks
innodb_checksum_algorithm=CRC32

#myisam
myisam_sort_buffer_size=64M
delayed_insert_timeout=300
#binlog
#log-bin=/u01/my57/log/mysql-bin
server_id=3017441834
binlog_cache_size=32K
max_binlog_cache_size=2G
max_binlog_size=500M
binlog-format=ROW
sync_binlog=1000
log-slave-updates=1
expire_logs_days=0

max_allowed_packet=128M

#server
port=13606
skip-name-resolve
skip-ssl
skip-external-locking
max_connections=21000
max_user_connections=20200
show_compatibility_56=ON

character-set-server=utf8
open_files_limit=65536
local-infile=1
performance_schema=OFF
performance_schema_instrument='%=ON'

query_cache_type=0

#replication
master-info-file=/u01/my57/log/master.info
relay-log=/u01/my57/log/relaylog
relay_log_info_file=/u01/my57/log/relay-log.info
relay-log-index=/u01/my57/log/mysqld-relay-bin.index
slave_load_tmpdir=/u01/my57/tmp
slave_type_conversions="ALL_NON_LOSSY"
slave_net_timeout=4
skip-slave-start
sync_master_info=1000
sync_relay_log_info=1000

rpl_stop_slave_timeout=300
slave_checkpoint_group=1024
slave_checkpoint_period=300
slave_parallel_workers=8
#slave_pr_mode=TABLE
slave_pending_jobs_size_max=1073741824
slave_rows_search_algorithms='TABLE_SCAN,INDEX_SCAN,HASH_SCAN'

slave_sql_verify_checksum=OFF
master_verify_checksum=OFF
gtid_mode=OFF
master_info_repository=TABLE
relay_log_info_repository=TABLE

connect_timeout=8
net_read_timeout=30
net_write_timeout=60
[14 Jul 2016 9:37] zhai weixiang
Enable truncating undo log online:

innodb_max_undo_log_size = 104857600
innodb_undo_log_truncate = ON
[14 Jul 2016 9:47] zhai weixiang
This issue should be very easy to repeat:

First start a read only transaction:

set session tx_isolation = 'REPEATABLE-READ';
begin;
select * from sbtest1 limit 1;  -- keep the read view open

Then start sysbench, and run for a while until the history list of purge system is big enough (in my test, it's bigger than 6,000,000), and the size of most undo tablespaces exceed the configured value of innodb_max_undo_log_size

Then commit the transaction, wait, and check the error log
[14 Jul 2016 9:53] MySQL Verification Team
Thank you for the conf, and repeatable steps.

Thanks,
Umesh
[14 Jul 2016 12:45] MySQL Verification Team
Thank you Zhai, fully verified!

Thanks,
Umesh
[14 Jul 2016 12:45] MySQL Verification Team
test results

Attachment: 82213.log (application/octet-stream, text), 7.94 KiB.

[14 Jul 2016 12:49] MySQL Verification Team
-- extract from error log

2016-07-14T12:35:52.129916Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4986877! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-14T12:35:52.130144Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4986877! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-14T12:35:52.130213Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4986877! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-14T12:35:52.139922Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4986590! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-14T12:35:52.139951Z 0 [Warning] InnoDB: Purge reached the head of the history list, but its length is still reported as 4986590! Make a detailed bug report, and submit it to http://bugs.mysql.com
2016-07-14T12:39:38.167624Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 1
2016-07-14T12:39:38.345560Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 1
2016-07-14T12:44:38.365546Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 2
2016-07-14T12:44:38.572898Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 2
2016-07-14T12:44:38.573521Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 3
2016-07-14T12:44:38.813712Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 3
2016-07-14T12:44:38.814294Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 4
2016-07-14T12:44:39.008712Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 4
2016-07-14T12:44:39.009223Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 5
2016-07-14T12:44:39.200847Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 5
2016-07-14T12:44:39.201413Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 6
2016-07-14T12:44:39.389119Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 6
2016-07-14T12:44:39.389451Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 7
2016-07-14T12:44:39.573908Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 7
2016-07-14T12:44:39.574459Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 8
2016-07-14T12:44:39.755463Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 8
2016-07-14T12:44:39.755965Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 9
2016-07-14T12:44:39.933955Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 9
2016-07-14T12:44:39.934462Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 10
2016-07-14T12:44:40.111639Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 10
2016-07-14T12:44:40.112197Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 11
2016-07-14T12:44:40.285415Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 11
2016-07-14T12:44:40.285876Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 12
2016-07-14T12:44:40.457220Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 12
2016-07-14T12:44:40.457772Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 13
2016-07-14T12:44:40.620059Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 13
2016-07-14T12:44:40.620408Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 14
2016-07-14T12:44:40.781081Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 14
2016-07-14T12:44:40.781779Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 15
2016-07-14T12:44:40.937669Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 15
2016-07-14T12:44:40.938389Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 16
2016-07-14T12:44:41.088592Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 16
2016-07-14T12:44:41.089097Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 17
2016-07-14T12:44:41.237917Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 17
2016-07-14T12:44:41.238486Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 18
2016-07-14T12:44:41.376476Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 18
2016-07-14T12:44:41.376965Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 19
2016-07-14T12:44:41.512410Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 19
2016-07-14T12:44:41.512990Z 0 [Note] InnoDB: Truncating UNDO tablespace with space identifier 20
2016-07-14T12:44:41.645945Z 0 [Note] InnoDB: Completed truncate of UNDO tablespace with space identifier 20
[17 Nov 2017 15:44] Daniel Price
Posted by developer:
 
Fixed as of the upcoming  5.5.59, 5.6.39, 5.7.21, 8.0.4 release, and here's the changelog entry:

 While innodb_undo_log_truncate was enabled, warnings that should only
appear in a debug version of MySQL were printed to the error log when the
length of the history list exceeded 2000000.
[15 Jan 2018 12:37] Daniel Price
Posted by developer:
 
Revised changelog entry:

Warnings that should only appear in a debug version of MySQL were printed
to the error log when the length of the history list exceeded 2000000.