MySQL Bugs: #118265: mysqld hangs durning startup

Bug #118265	mysqld hangs durning startup
Submitted:	25 May 23:12	Modified:	17 Jun 7:20
Reporter:	Mark Vollbrecht	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	9.3.0	OS:	MacOS (15.4.1 (24E263))
Assigned to:		CPU Architecture:	x86 (Quad-Core Intel Core i7)

Description:
I use homebrew to install and update mysql since 8.0.30.
After upgrading from 9.2.0 to 9.3.0, I started getting the error when running the mysql command:
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/tmp/mysql.sock' (2)

After researching that issue and trying to figure out why the '/tmp/mysql.sock' was missing, I finally looked at the Activity Monitor and saw that mysqld was running at or close to 100% CPU.

I tried using 'brew services stop mysql' to stop mysqld, but it didn't stop. I finally had to use a 'kill -9' to stop it.

I reinstalled mysql using 'brew uninstall mysql' and 'brew install mysql'. With the same results.

I updated the command used to start mysqld with the log-error-verbosity option set to 3. Running the command:
/usr/local/opt/mysql/bin/mysqld --basedir=/usr/local/opt/mysql --datadir=/usr/local/var/mysql --plugin-dir=/usr/local/opt/mysql/lib/plugin --log-error=Marks-MacBook-Pro.local.err --pid-file=Marks-MacBook-Pro.local.pid --log-error-verbosity=3

I got the following log entries:

Log entries when starting mysqld with log_error_verbosity=3
===========================================================
2025-05-18T22:44:13.166693Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2025-05-18T22:44:13.399374Z 0 [Note] [MY-010098] [Server] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2025-05-18T22:44:13.399415Z 0 [Note] [MY-010949] [Server] Basedir set to /usr/local/Cellar/mysql/9.3.0/.
2025-05-18T22:44:13.399423Z 0 [System] [MY-010116] [Server] /usr/local/opt/mysql/bin/mysqld (mysqld 9.3.0) starting as process 86081
2025-05-18T22:44:13.402766Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /usr/local/var/mysql/ is case insensitive
2025-05-18T22:44:13.431382Z 0 [Note] [MY-015140] [InnoDB] Using innodb_flush_method=fsync
2025-05-18T22:44:13.431611Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2025-05-18T22:44:13.431682Z 0 [Note] [MY-010747] [Server] Plugin 'ndbcluster' is disabled.
2025-05-18T22:44:13.431704Z 0 [Note] [MY-010747] [Server] Plugin 'ndbinfo' is disabled.
2025-05-18T22:44:13.431717Z 0 [Note] [MY-010747] [Server] Plugin 'ndb_transid_mysql_connection_map' is disabled.
2025-05-18T22:44:13.432991Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2025-05-18T22:44:13.433017Z 1 [Note] [MY-013546] [InnoDB] Atomic write enabled
2025-05-18T22:44:13.433081Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2025-05-18T22:44:13.433101Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier
2025-05-18T22:44:13.433113Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.3.1
2025-05-18T22:44:13.436381Z 1 [Note] [MY-012951] [InnoDB] Using hardware accelerated crc32 and polynomial multiplication.
2025-05-18T22:44:13.436831Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './'
2025-05-18T22:44:13.436897Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2025-05-18T22:44:13.439164Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 15 files.
2025-05-18T22:44:13.439705Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M
2025-05-18T22:44:13.463335Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2025-05-18T22:44:13.466573Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2025-05-18T22:44:13.475594Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2025-05-18T22:44:13.497704Z 1 [Note] [MY-013566] [InnoDB] Double write buffer files: 2
2025-05-18T22:44:13.497743Z 1 [Note] [MY-013565] [InnoDB] Double write buffer pages per instance: 128
2025-05-18T22:44:13.497816Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2025-05-18T22:44:13.497880Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2025-05-18T22:44:13.539267Z 1 [Note] [MY-013883] [InnoDB] The latest found checkpoint is at lsn = 1778285177 in redo log file ./#innodb_redo/#ib_redo543.
2025-05-18T22:44:13.539369Z 1 [Note] [MY-012560] [InnoDB] The log sequence number 1778279708 in the system tablespace does not match the log sequence number 1778285177 in the redo log files!
2025-05-18T22:44:13.539391Z 1 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2025-05-18T22:44:13.539404Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2025-05-18T22:44:13.545159Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 1778285177, whereas checkpoint_lsn = 1778285177 and start_lsn = 1778285056
2025-05-18T22:44:13.545213Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 1778285177
2025-05-18T22:44:13.545226Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ...
2025-05-18T22:44:13.545278Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2025-05-18T22:44:13.650844Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2025-05-18T22:44:13.654910Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2025-05-18T22:44:13.656044Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2025-05-18T22:44:13.658420Z 1 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2025-05-18T22:44:13.658566Z 1 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 662356
2025-05-18T22:44:13.701494Z 1 [Note] [MY-013776] [InnoDB] Parallel initialization of rseg complete
2025-05-18T22:44:13.701541Z 1 [Note] [MY-013777] [InnoDB] Time taken to initialize rseg using 4 thread: 42 ms.
2025-05-18T22:44:13.702017Z 1 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"
2025-05-18T22:44:13.702041Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2025-05-18T22:44:13.702262Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2025-05-18T22:44:13.707885Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.
2025-05-18T22:44:13.708071Z 1 [Note] [MY-013627] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'
2025-05-18T22:44:13.714555Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2025-05-18T22:44:13.714741Z 1 [Note] [MY-012976] [InnoDB] 9.3.0 started; log sequence number 1778285187
2025-05-18T22:44:13.715323Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2025-05-18T22:44:13.722258Z 1 [Note] [MY-013327] [Server] MySQL server upgrading from version '90200' to '90300'.
2025-05-18T22:44:13.843981Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2025-05-18T22:44:13.856215Z 1 [Note] [MY-012356] [InnoDB] Scanned 17 tablespaces. Validated 17.

This is where it hangs until I do a kill -9 to stop it.

How to repeat:
Don't know how to repeat.

Hi,
I had 8.0.40 on my 15.5 and I just upgraded to 8.0.42 -> 8.4.5 -> 9.3.0 without a problem. I have a rather large db here with a lot of tables, no issues to speak of, upgraded and runs without a problem.

I see in your log that it has to repair crashed system and then fails upgrading it. Not sure if this is from the first time or this crash is from you killing after it hang the last time?

There is not enough data in the log to know what was going on there. You should be able to generate a core from a stuck mysqld by

gdb --pid <mysqld_process_id> --batch -ex generate-core-file

or by killing it with -11 

then you can load the core file with gdb and see where it got stuck.

Hi,

I did reproduce with your datadir. Verified.

2025-06-17T07:18:49.6NZ mysqld_safe Logging to '/opt/homebrew/var/mysql/BogdanMBPROM3MAX.local.lan.err'.
2025-06-17T07:18:49.6NZ mysqld_safe Starting mysqld daemon with databases from /opt/homebrew/var/mysql
2025-06-17T07:18:49.599049Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2025-06-17T07:18:49.738489Z 0 [System] [MY-010116] [Server] /opt/homebrew/opt/mysql/bin/mysqld (mysqld 9.3.0) starting as process 11351
2025-06-17T07:18:49.740755Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /opt/homebrew/var/mysql/ is case insensitive
2025-06-17T07:18:49.744208Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2025-06-17T07:18:49.993613Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.

Having the exact same issue on macOS Sequoia 15.5, trying to update from 8.4.4 -> 8.4.5. The verbose log is pretty much identical to the one supplied by the OP.

Log file for documentation purposes. M1 Mac. Homebrew mysql@8.4 installation. Once mysqld is started, it just jumps right up to 100% or more, hangs, and renders mysql useless. My suspicion is that the Innodb was corrupted, but I'm unable to prove that theory.

As a test, I also used the mysql native installers and everything ran just fine out of a clean install. So, it's not the laptop, but the Homebrew mysql@8.4 installation having issues. I do not want to update to 9 if I don't have to.

2025-06-23T17:50:23.870144Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2025-06-23T17:50:24.044824Z 0 [Warning] [MY-010097] [Server] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2025-06-23T17:50:24.045132Z 0 [Note] [MY-010949] [Server] Basedir set to /opt/homebrew/Cellar/mysql@8.4/8.4.5/.
2025-06-23T17:50:24.045134Z 0 [System] [MY-010116] [Server] /opt/homebrew/opt/mysql@8.4/bin/mysqld (mysqld 8.4.5) starting as process 43395
2025-06-23T17:50:24.052451Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /opt/homebrew/var/mysql/ is case insensitive
2025-06-23T17:50:24.068923Z 0 [Note] [MY-015140] [InnoDB] Using innodb_flush_method=fsync
2025-06-23T17:50:24.070266Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2025-06-23T17:50:24.070486Z 0 [Note] [MY-010747] [Server] Plugin 'ndbcluster' is disabled.
2025-06-23T17:50:24.070666Z 0 [Note] [MY-010747] [Server] Plugin 'ndbinfo' is disabled.
2025-06-23T17:50:24.070681Z 0 [Note] [MY-010747] [Server] Plugin 'ndb_transid_mysql_connection_map' is disabled.
2025-06-23T17:50:24.076491Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2025-06-23T17:50:24.076722Z 1 [Note] [MY-013546] [InnoDB] Atomic write enabled
2025-06-23T17:50:24.077057Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2025-06-23T17:50:24.077094Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier
2025-06-23T17:50:24.077107Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.3.1
2025-06-23T17:50:24.079501Z 1 [Note] [MY-012951] [InnoDB] Using hardware accelerated crc32 and polynomial multiplication.
2025-06-23T17:50:24.080758Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './'
2025-06-23T17:50:24.081219Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2025-06-23T17:50:24.083851Z 1 [Note] [MY-013503] [InnoDB] Directory '/opt/homebrew/var/mysql/.DS_Store' will not be scanned because it is a hidden directory.
2025-06-23T17:50:24.963330Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 3114 files.
2025-06-23T17:50:24.964268Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M 
2025-06-23T17:50:24.965911Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2025-06-23T17:50:24.968392Z 1 [Note] [MY-013503] [InnoDB] Directory '/opt/homebrew/var/mysql/.DS_Store' will not be scanned because it is a hidden directory.
2025-06-23T17:50:24.968956Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2025-06-23T17:50:24.974215Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2025-06-23T17:50:24.985667Z 1 [Note] [MY-013503] [InnoDB] Directory '/opt/homebrew/var/mysql/.DS_Store' will not be scanned because it is a hidden directory.
2025-06-23T17:50:24.986105Z 1 [Note] [MY-013566] [InnoDB] Double write buffer files: 2
2025-06-23T17:50:24.986139Z 1 [Note] [MY-013565] [InnoDB] Double write buffer pages per instance: 128
2025-06-23T17:50:24.986201Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2025-06-23T17:50:24.986261Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2025-06-23T17:50:25.013892Z 1 [Note] [MY-013883] [InnoDB] The latest found checkpoint is at lsn = 6479012155 in redo log file ./#innodb_redo/#ib_redo1978.
2025-06-23T17:50:25.014161Z 1 [Note] [MY-012560] [InnoDB] The log sequence number 6476634779 in the system tablespace does not match the log sequence number 6479012155 in the redo log files!
2025-06-23T17:50:25.014212Z 1 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2025-06-23T17:50:25.014259Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2025-06-23T17:50:25.033003Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 6479011878, whereas checkpoint_lsn = 6479012155 and start_lsn = 6479011840
2025-06-23T17:50:25.033048Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 6479012155
2025-06-23T17:50:25.034477Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2025-06-23T17:50:25.034853Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ...
2025-06-23T17:50:25.034878Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2025-06-23T17:50:25.136990Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2025-06-23T17:50:25.138008Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2025-06-23T17:50:25.138942Z 1 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2025-06-23T17:50:25.138981Z 1 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 505866
2025-06-23T17:50:25.168282Z 1 [Note] [MY-013776] [InnoDB] Parallel initialization of rseg complete
2025-06-23T17:50:25.168323Z 1 [Note] [MY-013777] [InnoDB] Time taken to initialize rseg using 4 thread: 29 ms.
2025-06-23T17:50:25.170358Z 1 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"
2025-06-23T17:50:25.170374Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2025-06-23T17:50:25.170658Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2025-06-23T17:50:25.177305Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.
2025-06-23T17:50:25.177851Z 1 [Note] [MY-013627] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'
2025-06-23T17:50:25.187541Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2025-06-23T17:50:25.187683Z 1 [Note] [MY-012976] [InnoDB] 8.4.5 started; log sequence number 6479012165
2025-06-23T17:50:25.188513Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2025-06-23T17:50:25.201881Z 1 [Note] [MY-013327] [Server] MySQL server upgrading from version '80404' to '80405'.
2025-06-23T17:50:25.288566Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2025-06-23T17:50:26.501621Z 1 [Note] [MY-012356] [InnoDB] Scanned 3116 tablespaces. Validated 3116.