Mysql on Ubuntu crashing periodically [duplicate]

Question

This question already has answers here:

MySQL InnoDB crash post-mortem (4 answers)

Closed 6 days ago.

I have a problem with Mysql on my ubuntu server. it is restarting periodically about 4-5 times a day .

Here is the logs that I found in /var/log/mysql/error.log:

2021-02-23T08:35:08.249856Z 18 [Note] Aborted connection 18 to db: 'dbname' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2021-02-23T10:34:19.443803Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5088ms. The settings might not be optimal. (flushed=201 and evicted=0, during the time.)
2021-02-23T10:34:47.634586Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4824ms. The settings might not be optimal. (flushed=202 and evicted=0, during the time.)
2021-02-23T10:35:23.300149Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-02-23T10:35:23.300393Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2021-02-23T10:35:23.304521Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.33-0ubuntu0.18.04.1) starting as process 123774 ...
2021-02-23T10:35:23.422500Z 0 [Note] InnoDB: PUNCH HOLE support available
2021-02-23T10:35:23.422575Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-02-23T10:35:23.422587Z 0 [Note] InnoDB: Uses event mutexes
2021-02-23T10:35:23.422597Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2021-02-23T10:35:23.422606Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-02-23T10:35:23.422616Z 0 [Note] InnoDB: Using Linux native AIO
2021-02-23T10:35:23.430306Z 0 [Note] InnoDB: Number of pools: 1
2021-02-23T10:35:23.482073Z 0 [Note] InnoDB: Using CPU crc32 instructions
2021-02-23T10:35:23.549284Z 0 [Note] InnoDB: Initializing buffer pool, total size = 11G, instances = 8, chunk size = 128M
2021-02-23T10:35:24.950573Z 0 [Note] InnoDB: Completed initialization of buffer pool
2021-02-23T10:35:25.432846Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-02-23T10:35:25.472539Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2021-02-23T10:35:25.725336Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 340770137569
2021-02-23T10:35:26.793582Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340775379968
2021-02-23T10:35:27.011079Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340780622848
2021-02-23T10:35:27.253004Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340785865728
2021-02-23T10:35:27.486900Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340791108608
2021-02-23T10:35:31.778895Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340880237568
2021-02-23T10:35:32.176816Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340885480448
2021-02-23T10:35:32.417818Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340890723328
2021-02-23T10:35:32.657115Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340895966208
2021-02-23T10:35:32.993739Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340901209088
2021-02-23T10:35:33.231043Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 340906451968
2021-02-23T10:35:45.981286Z 0 [Note] InnoDB: Database was not shutdown normally!
2021-02-23T10:35:45.981297Z 0 [Note] InnoDB: Starting crash recovery.
2021-02-23T10:35:47.430460Z 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 
2021-02-23T10:37:35.718502Z 0 [Note] InnoDB: Apply batch completed
2021-02-23T10:37:36.213080Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-02-23T10:37:36.213174Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-02-23T10:37:36.213376Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-02-23T10:37:36.322627Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-02-23T10:37:36.324281Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2021-02-23T10:37:36.324312Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2021-02-23T10:37:36.325223Z 0 [Note] InnoDB: Waiting for purge to start
2021-02-23T10:37:36.375439Z 0 [Note] InnoDB: 5.7.33 started; log sequence number 341150009542
2021-02-23T10:37:36.375495Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 130943ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2021-02-23T10:37:36.376274Z 0 [Note] InnoDB: Loading buffer pool(s) from /media/ssd/mysql/ib_buffer_pool
2021-02-23T10:37:36.389529Z 0 [Note] Plugin 'FEDERATED' is disabled.
2021-02-23T10:37:36.737795Z 0 [Note] InnoDB: Buffer pool(s) load completed at 210223 14:07:36
2021-02-23T10:37:37.064320Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2021-02-23T10:37:37.064371Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2021-02-23T10:37:37.168308Z 0 [Warning] CA certificate ca.pem is self signed.
2021-02-23T10:37:37.246404Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2021-02-23T10:37:37.249146Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2021-02-23T10:37:37.249192Z 0 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2021-02-23T10:37:37.249280Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2021-02-23T10:37:37.430015Z 0 [Note] Event Scheduler: Loaded 0 events
2021-02-23T10:37:37.430686Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.33-0ubuntu0.18.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)
2021-02-23T14:51:15.763758Z 8 [Note] Aborted connection 8 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:51:15.763838Z 16 [Note] Aborted connection 16 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:51:15.763995Z 10 [Note] Aborted connection 10 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:51:15.764047Z 15 [Note] Aborted connection 15 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:51:17.210238Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 29446ms. The settings might not be optimal. (flushed=204 and evicted=0, during the time.)
2021-02-23T14:54:15.294784Z 453 [Note] Aborted connection 453 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:54:15.296473Z 451 [Note] Aborted connection 451 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:54:15.298752Z 450 [Note] Aborted connection 450 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T14:54:15.298926Z 14 [Note] Aborted connection 14 to db: 'dbname' user: 'root' host: 'localhost' (Got an error reading communication packets)
2021-02-23T17:11:22.648311Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-02-23T17:11:22.648589Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2021-02-23T17:11:22.652881Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.33-0ubuntu0.18.04.1) starting as process 1634 ...
2021-02-23T17:11:22.672652Z 0 [Note] InnoDB: PUNCH HOLE support available
2021-02-23T17:11:22.672725Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-02-23T17:11:22.672736Z 0 [Note] InnoDB: Uses event mutexes
2021-02-23T17:11:22.672745Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2021-02-23T17:11:22.672754Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-02-23T17:11:22.672762Z 0 [Note] InnoDB: Using Linux native AIO
2021-02-23T17:11:22.675075Z 0 [Note] InnoDB: Number of pools: 1
2021-02-23T17:11:22.683213Z 0 [Note] InnoDB: Using CPU crc32 instructions
2021-02-23T17:11:22.689903Z 0 [Note] InnoDB: Initializing buffer pool, total size = 11G, instances = 8, chunk size = 128M
2021-02-23T17:11:24.068244Z 0 [Note] InnoDB: Completed initialization of buffer pool
2021-02-23T17:11:24.559873Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-02-23T17:11:24.605433Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2021-02-23T17:11:24.871485Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 342136489876
2021-02-23T17:11:25.341573Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342141732352
2021-02-23T17:11:25.577950Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342146975232
2021-02-23T17:11:25.795290Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342152218112
2021-02-23T17:11:26.031098Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342157460992
2021-02-23T17:11:26.355898Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342162703872
2021-02-23T17:11:26.619473Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342167946752
2021-02-23T17:11:27.019359Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342173189632
2021-02-23T17:11:28.172480Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342199404032
2021-02-23T17:11:28.383917Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342204646912
2021-02-23T17:11:28.571524Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 342209889792
2021-02-23T17:11:40.944348Z 0 [Note] InnoDB: Database was not shutdown normally!
2021-02-23T17:11:40.944364Z 0 [Note] InnoDB: Starting crash recovery.
2021-02-23T17:11:41.913740Z 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 
2021-02-23T17:13:53.415441Z 0 [Note] InnoDB: Apply batch completed
2021-02-23T17:13:53.700851Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-02-23T17:13:53.700935Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-02-23T17:13:53.701086Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-02-23T17:13:53.816298Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-02-23T17:13:53.817845Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2021-02-23T17:13:53.817877Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2021-02-23T17:13:53.818861Z 0 [Note] InnoDB: 5.7.33 started; log sequence number 342515600566
2021-02-23T17:13:53.818894Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 149259ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2021-02-23T17:13:53.819711Z 0 [Note] InnoDB: Loading buffer pool(s) from /media/ssd/mysql/ib_buffer_pool
2021-02-23T17:13:53.826641Z 0 [Note] Plugin 'FEDERATED' is disabled.
2021-02-23T17:13:54.130893Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2021-02-23T17:13:54.130990Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2021-02-23T17:13:54.150644Z 0 [Warning] CA certificate ca.pem is self signed.
2021-02-23T17:13:54.168241Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2021-02-23T17:13:54.171009Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2021-02-23T17:13:54.171228Z 0 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2021-02-23T17:13:54.171337Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2021-02-23T17:13:54.194435Z 0 [Note] InnoDB: Buffer pool(s) load completed at 210223 20:43:54
2021-02-23T17:13:54.323573Z 0 [Note] Event Scheduler: Loaded 0 events
2021-02-23T17:13:54.324340Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.33-0ubuntu0.18.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)

And Here is my.cnf file :

!includedir /etc/mysql/conf.d/
!includedir /etc/mysql/mysql.conf.d/
[mysqld]
sql_mode = "ONLY_FULL_GROUP_BY,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"
innodb_buffer_pool_size = 11G
innodb_log_buffer_size = 8M
innodb_log_file_size = 2047M

I can not determine what causes these crashes :(

Answer 1

Note the pattern:

2021-02-23T08:35:08.249856Z 18 [Note] Aborted connection 18 to db: 'dbname' user: 'root' host: 'localhost' (Got timeout reading communication packets)

Large time gap

2021-02-23T10:34:19.443803Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5088ms. The settings might not be optimal. (flushed=201 and evicted=0, during the time.)
2021-02-23T10:34:47.634586Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4824ms. The settings might not be optimal. (flushed=202 and evicted=0, during the time.)
2021-02-23T10:35:23.300149Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-02-23T10:35:23.300393Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2021-02-23T10:35:23.304521Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.33-0ubuntu0.18.04.1) starting as process 123774 ...

This is mysql restarting.

That means there wasn't a clean shutdown. Which is backed up by your mysql.service: Main process exited, code=killed, status=9/KILL comment.

So either you have a person going around doing a kill -9 on your mysqld process, or more likely, you are running out of memory at a particular point, the OOM killer is removing mysqld, and systemd is restarting it at point later in time.

Running dmesg should confirm the out of memory.