Database connections timeout

August 4, 2016 656 views
Networking MySQL

Persistent database connections to MySQL and Redis servers don't stay open for more than a couple of minutes before connection is dropped. This issue came up since we switched to node applications in cluster mode that keep around 30 - 50 connections open at any time. Most common error is "MySQL server has gone away" that is usually handled in application logic, but lately errors like "Lost connection to MySQL server during query" and 111 "Connection refused" started coming up, which are not handled cleanly.

Even PHP applications that keep only one non-persistent connection have random connection issues. On top of that even remote SSH to server drops occasionally.

All our servers run in SF1 region. Any ideas what would be causing these connections issues?

2 comments
  • Hi! Are there any errors in MySQL's error log?

    sudo tail -30 /var/log/mysql.err
    
  • Actually there are messages I have missed before. Looks like the mysql server restarts itself once or twice a day. That would definitely contribute to timeouts.

    
    2016-08-05 00:11:20 25575 [Note] InnoDB: Using CPU crc32 instructions
    2016-08-05 00:11:20 25575 [Note] InnoDB: Initializing buffer pool, size = 5.0G
    2016-08-05 00:11:20 25575 [Note] InnoDB: Completed initialization of buffer pool
    2016-08-05 00:11:20 25575 [Note] InnoDB: Highest supported file format is Barracuda.
    2016-08-05 00:11:20 25575 [Note] InnoDB: Log scan progressed past the checkpoint lsn 223074090775
    2016-08-05 00:11:20 25575 [Note] InnoDB: Database was not shutdown normally!
    2016-08-05 00:11:20 25575 [Note] InnoDB: Starting crash recovery.
    2016-08-05 00:11:20 25575 [Note] InnoDB: Reading tablespace information from the .ibd files...
    2016-08-05 00:11:21 25575 [Note] InnoDB: Restoring possible half-written data pages
    2016-08-05 00:11:21 25575 [Note] InnoDB: from the doublewrite buffer...
    InnoDB: Doing recovery: scanned up to log sequence number 223074115733
    2016-08-05 00:11:21 25575 [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
    InnoDB: Apply batch completed
    2016-08-05 00:11:22 25575 [Note] InnoDB: 128 rollback segment(s) are active.
    2016-08-05 00:11:22 25575 [Note] InnoDB: Waiting for purge to start
    2016-08-05 00:11:22 25575 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.30-76.3 started; log sequence number 223074115733
    2016-08-05 00:11:22 25575 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
    2016-08-05 00:11:22 25575 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
    2016-08-05 00:11:22 25575 [Note] Server hostname (bind-address): '*'; port: 3306
    2016-08-05 00:11:22 25575 [Note] IPv6 is available.
    2016-08-05 00:11:22 25575 [Note]   - '::' resolves to '::';
    2016-08-05 00:11:22 25575 [Note] Server socket created on IP: '::'.
    2016-08-05 00:11:22 25575 [Note] Event Scheduler: Loaded 0 events
    2016-08-05 00:11:22 25575 [Note] /usr/sbin/mysqld: ready for connections.
    Version: '5.6.30-76.3'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Percona Server (GPL), Release 76.3, Revision 3850db5
    2016-08-05 00:41:58 25575 [Warning] IP address 'xxx.xxx.xxx.xxx' could not be resolved: Name or service not known
    160805 08:30:24 mysqld_safe Number of processes running now: 0
    160805 08:30:24 mysqld_safe mysqld restarted
    2016-08-05 08:30:26 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
    2016-08-05 08:30:26 0 [Note] /usr/sbin/mysqld (mysqld 5.6.30-76.3) starting as process 28380 ...
    2016-08-05 08:30:26 28380 [Note] Plugin 'FEDERATED' is disabled.
    2016-08-05 08:30:26 28380 [Note] InnoDB: Using atomics to ref count buffer pool pages
    2016-08-05 08:30:26 28380 [Note] InnoDB: The InnoDB memory heap is disabled
    2016-08-05 08:30:26 28380 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
    2016-08-05 08:30:26 28380 [Note] InnoDB: Memory barrier is not used
    2016-08-05 08:30:26 28380 [Note] InnoDB: Compressed tables use zlib 1.2.7
    2016-08-05 08:30:26 28380 [Note] InnoDB: Using Linux native AIO
    2016-08-05 08:30:26 28380 [Note] InnoDB: Using CPU crc32 instructions
    2016-08-05 08:30:26 28380 [Note] InnoDB: Initializing buffer pool, size = 5.0G
    2016-08-05 08:30:26 28380 [Note] InnoDB: Completed initialization of buffer pool
    2016-08-05 08:30:27 28380 [Note] InnoDB: Highest supported file format is Barracuda.
    2016-08-05 08:30:27 28380 [Note] InnoDB: The log sequence numbers 199782124887 and 199782124887 in ibdata files do not match the log sequence number 223166042299 in the ib_logfiles!
    2016-08-05 08:30:27 28380 [Note] InnoDB: Database was not shutdown normally!
    2016-08-05 08:30:27 28380 [Note] InnoDB: Starting crash recovery.
    2016-08-05 08:30:27 28380 [Note] InnoDB: Reading tablespace information from the .ibd files...
    2016-08-05 08:30:27 28380 [Note] InnoDB: Restoring possible half-written data pages
    2016-08-05 08:30:27 28380 [Note] InnoDB: from the doublewrite buffer...
    2016-08-05 08:30:28 28380 [Note] InnoDB: 128 rollback segment(s) are active.
    2016-08-05 08:30:28 28380 [Note] InnoDB: Waiting for purge to start
    2016-08-05 08:30:28 28380 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.30-76.3 started; log sequence number 223166042299
    2016-08-05 08:30:28 28380 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
    2016-08-05 08:30:28 28380 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
    2016-08-05 08:30:28 28380 [Note] Server hostname (bind-address): '*'; port: 3306
    2016-08-05 08:30:28 28380 [Note] IPv6 is available.
    2016-08-05 08:30:28 28380 [Note]   - '::' resolves to '::';
    2016-08-05 08:30:28 28380 [Note] Server socket created on IP: '::'.
    2016-08-05 08:30:28 28380 [Note] Event Scheduler: Loaded 0 events
    2016-08-05 08:30:28 28380 [Note] /usr/sbin/mysqld: ready for connections.
    Version: '5.6.30-76.3'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Percona Server (GPL), Release 76.3, Revision 3850db5
    2016-08-05 16:19:59 28380 [Warning] IP address 'xxx.xxx.xxx.xxx' could not be resolved: Name or service not known
    
1 Answer

Sorry for the late reply. With those persistent connections it's possible that you are running out of listeners (with all the slots full with persistent connections and the short term php ones as well new clients may be getting denied or dormant connections freed up).

I would recommend reviewing my.cnf (in /etc/mysql) to see what your max_connections variable is set to. With the persistent connections, check the wait_timeout value in case MySQL is timing out these connections when they are idle.

Have another answer? Share your knowledge.