MySQL Bugs: #104529: LSN keep on increasing without any changes happening at instance level

Bug #104529	LSN keep on increasing without any changes happening at instance level
Submitted:	4 Aug 2021 8:20	Modified:	4 Aug 2021 11:31
Reporter:	Ankit Kapoor	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	8.0.23, 8.0.26	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
Can you please see this logic. This is idle server and standalone which means no replica. LSN keep on increasing post executing flush logs. Though flush logs can touch the redo log buffer but if no changes are happening then LSN should not increase as well. Have tested this with binlog enabled and disabled both. In both cases LSN is increasing

	

mysql> pager grep sequence;
PAGER set to 'grep sequence'

mysql> show engine innodb status\G;
Log sequence number 79708796484
1 row in set (0.01 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.00 sec)

mysql> show engine innodb status\G;
Log sequence number 79708796530
1 row in set (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.01 sec)

mysql> show engine innodb status\G;
Log sequence number 79708796560
1 row in set (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.01 sec)

mysql> show engine innodb status\G;
Log sequence number 79708796590
1 row in set (0.00 sec)

How to repeat:
take a testing instance and disabled binlogs and make sure no one is writing on this instance .
grep sequence from innodb status 
execute flush logs and check the current lsn.

repeat this cycle and you will observe that LSN keeps on changing

again repeat this cycle with bin logs enabled

Hello Ankit Kapoor,

Thank you for the report and feedback.

regards,
Umesh

Posted by developer:
 
When I set a memory breakpoint in Visual Studio, to track changes of the lsn.sn atomic variable, value of which is reported as "Log sequence number" in the `show engine innodb status`, then I see that it is being modified with following callstack during `FLUSH LOGS;` statement:
>	log_buffer_s_lock_enter_reserve(log_t & log, unsigned __int64 len) Line 504	C++
 	log_buffer_reserve(log_t & log, unsigned __int64 len) Line 836	C++
 	mtr_t::Command::execute() Line 841	C++
 	mtr_t::commit() Line 661	C++
 	trx_sys_persist_gtid_num(unsigned __int64 gtid_trx_no) Line 146	C++
 	Clone_persist_gtid::update_gtid_trx_no(unsigned __int64 new_gtid_trx_no) Line 475	C++
 	Clone_persist_gtid::flush_gtids(THD * thd) Line 533	C++
 	Clone_persist_gtid::periodic_write() Line 610	C++
 	clone_gtid_thread(Clone_persist_gtid * persist_gtid) Line 692	C++

That is flush_gtids() is the reason, and it is triggered by a thread which sets the conditional variable.
There are three places where we do that:
>	Clone_persist_gtid::wait_flush(bool compress_gtid, bool early_timeout, std::function<int __cdecl(void)> cbk) Line 725	C++
 	innobase_flush_logs(handlerton * hton, bool binlog_group_flush) Line 5493	C++
 	flush_handlerton(THD * __formal, st_plugin_int * * plugin, void * arg) Line 2448	C++
 	plugin_foreach_with_mask(THD * thd, bool(*)(THD *, st_plugin_int * *, void *) * funcs, int type, unsigned int state_mask, void * arg) Line 2740	C++
 	plugin_foreach_with_mask(THD * thd, bool(*)(THD *, st_plugin_int * *, void *) func, int type, unsigned int state_mask, void * arg) Line 2754	C++
 	ha_flush_logs(bool binlog_group_flush) Line 2455	C++
 	handle_reload_request(THD * thd, unsigned long options, TABLE_LIST * tables, int * write_to_binlog) Line 210	C++
 	mysql_execute_command(THD * thd, bool first_level) Line 4006	C++
 	dispatch_sql_command(THD * thd, Parser_state * parser_state) Line 5132	C++
 	dispatch_command(THD * thd, const COM_DATA * com_data, enum_server_command command) Line 1925	C++
 	do_command(THD * thd) Line 1342	C++
 	handle_connection(void * arg) Line 302	C++
 	pfs_spawn_thread(void * arg) Line 2948	C++
 	win_thread_start(void * p) Line 73	C++
and:
>	Clone_persist_gtid::wait_flush(bool compress_gtid, bool early_timeout, std::function<int __cdecl(void)> cbk) Line 725	C++
 	innobase_flush_logs(handlerton * hton, bool binlog_group_flush) Line 5493	C++
 	flush_handlerton(THD * __formal, st_plugin_int * * plugin, void * arg) Line 2448	C++
 	plugin_foreach_with_mask(THD * thd, bool(*)(THD *, st_plugin_int * *, void *) * funcs, int type, unsigned int state_mask, void * arg) Line 2740	C++
 	plugin_foreach_with_mask(THD * thd, bool(*)(THD *, st_plugin_int * *, void *) func, int type, unsigned int state_mask, void * arg) Line 2754	C++
 	ha_flush_logs(bool binlog_group_flush) Line 2455	C++
 	MYSQL_BIN_LOG::new_file_impl(bool need_lock_log, Format_description_log_event * extra_description_event) Line 6444	C++
 	MYSQL_BIN_LOG::new_file_without_locking(Format_description_log_event * extra_description_event) Line 6387	C++
 	MYSQL_BIN_LOG::rotate(bool force_rotate, bool * check_purge) Line 7061	C++
 	MYSQL_BIN_LOG::rotate_and_purge(THD * thd, bool force_rotate) Line 7134	C++
 	handle_reload_request(THD * thd, unsigned long options, TABLE_LIST * tables, int * write_to_binlog) Line 234	C++
 	mysql_execute_command(THD * thd, bool first_level) Line 4006	C++
 	dispatch_sql_command(THD * thd, Parser_state * parser_state) Line 5132	C++
 	dispatch_command(THD * thd, const COM_DATA * com_data, enum_server_command command) Line 1925	C++
 	do_command(THD * thd) Line 1342	C++
 	handle_connection(void * arg) Line 302	C++
 	pfs_spawn_thread(void * arg) Line 2948	C++
 	win_thread_start(void * p) Line 73	C++
and:
>	Clone_persist_gtid::wait_flush(bool compress_gtid, bool early_timeout, std::function<int __cdecl(void)> cbk) Line 725	C++
 	innobase_flush_logs(handlerton * hton, bool binlog_group_flush) Line 5493	C++
 	flush_handlerton(THD * __formal, st_plugin_int * * plugin, void * arg) Line 2448	C++
 	plugin_foreach_with_mask(THD * thd, bool(*)(THD *, st_plugin_int * *, void *) * funcs, int type, unsigned int state_mask, void * arg) Line 2740	C++
 	plugin_foreach_with_mask(THD * thd, bool(*)(THD *, st_plugin_int * *, void *) func, int type, unsigned int state_mask, void * arg) Line 2754	C++
 	ha_flush_logs(bool binlog_group_flush) Line 2455	C++
 	MYSQL_BIN_LOG::purge() Line 7096	C++
 	MYSQL_BIN_LOG::rotate_and_purge(THD * thd, bool force_rotate) Line 7143	C++
 	handle_reload_request(THD * thd, unsigned long options, TABLE_LIST * tables, int * write_to_binlog) Line 234	C++
 	mysql_execute_command(THD * thd, bool first_level) Line 4006	C++
 	dispatch_sql_command(THD * thd, Parser_state * parser_state) Line 5132	C++
 	dispatch_command(THD * thd, const COM_DATA * com_data, enum_server_command command) Line 1925	C++
 	do_command(THD * thd) Line 1342	C++
 	handle_connection(void * arg) Line 302	C++
 	pfs_spawn_thread(void * arg) Line 2948	C++
 	win_thread_start(void * p) Line 73	C++

The last two are related to binlog.
I've used a very simple approach to testing this:
/c/ade/mysql/mysql-bin/runtime_output_directory/Debug/mysqld.exe --console --gdb --initialize-insecure
followed by:
/c/ade/mysql/mysql-bin/runtime_output_directory/Debug/mysqld.exe --console --gdb 
and issuing FLUSH LOGS from a client, that's all.

What you see in case of bin log being disabled ? If I go as per you in below snippet then flush logs should not increase the LSN when bin logs are disabled

log_buffer_s_lock_enter_reserve(log_t & log, unsigned __int64 len) Line 504	C++
 	log_buffer_reserve(log_t & log, unsigned __int64 len) Line 836	C++
 	mtr_t::Command::execute() Line 841	C++
 	mtr_t::commit() Line 661	C++
 	trx_sys_persist_gtid_num(unsigned __int64 gtid_trx_no) Line 146	C++
 	Clone_persist_gtid::update_gtid_trx_no(unsigned __int64 new_gtid_trx_no) Line 475	C++
 	Clone_persist_gtid::flush_gtids(THD * thd) Line 533	C++
 	Clone_persist_gtid::periodic_write() Line 610	C++
 	clone_gtid_thread(Clone_persist_gtid * persist_gtid) Line 692	C++