Mysql crash and restart takes six hours

MySQL & MariaDB Percona Server for MySQL 5.7
1

what can I do to reduce the starting time
mysql5.7.31
the start log:

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash. 
2022-12-06T01:33:51.398988Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 
2022-12-06T01:33:51.399118Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled 2022-12-06T01:33:51.399151Z 0 [Note] /usr/local/mysql2/bin/mysqld (mysqld 5.7.32-log) starting as process 29449 ... 
2022-12-06T01:33:51.886174Z 0 [Note] InnoDB: PUNCH HOLE support available 
2022-12-06T01:33:51.886196Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 
2022-12-06T01:33:51.886199Z 0 [Note] InnoDB: Uses event mutexes 
2022-12-06T01:33:51.886202Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier 
2022-12-06T01:33:51.886205Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 
2022-12-06T01:33:51.886208Z 0 [Note] InnoDB: Using Linux native AIO 
2022-12-06T01:33:51.886497Z 0 [Note] InnoDB: Number of pools: 1 
2022-12-06T01:33:51.886612Z 0 [Note] InnoDB: Using CPU crc32 instructions 
2022-12-06T01:33:51.888298Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 
2022-12-06T01:33:51.900187Z 0 [Note] InnoDB: Completed initialization of buffer pool 
2022-12-06T01:33:51.908559Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 
2022-12-06T01:33:52.162977Z 0 [Note] InnoDB: Highest supported file format is Barracuda. 
2022-12-06T01:33:52.306201Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 69879080507466 
2022-12-06T01:33:52.922120Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 69879080770444 
2022-12-06T01:33:52.922157Z 0 [Note] InnoDB: Database was not shutdown normally! 
2022-12-06T01:33:52.922162Z 0 [Note] InnoDB: Starting crash recovery. 
2022-12-06T01:38:25.748511Z 0 [Note] InnoDB: 5 transaction(s) which must be rolled back or cleaned up in total 26093901 row operations to undo 
2022-12-06T01:38:25.749995Z 0 [Note] InnoDB: Trx id counter is 2856569600 
2022-12-06T01:38:25.750009Z 0 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99  
2022-12-06T01:38:27.937131Z 0 [Note] InnoDB: Apply batch completed
2022-12-06T04:14:16.554205Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 9624243ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.) 
2022-12-06T07:50:23.877930Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions 
2022-12-06T07:50:23.879487Z 0 [Note] InnoDB: Rolling back trx with id 2856569320, 0 rows to undo 
2022-12-06T07:50:23.883068Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 
2022-12-06T07:50:23.883080Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables 
2022-12-06T07:50:23.883081Z 0 [Note] InnoDB: Rollback of trx with id 2856569320 completed 
2022-12-06T07:50:23.883099Z 0 [Note] InnoDB: Rolling back trx with id 2856568950, 367 rows to undo 
2022-12-06T07:50:23.892304Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2022-12-06T07:50:24.027580Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 
2022-12-06T07:50:24.111413Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 2022-12-06T07:50:24.111433Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 
2022-12-06T07:50:24.157138Z 0 [Note] InnoDB: Waiting for purge to start 
2022-12-06T07:50:24.225198Z 0 [Note] InnoDB: 5.7.32 started; log sequence number 69879080770444 
2022-12-06T07:50:24.228477Z 0 [Note] InnoDB: Loading buffer pool(s) from /data5/mysql-5.7.32/data/ib_buffer_pool 
2022-12-06T07:50:24.308694Z 0 [Note] Plugin 'FEDERATED' is disabled. 
2022-12-06T07:50:24.569514Z 0 [Note] InnoDB: Rollback of trx with id 2856568950 completed 
2022-12-06T07:50:24.569537Z 0 [Note] InnoDB: Rolling back trx with id 2856565387, 99613 rows to undo InnoDB: Progress in percents: 1
2022-12-06T07:50:24.986986Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them. 
2022-12-06T07:50:24.987005Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory. 2022-12-06T07:50:25.051557Z 0 [Warning] CA certificate ca.pem is self signed. 
2022-12-06T07:50:25.054680Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory. 
2022-12-06T07:50:25.089348Z 0 [Note] Server hostname (bind-address): '*'; port: 3306 
2022-12-06T07:50:25.090809Z 0 [Note] IPv6 is not available. 
2022-12-06T07:50:25.090830Z 0 [Note]   - '0.0.0.0' resolves to '0.0.0.0'; 
2022-12-06T07:50:25.090860Z 0 [Note] Server socket created on IP: '0.0.0.0'.  2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22
2022-12-06T07:50:26.592567Z 0 [Note] InnoDB: Buffer pool(s) load completed at 221206 15:50:26  23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
2022-12-06T07:50:30.239393Z 0 [Note] Event Scheduler: Loaded 0 events 
2022-12-06T07:50:30.240260Z 0 [Note] /usr/local/mysql2/bin/mysqld: ready for connections. Version: '5.7.32-log'  socket: '/data5/mysql-5.7.32/mysql.sock'  port: 3306  MySQL Community Server (GPL) 
2022-12-06T07:50:30.272949Z 0 [Note] InnoDB: Rollback of trx with id 2856565387 completed 
2022-12-06T07:50:30.272975Z 0 [Note] InnoDB: Rolling back trx with id 2856556793, 681308 rows to undo

the ibdata1 file is 45G, use share table space

1 Like
2

Based on the below log, it is clear that some incomplete 5 transactions had modified ~26093901 rows once the database was not shut down properly. Now mysqld needs to perform rollback for those transactions (rows). The time it takes to roll back an incomplete transaction can be three or four times the amount of time a transaction is active before it is interrupted, depending on the server load.

Here we can’t or should not ignore/cancel this rollback process as it could cause data inconsistency/crash to data files.

Here we recommend keeping an eye on the long-running open transaction (history list length) and making sure to use small transactions or perform the commit/rollback as soon as possible.

More details (Check section: Roll back of incomplete transactions) : MySQL :: MySQL 5.7 Reference Manual :: 14.19.2 InnoDB Recovery

2022-12-06T01:33:52.922157Z 0 [Note] InnoDB: Database was not shutdown normally! 
2022-12-06T01:33:52.922162Z 0 [Note] InnoDB: Starting crash recovery. 
2022-12-06T01:38:25.748511Z 0 [Note] InnoDB: 5 transaction(s) which must be rolled back or cleaned up in total 26093901 row operations to undo 
2022-12-06T01:38:25.749995Z 0 [Note] InnoDB: Trx id counter is 2856569600 
2022-12-06T01:38:25.750009Z 0 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99  
2022-12-06T01:38:27.937131Z 0 [Note] InnoDB: Apply batch completed
2022-12-06T04:14:16.554205Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 9624243ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
1 Like