MySQL Bugs: #78844: InnoDB log recovery is too noisy.

Bug #78844	InnoDB log recovery is too noisy.
Submitted:	15 Oct 2015 11:35	Modified:	19 Oct 2015 10:26
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.7	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	innodb recovery, logging, noise

Description:
This is true also with 5.6.

After a crash and on innodb recovery you see logging of the form on a 5.7 server:

2015-10-15T11:07:02.722502Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 218472188171
2015-10-15T11:07:03.010307Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 218477430784
...
2015-10-15T11:09:57.451545Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 222879189213
2015-10-15T11:09:57.453030Z 0 [Note] InnoDB: Database was not shutdown normally!
2015-10-15T11:09:57.453046Z 0 [Note] InnoDB: Starting crash recovery.
...

The number of Doing recovery log lines seems rather excessive. The cause of the recovery is irrelevant here.

How to repeat:
See logging above.

Also I did some counts.
1686 log lines in this case in under 3 minutes.

For me the extra log lines don't actually give me anything useful. All they do is fill up the log file and often if looking for other things they need to be filtered out.

Any DBA is concerned about a database recovery so seeing the start of the process, and the end is important as is seeing that something is actually happening and progress is being made. The frequency of the logging in between is excessive.

Suggested fix:
I would be tempted to log at most 1 line per "period", say 5 or 10 seconds. This period probably should be configurable to suit different people's tastes, but an update every 10 seconds would give me 18 lines instead of nearly 100 times that.

I believe the recovery process here is single threaded so I would imagine that it should be straight forward to adjust such logging.

Hello Simon,

Thank you for the feature request!

Thanks,
Umesh

// 5.7.10

2015-10-16T09:21:53.770681Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 198035166
2015-10-16T09:21:53.770702Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 198035175
2015-10-16T09:21:53.771256Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 198035175
2015-10-16T09:21:53.771268Z 0 [Note] InnoDB: Database was not shutdown normally!
2015-10-16T09:21:53.771274Z 0 [Note] InnoDB: Starting crash recovery.
.
.
2015-10-16T09:21:54.015406Z 0 [Note] bin/mysqld: ready for connections.
Version: '5.7.10-enterprise-commercial-advanced'  socket: '/tmp/mysql_ushastry.sock'  port: 15000  MySQL Enterprise Server - Advanced Edition (Commercial)

I notice on a 5.6 server which is recovering from a crash:

...
InnoDB: Doing recovery: scanned up to log sequence number 603926961664
InnoDB: Doing recovery: scanned up to log sequence number 603932204544
InnoDB: Doing recovery: scanned up to log sequence number 603936216206
InnoDB: 984 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 658474 row operations to undo
InnoDB: Trx id counter is 74629376
2015-10-19 12:05:14 722 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 44 45 46 47 48 49 50 51 52 53 

What I miss here, during recovery, is to see more information apart from the sequence number.
Something more useful to a DBA such as:
- number of "Events" or "transactions" seen/processed
- the size of the iblog files processed so far.
- timestamp of the time in the iblog file

With the noisy logs as they are this information may not be worth adding but if the logs are somewhat less noisy this extra perspective might be helpful.