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

    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

            Activity

              People

              • Assignee:
                marko Marko Mäkelä
                Reporter:
                GeoffMontee Geoff Montee
              • Votes:
                1 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: