Description:
2023-06-16T15:13:12.685445Z 0 [ERROR] [MY-012611] [InnoDB] Operating system error number 1460 in a file operation.
2023-06-16T15:13:12.685491Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: os0file.cc:7022:slot->is_reserved thread 9968
2023-06-16T15:13:12Z UTC - mysqld got exception 0x16 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
2023-06-16T15:13:12.688247Z 0 [ERROR] [MY-012646] [InnoDB] File .\undo_002: 'aio write' returned OS error 1560. Cannot continue operation
2023-06-16T15:13:12.688733Z 0 [ERROR] [MY-012981] [InnoDB] Cannot continue operation.
When it restarts he is what the log shows:
2023-06-16T15:38:30.873348Z 0 [Note] [MY-013847] [Server] Using jemalloc.dll for my_malloc and ut::malloc etc.
2023-06-16T15:38:31.133304Z 0 [Note] [MY-010949] [Server] Basedir set to C:\mysql\mysql8.0.31\.
2023-06-16T15:38:31.133317Z 0 [System] [MY-010116] [Server] C:\mysql\mysql8.0.31\bin\mysqld.exe (mysqld 8.0.31) starting as process 13000
2023-06-16T15:38:31.165394Z 0 [Note] [MY-012366] [InnoDB] Using Windows native AIO
2023-06-16T15:38:31.165851Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2023-06-16T15:38:31.166183Z 0 [Note] [MY-010747] [Server] Plugin 'ndbcluster' is disabled.
2023-06-16T15:38:31.166453Z 0 [Note] [MY-010747] [Server] Plugin 'ndbinfo' is disabled.
2023-06-16T15:38:31.166696Z 0 [Note] [MY-010747] [Server] Plugin 'ndb_transid_mysql_connection_map' is disabled.
2023-06-16T15:38:31.167035Z 0 [Note] [MY-010747] [Server] Plugin 'mysqlx' is disabled.
2023-06-16T15:38:31.169582Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2023-06-16T15:38:31.169889Z 1 [Note] [MY-013546] [InnoDB] Atomic write enabled
2023-06-16T15:38:31.170823Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2023-06-16T15:38:31.171122Z 1 [Note] [MY-012945] [InnoDB] _mm_lfence() and _mm_sfence() are used for memory barrier
2023-06-16T15:38:31.171468Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.12
2023-06-16T15:38:31.173404Z 1 [Note] [MY-012951] [InnoDB] Using hardware accelerated crc32 and polynomial multiplication.
2023-06-16T15:38:31.174418Z 1 [Note] [MY-012203] [InnoDB] Directories to scan '.\'
2023-06-16T15:38:31.174792Z 1 [Note] [MY-012204] [InnoDB] Scanning '.\'
2023-06-16T15:38:31.214038Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 250 files.
2023-06-16T15:38:31.216584Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 8.000000G, instances = 2, chunk size =128.000000M
2023-06-16T15:38:31.466728Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2023-06-16T15:38:31.498357Z 1 [Note] [MY-013532] [InnoDB] Using '.\#ib_16384_0.dblwr' for doublewrite
2023-06-16T15:38:31.499072Z 1 [Note] [MY-013532] [InnoDB] Using '.\#ib_16384_1.dblwr' for doublewrite
2023-06-16T15:38:31.516768Z 1 [Note] [MY-013566] [InnoDB] Double write buffer files: 2
2023-06-16T15:38:31.517052Z 1 [Note] [MY-013565] [InnoDB] Double write buffer pages per instance: 4
2023-06-16T15:38:31.517441Z 1 [Note] [MY-013532] [InnoDB] Using '.\#ib_16384_0.dblwr' for doublewrite
2023-06-16T15:38:31.517823Z 1 [Note] [MY-013532] [InnoDB] Using '.\#ib_16384_1.dblwr' for doublewrite
2023-06-16T15:38:31.595383Z 1 [Note] [MY-013883] [InnoDB] The latest found checkpoint is at lsn = 8827579191 in redo log file .\#innodb_redo\#ib_redo2695.
2023-06-16T15:38:31.596852Z 1 [Note] [MY-012560] [InnoDB] The log sequence number 5986749796 in the system tablespace does not match the log sequence number 8827579191 in the redo log files!
2023-06-16T15:38:31.597446Z 1 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2023-06-16T15:38:31.597715Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2023-06-16T15:38:31.611767Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 8827578931, whereas checkpoint_lsn = 8827579191 and start_lsn = 8827578880
2023-06-16T15:38:31.612278Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 8827591131
2023-06-16T15:38:31.671344Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2023-06-16T15:38:31.672458Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 118 redo log records ...
2023-06-16T15:38:31.675634Z 1 [Note] [MY-012533] [InnoDB] 10%
2023-06-16T15:38:31.676203Z 1 [Note] [MY-012533] [InnoDB] 20%
2023-06-16T15:38:31.676544Z 1 [Note] [MY-012533] [InnoDB] 30%
2023-06-16T15:38:31.676791Z 1 [Note] [MY-012533] [InnoDB] 40%
2023-06-16T15:38:31.677272Z 1 [Note] [MY-012533] [InnoDB] 50%
2023-06-16T15:38:31.677516Z 1 [Note] [MY-012533] [InnoDB] 60%
2023-06-16T15:38:31.683944Z 1 [Note] [MY-012533] [InnoDB] 70%
2023-06-16T15:38:31.684480Z 1 [Note] [MY-012533] [InnoDB] 80%
2023-06-16T15:38:31.684745Z 1 [Note] [MY-012533] [InnoDB] 90%
2023-06-16T15:38:31.685041Z 1 [Note] [MY-012533] [InnoDB] 100%
2023-06-16T15:38:32.187198Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2023-06-16T15:38:32.357348Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace '.\undo_001'.
2023-06-16T15:38:32.358518Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace '.\undo_002'.
2023-06-16T15:38:32.361114Z 1 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2023-06-16T15:38:32.361567Z 1 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 15181820
2023-06-16T15:38:32.376146Z 1 [Note] [MY-013776] [InnoDB] Parallel initialization of rseg complete
2023-06-16T15:38:32.376477Z 1 [Note] [MY-013777] [InnoDB] Time taken to initialize rseg using 4 thread: 14930 ms.
2023-06-16T15:38:32.378977Z 1 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"
2023-06-16T15:38:32.379410Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2023-06-16T15:38:32.380280Z 1 [Note] [MY-012265] [InnoDB] Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-06-16T15:38:32.430893Z 1 [Note] [MY-012266] [InnoDB] File '.\ibtmp1' size is now 12 MB.
2023-06-16T15:38:32.432026Z 1 [Note] [MY-013627] [InnoDB] Scanning temp tablespace dir:'.\#innodb_temp\'
2023-06-16T15:38:32.546145Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2023-06-16T15:38:32.547456Z 1 [Note] [MY-012976] [InnoDB] 8.0.31 started; log sequence number 8827591267
2023-06-16T15:38:32.547924Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2023-06-16T15:38:32.564075Z 1 [Note] [MY-011089] [Server] Data dictionary restarting version '80023'.
2023-06-16T15:38:32.695781Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2023-06-16T15:38:33.029830Z 1 [Note] [MY-012356] [InnoDB] Scanned 252 tablespaces. Validated 252.
2023-06-16T15:38:33.059573Z 1 [Note] [MY-010006] [Server] Using data dictionary with version '80023'.
2023-06-16T15:38:33.117782Z 0 [Note] [MY-013911] [Server] Crash recovery finished in InnoDB engine. No attempts to commit, rollback or prepare any transactions.
2023-06-16T15:38:33.122949Z 0 [Note] [MY-012487] [InnoDB] DDL log recovery : begin
2023-06-16T15:38:33.123399Z 0 [Note] [MY-012488] [InnoDB] DDL log recovery : end
How to repeat:
It happens once a week but there is no way to reproduce. CPU spikes to 100% and then MySQL crashes. We then have to stop and start the service for it to recover. Brand new server 24GB ram with SSD drives 4 CPU Sockets and 16 Virtual Processors running on Hypervison with average CPU of 28%
