Bug #120758 Add logging for redo log scan performance statistics

• Submitted: 24 Jun 6:13
• Reporter: Venkatesh Duggirala (OCA)
• Status: Open
• Category: MySQL Server: InnoDB storage engine
• Severity: S3 (Non-critical)
• OS: Any
• CPU Architecture: Any

[24 Jun 6:13] Venkatesh Duggirala

Description:
It will be helpful to add timing measurements for the IO read and parsing phases during redo log scanning, tracking the number of IO calls, some statistics including scanned MB, total IO calls, IO time, and parse time are logged periodically during the scan.

These measurements will be helpful for debugging crash recovery time.

How to repeat:
Code Walk through of this function

https://github.com/mysql/mysql-server/blob/trunk/storage/innobase/log/log0recv.cc#L3622C16...

Suggested fix:
Calculate all the statistics in the above function and dump a message towards the end in the error log something similar below :
  

   ib::info() << "Recovery Stats: "
                 << "Scanned=" << scanned_mb << "MB, "
                 << "IO Calls=" << total_ios << ", "
                 << "IO Time=" << io_ms << "ms, "
                 << "Parse Time=" << parse_ms << "ms, "
                 << "Scan Rate=" << std::fixed << std::setprecision(2)
                 << ((double)scanned_mb /
                     (std::max(1.0, (double)(io_ms + parse_ms)) / 1000.0))
                 << "MB/s";

[14 Jul 14:43] Jakub Lopuszanski

Hello Venkatesh, and thank you for your report.
I'd like to better understand your use case.
In particular even today, you can take a look at error log messages like
```
2026-07-14T14:08:34.465464Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2026-07-14T14:08:34.471700Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 22798357, whereas checkpoint_lsn = 22798671 and start_lsn = 22798336
2026-07-14T14:08:34.471808Z 1 [Note] [MY-016004] [InnoDB] Starting to parse redo log at lsn = 22798357, whereas checkpoint_lsn = 22798671
2026-07-14T14:08:34.534702Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 23166971
2026-07-14T14:08:34.534846Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 28 redo log records ...
2026-07-14T14:08:34.736573Z 1 [Note] [MY-012533] [InnoDB] 100%
2026-07-14T14:08:34.755224Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
```
to deduce from them that 
1. end-to-end duration was 08:34.755224 - 08:34.465464
2. applying deltas took 08:34.755224 - 08:34.534846
3. ios+parsing took 08:34.534846 - 08:34.465464
then the remaining info, about the duration and number of IOs can be gained from performance schema:
```
 SELECT
   FILE_NAME,
   COUNT_READ,
   ROUND(SUM_NUMBER_OF_BYTES_READ / 1024 / 1024, 2) AS read_mib,
   ROUND(SUM_TIMER_READ / 1e9, 3) AS read_ms
 FROM performance_schema.file_summary_by_instance
 WHERE EVENT_NAME = 'wait/io/file/innodb/innodb_log_file'
 ORDER BY SUM_NUMBER_OF_BYTES_READ DESC;
```
This presents results like (these particular results are not from the same run as the log above):
```
+------------------------------------------------------------+------------+----------+---------+
| FILE_NAME                                                  | COUNT_READ | read_mib | read_ms |
+------------------------------------------------------------+------------+----------+---------+
| C:\ade\mysql\12\mysql-bin\data\#innodb_redo\#ib_redo17     |          8 |     0.07 |   0.714 |
| C:\ade\mysql\12\mysql-bin\data\#innodb_redo\#ib_redo18_tmp |          0 |     0.00 |       0 |
...
```
Knowing how much time was spend on IO, you can then figure out the time spent on parsing.

I'd rather make performance schema more useful, then put more info into the error logs, as I believe the error log should be about errors, and performance schema about performance.
Also, there's some risk of putting information in the log in a "too specific" format, as then people start writing parsers and rely on the format, which ties our hands if we ever want to make some changes, like (say) parallel parsing, or overlapping parsing with io, etc.