[MDEV-13814] Extra logging when innodb_log_archive=ON ( [Note] InnoDB: Read redo log up to LSN=...) Created: 2017-09-15  Updated: 2020-08-25  Resolved: 2017-09-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - XtraDB
Affects Version/s: 10.0.30, 10.1.22
Fix Version/s: 10.0.33, 10.1.27

Type: Bug Priority: Major
Reporter: Claudio Nanni Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None
Environment:

RHEL

Issue Links:
Problem/Incident
is caused by MDEV-11027 InnoDB log recovery is too noisy Closed
Relates
relates to MDEV-14174 crash on start with innodb-track-chan... Closed

 Description   

A healthy running server prints the following messages, approximately every 16MB of redo log:

2017-09-10 13:56:21 140493990914816 [Note] InnoDB: Read redo log up to LSN=139157068288
2017-09-10 14:46:42 140496077253376 [Note] InnoDB: Read redo log up to LSN=139173845504
2017-09-10 14:57:45 140496085437184 [Note] InnoDB: Read redo log up to LSN=139190622720
2017-09-10 15:36:40 140496110553856 [Note] InnoDB: Read redo log up to LSN=139207399936
2017-09-10 15:39:12 140496496207616 [Note] InnoDB: Read redo log up to LSN=139224177152
2017-09-10 15:59:44 140496504600320 [Note] InnoDB: Read redo log up to LSN=139240954368
2017-09-10 16:27:30 140493987277568 [Note] InnoDB: Read redo log up to LSN=139257731584
2017-09-10 16:40:22 140496496207616 [Note] InnoDB: Read redo log up to LSN=139274508800
2017-09-10 16:55:52 140496335579904 [Note] InnoDB: Read redo log up to LSN=139291286016
2017-09-10 17:45:49 140496336186112 [Note] InnoDB: Read redo log up to LSN=139308063232
2017-09-10 18:25:37 140496496207616 [Note] InnoDB: Read redo log up to LSN=139316947456
2017-09-10 18:51:12 140496496207616 [Note] InnoDB: Read redo log up to LSN=139341617664

No recovery is in progress, the server is receiving connections and properly working.

innodb_log_archive=ON
log_warnings=2

 Comments   
Comment by Marko Mäkelä [ 2017-09-15 ]

The logging was changed in MDEV-11027. I forgot to test innodb_log_archive=ON.

Comment by Marko Mäkelä [ 2017-09-22 ]

The preprocessor symbol UNIV_LOG_ARCHIVE is not defined in the 5.5 build. It is defined in the 10.0 XtraDB.
UNIV_LOG_ARCHIVE always was dead code in InnoDB, and it was enabled in XtraDB starting with 5.6.14 (MariaDB 10.0.7, 10.1.0).

Comment by Marko Mäkelä [ 2017-09-22 ]

I can repeat this on 10.0:

./mtr --mem --mysqld=--loose-innodb-log-archive=ON innodb.innodb_mysql.xtradb

After the run, I can see the message in the var/log/mysqld.1.err during shutdown (which is clearly not part of the crash recovery):

170922 10:20:04 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
170922 10:20:04 [Note] InnoDB: Read redo log up to LSN=1891328
 
170922 10:20:05 [Note] InnoDB: Shutdown completed; log sequence number 10915852

Comment by Marko Mäkelä [ 2017-09-22 ]

The fix is simple: add a condition before the call that was introduced in MDEV-11027:

diff --git a/storage/xtradb/log/log0log.cc b/storage/xtradb/log/log0log.cc
 
index a3b08eb6730..b8eaa08638f 100644
 
--- a/storage/xtradb/log/log0log.cc
 
+++ b/storage/xtradb/log/log0log.cc
 
@@ -2537,7 +2537,7 @@ log_group_read_log_seg(
 
 	start_lsn += len;
 
 	buf += len;
 
 
-	if (recv_sys->report(ut_time())) {
 
+	if (recv_recovery_is_on() && recv_sys->report(ut_time())) {
 
 		ib_logf(IB_LOG_LEVEL_INFO, "Read redo log up to LSN=" LSN_PF,
 
 			start_lsn);
 
 	}

This is only needed for XtraDB, which calls this function outside crash recovery when innodb_log_archive=ON. InnoDB does not have that setting.

Generated at Thu Feb 08 08:08:35 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.