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: | |
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) |
[25 May 23:12]
Mark Vollbrecht
[27 May 18:27]
MySQL Verification Team
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.
[17 Jun 7:20]
MySQL Verification Team
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.
[23 Jun 18:00]
Jeffrey DeLong
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.
[23 Jun 18:08]
Jeffrey DeLong
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.