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

Rollback progress log messages during crash recovery are intermixed with unrelated log messages

    XMLWordPrintable

Details

    Description

      When InnoDB rolls back uncommitted transactions during crash recovery, it writes messages to the error log to keep track of its progress.

      However, these messages can be intermixed with unrelated error log messages. Consider the following log snippet:

      InnoDB: Starting in background the rollback of uncommitted transactions
      		 
      2017-03-20 13:32:25 7fe68f3ff700  InnoDB: Rolling back trx with id 746708378, 903119011 rows to undo
      		 
       
      		 
      InnoDB: Progress in percents: 12017-03-20 13:32:25 140737353812224 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 102852718183039
      		 
      2017-03-20 13:32:25 140627790493440 [Note] InnoDB: Dumping buffer pool(s) not yet started
      		 
      2017-03-20 13:32:25 140737353812224 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2017-03-20 13:32:25 140737353812224 [Warning] Failed to create a socket for IPv6 '::': errno: 97.
      		 
      2017-03-20 13:32:25 140737353812224 [Note] Server socket created on IP: '0.0.0.0'.
      		 
      2017-03-20 13:32:25 140737353812224 [Note] /usr/sbin/mysqld: ready for connections.
      		 
      Version: '10.1.20-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
      		 
       2 3 4 5 6 7 8 9 10 11 12 132017-03-20 14:27:15 140710228216576 [Note] /usr/sbin/mysqld: Normal shutdown
      		 
       
      		 
      2017-03-20 14:27:15 140710228216576 [Note] Event Scheduler: Purging the queue. 0 events
      		 
      2017-03-20 14:27:15 140627773708032 [Note] InnoDB: FTS optimize thread exiting.
      		 
      2017-03-20 14:27:15 140710228216576 [Note] InnoDB: Starting shutdown...
      		 
      2017-03-20 14:28:16 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:29:16 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:30:16 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:31:16 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:32:16 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
       142017-03-20 14:33:19 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:34:19 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:35:19 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:36:19 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:37:20 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
      2017-03-20 14:38:20 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish
      		 
       152017-03-20 14:39:20 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish

      The progress reporting starts with the following message:

      InnoDB: Progress in percents: 1

      And then the following message is intermixed on the same line:

      2017-03-20 13:32:25 140737353812224 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 102852718183039

      And you can see the same happening when the following progress report message is written:

       2 3 4 5 6 7 8 9 10 11 12 13

      And then the following shutdown log message is intermixed on the same line:

      2017-03-20 14:27:15 140710228216576 [Note] /usr/sbin/mysqld: Normal shutdown

      After the shutdown request, the progress report messages become even harder to pick out, as each one is mixed in with its own message about waiting on active transactions.

      Here's the progress report for 14%:

       142017-03-20 14:33:19 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish

      And 15%:

       152017-03-20 14:39:20 140710228216576 [Note] InnoDB: Waiting for 1 active transactions to finish

      We should probably change how these progress report messages are printed, so that they aren't intermixed with unrelated log messages.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22577 innodb_fast_shutdown=0 fails to report purge progress

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-13797 InnoDB may hang if shutdown is initiated soon after startup, while rolling back recovered incomplete transactions

          • Major - Major loss of function.
          • Closed

          Task - A task that needs to be done. MDEV-14705 systemd: EXTEND_TIMEOUT_USEC= to avoid startup and shutdown timeouts

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            People

              marko Marko Mäkelä
              GeoffMontee Geoff Montee (Inactive)
              Votes:
              1 Vote for this issue
              Watchers:
              3 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.