0

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 :(

5
  • Additional information request. RAM size, # cores, any SSD or NVME devices on MySQL Host server? Post on pastebin.com and share the links. From your SSH login root, Text results of: B) SHOW GLOBAL STATUS; after minimum 24 hours UPTIME C) SHOW GLOBAL VARIABLES; D) SHOW FULL PROCESSLIST; F) complete MySQLTuner report AND Optional helpful information, if available includes - htop OR top for most active apps, ulimit -a for a Linux/Unix list of limits, iostat -xm 5 3 for IOPS by device and core/cpu count, for server workload tuning analysis to provide suggestions. Commented Feb 23, 2021 at 20:12
  • Have you looked at the syslog?
    – mustaccio
    Commented Feb 23, 2021 at 21:13
  • 1
    @mustaccio here is service log : mysql.service: Main process exited, code=killed, status=9/KILL \n mysql.service: Failed with result 'signal'. Commented Feb 24, 2021 at 12:23
  • BTW I totally endorse your strict sql_mode. Well done on becoming a better SQL writer.
    – danblack
    Commented Feb 25, 2021 at 5:52
  • Please post last 400 lines of your Error Log for analysis. Commented Feb 26, 2021 at 14:50

1 Answer 1

0

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.

Not the answer you're looking for? Browse other questions tagged or ask your own question.