[MDEV-12323] Rollback progress log messages during crash recovery are intermixed with unrelated log messages Created: 2017-03-21  Updated: 2020-08-25  Resolved: 2017-12-13

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.20
Fix Version/s: 10.0.34, 10.1.30, 10.2.12, 10.3.3

Type: Bug Priority: Minor
Reporter: Geoff Montee (Inactive) Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: innodb, rollback

Issue Links:
Relates
relates to MDEV-22577 innodb_fast_shutdown=0 fails to repor... Closed
relates to MDEV-13797 InnoDB may hang if shutdown is initia... Closed
relates to MDEV-14705 systemd: EXTEND_TIMEOUT_USEC= to avoi... Closed

 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.



 Comments   
Comment by Marko Mäkelä [ 2017-12-13 ]

The messages will be displayed every 15 seconds, just like the crash recovery messages that were introduced in MDEV-11027.

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