MySQL Bugs: #118358: Startup without Signs of Progress when Rolling-Back Big Transaction.

Bug #118358	Startup without Signs of Progress when Rolling-Back Big Transaction.
Submitted:	4 Jun 12:04	Modified:	4 Jul 7:55
Reporter:	Jean-François Gagné	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	8.0.42, 8.4.5 9.3.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Hi,

when a big transaction is rolled back on MySQL startup with default log verbosity, there are long gaps in the error logs.  See How to repeat for details (gaps of 29 seconds and 2.5 minutes; with the 29 second gap possibly being larger).

Filing this as a S2 / Serious, because such usability issues are not minor.  I do not think this is a S5 / Performance issue as this is not about making things faster.  There might be an argument to be made that this is a feature request, but I think such usability issues should be considered bugs.

I set this as category InnoDB, but this is also partially replication, see MY-010855 in Suggested fix.

How to repeat is for 8.4.5, but the behavior is similar for 8.0.42 and 9.3.0.

Related: Bug#116619 - Startup without Signs of Progress with Many Tables (1M+).

Many thanks for looking into this,

Jean-François Gagné

How to repeat:
Using How to repeat from Bug#118356, I have below in the logs for MySQL startup after the crash, see gaps of gaps of 29 seconds and 2.5 minutes after MY-013577 and MY-010229 (more about the 29-second gap in Suggested fix).

2025-06-02T18:17:04.258352Z mysqld_safe Number of processes running now: 0
2025-06-02T18:17:04.270971Z mysqld_safe mysqld restarted
2025-06-02T18:17:04.471809Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2025-06-02T18:17:04.668881Z 0 [System] [MY-010116] [Server] /home/jgagne/opt/mysql/mysql_8.4.5/bin/mysqld (mysqld 8.4.5) starting as process 8070
2025-06-02T18:17:04.685396Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2025-06-02T18:17:05.527229Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2025-06-02T18:17:34.546243Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2025-06-02T18:20:08.398560Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2025-06-02T18:20:08.840369Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2025-06-02T18:20:08.840402Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2025-06-02T18:20:08.940141Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 18405, socket: /tmp/mysqlx-18405.sock
2025-06-02T18:20:08.940225Z 0 [System] [MY-010931] [Server] /home/jgagne/opt/mysql/mysql_8.4.5/bin/mysqld: ready for connections. Version: '8.4.5'  socket: '/tmp/mysql_sandbox8405.sock'  port: 8405  MySQL Community Server - GPL.

Suggested fix:
The 29-second gap after MY-013577 can be much longer, example of an almost 3-minute gap with 5 MiB rows below (Bug#118356is with 1 MiB rows).

2025-04-15T21:57:31.434472Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2025-04-15T21:57:33.599140Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2025-04-15T22:00:20.883542Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2025-04-15T22:13:17.921353Z 0 [System] [MY-010232] [Server] XA crash recovery finished.

Also, even with log_error_verbosity=3, there is at least one significant gap, example of a 2-minute gap below after MY-010855.  So this is not only about changing the level of some log lines, new lines should be added.  And note "Relay log sanitization" in below, this is probably a mistake as this is a standalone primary without relay log.

2025-04-16T00:10:09.683156Z 0 [Note] [MY-010902] [Server] Thread priority attribute setting in Resource Group SQL shall be ignored due to unsupported platform or insufficient privilege.
2025-04-16T00:10:09.685606Z 0 [Note] [MY-010855] [Server] Recovering after a crash using binlog
2025-04-16T00:12:09.900570Z 0 [Note] [MY-015128] [Server] Relay log sanitization: The following log needs truncation: ; read up to: 19059240960
2025-04-16T00:12:09.900643Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...

Note that I blogged about this, link below.

https://jfg-mysql.blogspot.com/2025/06/interesting-troubleshooting-crash-filling-then-free...

Hello Jean-François,

Thank you for the report and feedback.
My apologies, was caught up in other bugs and I missed this. 
I'll first go through Bug #118356 and come back on this and request you if anything further needed. Thank you.

regards,
Umesh

Hello Jean-François,

After verifying Bug #118356(didn't use start-up script mysql_safe instead used mysql),  restarted the instance but not seeing the huge gap after MY-013577 which you had noticed in your tests. Is there anything I'm missing? Pls let me know. Thank you once again for read-to use steps.

-- 

2025-06-11T06:24:39.854114Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2025-06-11T06:24:40.127732Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.

cat  /dev/shm/118356/log.err |grep -i "Starting XA crash recovery"
2025-06-11T06:24:49.591328Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...

cat  /dev/shm/118356/log.err |grep -i "XA crash recovery finished"
2025-06-11T06:25:03.948087Z 0 [System] [MY-010232] [Server] XA crash recovery finished.

In my tests, datadir is hosted on /dev/shm/ (sorry to trigger low disk I had to use).

regards,
Umesh

To see gap, you need a big trx to rollback, maybe increase nb rows in repro of other bug to crash on a bigger trx while copying binlogs.

JFG - sorry for brief text, I am on my phone

Also, maybe try with log verbosity 3 to confirm big trx being rolledback.

Thank you, Jean-François.
Tomorrow will give it a try as you suggested and get back to you.

Sincerely,
Umesh

Hi,
this bug is in Analyzing since 11 Jun, is there anything I can do to help ?
Best, 
J-F Gagné

Thank you, Jean-François.

Sincerely,
Umesh

if ok，i want to have make a pitch to solve this。