Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-13814

Extra logging when innodb_log_archive=ON ( [Note] InnoDB: Read redo log up to LSN=...)

Details

    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

      Attachments

        Issue Links

          Activity

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

            marko Marko Mäkelä added a comment - The logging was changed in MDEV-11027 . I forgot to test innodb_log_archive=ON.

            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).

            marko Marko Mäkelä added a comment - 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).

            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
            

            marko Marko Mäkelä added a comment - 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

            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.

            marko Marko Mäkelä added a comment - 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.

            People

              marko Marko Mäkelä
              claudio.nanni Claudio Nanni
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.