MySQL Bugs: #116619: Startup without Signs of Progress with Many Tables (1M+).

Bug #116619	Startup without Signs of Progress with Many Tables (1M+).
Submitted:	11 Nov 2024 20:52	Modified:	20 Aug 21:13
Reporter:	Jean-François Gagné	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S2 (Serious)
Version:	8.0.39, 8.0.40, 8.4.3, 9.1.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Hi,

when starting MySQL with many tables and default log verbosity, there are long gaps in the error logs.  See How to repeat for details (gaps of 6 and 1 minutes).

I would expect long startup operations to regularly output a log message to reassure the operator that things are not blocked.  This is what is done with log_error_verbosity of 3, but the default is 2, and I would expect regular signs of progress with the default value.

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 issues should be considered bugs.

I reported this for 8.0.39 because the logs I have in How to repeat are for this version (sorry, opening this bug is pending on my side for some time), but I think 8.0.40, 8.4.3 and 9.1.0 are also affected.

I might eventually submit a patch for this.

Many thanks for looking into this,

Jean-François Gagné

How to repeat:
See Bug#115988 for a script to create many tables.

Start MySQL with default log verbosity and many tables (1M+), the output should look similar to below.  Log message MY-013576 is at 2024-08-26T02:12:58, with the next line 6 minutes later, which is too long a gap.  Also, MY-013577 is at 2024-08-26T02:19:00, with the next line 1 minute later, which is also too long a gap.

2024-08-26T02:12:54.209842Z mysqld_safe Logging to '/home/jgagne/sandboxes/msb_mysql_8_0_39/data/msandbox.err'.
2024-08-26T02:12:54.282572Z mysqld_safe Starting mysqld daemon with databases from /home/jgagne/sandboxes/msb_mysql_8_0_39/data
2024-08-26T02:12:57.668709Z 0 [System] [MY-010116] [Server] /home/jgagne/opt/mysql/mysql_8.0.39/bin/mysqld (mysqld 8.0.39) starting as process 66873
2024-08-26T02:12:58.409124Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-08-26T02:19:00.014759Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-08-26T02:20:03.386016Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2024-08-26T02:20:03.386062Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2024-08-26T02:20:03.545458Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 18039, socket: /tmp/mysqlx-18039.sock
2024-08-26T02:20:03.545591Z 0 [System] [MY-010931] [Server] /home/jgagne/opt/mysql/mysql_8.0.39/bin/mysqld: ready for connections. Version: '8.0.39'  socket: '/tmp/mysql_sandbox8039.sock'  port: 8039  MySQL Community Server - GPL.

Hello Jean-François,

Thank you for the report and feedback.

regards,
Umesh

> I might eventually submit a patch for this.

The probability of me submitting a patch for this should be considered very low: I am not working on this and not planning to work on this for the next months.  Sorry for the shifting priorities on my side.

Posted by developer:
 
Thank you for the bug report. We believe the fix for Bug#38031020, which unfortunately does not have corresponding external bug number, will also address this issue by issuing periodic status messages to the error log while performing checks during upgrade.
Bug#38031020 is expected to be part of 10.0, 9.7.1, and 8.4.10

As a result this bug has been closed as duplicate.

> [Dyre Tjeldvoll on 28 Apr]: As a result this bug has been closed as duplicate.
>
> [Bug Status on 21 Jul]: Verified

Above is confusing: is this bug still opened, or is it closed ?

Also, I am not finding any reference to Bug#38031020 in the Release Notes: was this shipped ?

I would suggest not closing public bugs as Duplicate of private bugs.  I think it would be better to close them as fixed by another bug, but only when this other bug is ready to ship, and when there is a Release Note quote to attach to the bug.

Posted by developer:
 
I can confirm that Bug#38031020 was fixed. From that bug report I see:

"Added the following note to the MySQL Server 8.4.11, 9.7.2, and 26.7.0 release notes:

Upgrading from older 8.x releases with thousands of tables, views, routines, 
and events caused the memory consumed by server to grow continuously, 
leading to significant memory spikes.
Memory management is improved for these scenarios."

It is unfortunate that my earlier comment references 10.0, but that was written before the new versioning scheme was announced.

Your suggestion regarding the closing of public bugs is appreciated.

Thanks for the reply Dyre, and no problem about v10.

I did not find the fix in 9.7.1, so I will wait for 9.7.2.

It looks like Bug#38031020 and Bug#117983 are related, and that this bug (Bug#116619) has been solved at the same time as Bug#117983.

I am not seeing this fixed in 8.4.11.  I have not checked for 9.7.2 and 26.7.0 because it needs more than 1 hour to run below script for 8.4.11 (I initially wanted to run the loop for 8.4.10, 8.4.11, 9.7.1, 9.7.2 and 26.7.0, but it looks useless right now).

Coming back to Dyre Tjeldvoll comment from 28 Apr...

> We believe the fix for Bug#38031020 [...] will also address this issue by issuing periodic status messages to the error log while performing checks during upgrade.

It looks like Bug#38031020 added "periodic status messages to the error log while performing checks during upgrade", but this report is not limited to upgrades, it also applies to normal MySQL Startup.

In below, see 90 second gap in logging between 20:44:54 and 20:46:33 during a startup taking 02:15.

# Below is done on an AWS m6id.large instance (2 vcpus, 1 cores, 8 GB RAM and 118 GB SSD).

# Using the below utility functions from Bug#115988.
# - status_string;
# - start;
# - stop;
# - create_tables.

n=1000000
for mv in 8.4.11; do
  cd; dbdeployer deploy single mysql_$mv > /dev/null
  cd ~/sandboxes/msb_mysql_${mv//./_}

  create_tables
  stop; rm data/msandbox.err
  start | grep -v -e diskstats
  cp data/msandbox.err ../msandbox.err.$mv
  stop; cd; rm -rf ~/sandboxes/msb_mysql_${mv//./_}
done

8.4.11  creating: 1:13:32
8.4.11     start: 0:02:15

cat ~/sandboxes/msandbox.err.8.4.11
2026-08-20T20:44:51.183626Z mysqld_safe Logging to '/home/jgagne/sandboxes/msb_mysql_8_4_11/data/msandbox.err'.
2026-08-20T20:44:51.257172Z mysqld_safe Starting mysqld daemon with databases from /home/jgagne/sandboxes/msb_mysql_8_4_11/data
2026-08-20T20:44:53.768247Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2026-08-20T20:44:54.342565Z 0 [System] [MY-010116] [Server] /home/jgagne/opt/mysql/mysql_8.4.11/bin/mysqld (mysqld 8.4.11) starting as process 35326
2026-08-20T20:44:54.679682Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2026-08-20T20:46:33.278089Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2026-08-20T20:47:04.831630Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2026-08-20T20:47:04.831669Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2026-08-20T20:47:04.940201Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 18411, socket: /tmp/mysqlx-18411.sock
2026-08-20T20:47:04.940267Z 0 [System] [MY-010931] [Server] /home/jgagne/opt/mysql/mysql_8.4.11/bin/mysqld: ready for connections. Version: '8.4.11'  socket: '/tmp/mysql_sandbox8411.sock'  port: 8411  MySQL Community Server - GPL.