Bug #83245 Log parsing buffer overflow
Submitted: 3 Oct 2016 12:21 Modified: 12 Jan 2017 13:14
Reporter: Tomislav Plavcic Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.7.15 OS:Any
Assigned to: CPU Architecture:Any
Tags: regression

[3 Oct 2016 12:21] Tomislav Plavcic
Description:
If I run specific sysbench load and then kill the server the following error can be seen in the error log and the server won't start again:
2016-09-30T17:38:23.338904Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 30625294331
2016-09-30T17:38:23.957237Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 30630536704
2016-09-30T17:38:50.705715Z 0 [ERROR] InnoDB: Log parsing buffer overflow. Recovery may have failed!
2016-09-30T17:38:50.705735Z 0 [ERROR] InnoDB: Set innodb_force_recovery to ignore this error.
2016-09-30T17:38:50.705747Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2016-09-30T17:38:51.306392Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2016-09-30T17:38:51.306417Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2016-09-30T17:38:51.306421Z 0 [ERROR] Failed to initialize plugins.
2016-09-30T17:38:51.306424Z 0 [ERROR] Aborting

I can only start the server by using —innodb-force-recovery=6 but that skips roll-forward of redo log.

How to repeat:
mysqld options:
--no-defaults --skip-external-locking --max_allowed_packet=16M --thread_stack=192K --thread_cache_size=8 --max_connections=4096 --query_cache_limit=1M --query_cache_size=16M --expire_logs_days=1 --max_binlog_size=100M --innodb_buffer_pool_size=24G --innodb_log_file_size=1G --innodb_log_buffer_size=64M --innodb_flush_log_at_trx_commit=0 --innodb_flush_method=O_DIRECT --innodb_io_capacity=1000 --innodb_io_capacity_max=10000 --innodb_checksum_algorithm=strict_crc32 --innodb_purge_threads=8 --innodb_flush_neighbors=0 --innodb_change_buffer_max_size=5 --innodb_flush_log_at_trx_commit=2 --innodb_max_dirty_pages_pct=95 --innodb_sync_array_size=4 --innodb_monitor_enable="%" --innodb_max_purge_lag=1000000 --innodb_max_purge_lag_delay=10000 --innodb_undo_tablespaces=2 --innodb_undo_log_truncate=1

sysbench prepare (it will run for some time depending on the machine):
sysbench --test=/usr/share/doc/sysbench/tests/db/oltp.lua --report-interval=1 --oltp-tables-count=100000 --oltp-table-size=1000 --max-time=0 --oltp-read-only=off --max-requests=0 --num-threads=64 --rand-type=pareto --db-driver=mysql --mysql-user=sbtest --mysql-password=sbtest --mysql-db=sbtest prepare

sysbench run:
sysbench --test=/usr/share/doc/sysbench/tests/db/oltp.lua --report-interval=1 --oltp-tables-count=100000 --oltp-table-size=1000 --max-time=0 --oltp-read-only=off --max-requests=0 --num-threads=64 --rand-type=pareto --db-driver=mysql --mysql-user=root --mysql-db=sbtest run

After the sysbench has been running for 10 min just kill the server with something like "sudo kilall -9 mysqld" and then try to start the server again.

Suggested fix:
Fix the error or possibly make the server startable by using some lower value for innodb_force_recovery.
[4 Oct 2016 7:25] Umesh Shastry
Hello Tomislav,

Thank you for the report.
Observed this with 5.7.15 using provided steps.

Thanks,
Umesh
[4 Oct 2016 7:26] Umesh Shastry
test results

Attachment: 83245_5_7_15.results (application/octet-stream, text), 17.97 KiB.

[4 Oct 2016 7:50] Tomislav Plavcic
Let me just mention that the credit for the bug goes to Peter Zaitsev...
[25 Nov 2016 21:28] Peter Zaitsev
Note this bug is a regression MySQL 5.6 does not have this issue
[30 Nov 2016 7:25] Tomislav Plavcic
Changing the Severity to S1 because it seems to be more correct.
[12 Jan 2017 13:14] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 5.7.18, 8.0.1 release, and here's the changelog entry:

During a checkpoint, all MLOG_FILE_NAME redo log records were written in
a single mini-transaction (mtr), causing a log parsing buffer overflow.

Thank you for the bug report.