개발 노트, SQLAlchemy를 사용하면서 MySQL Connection이 끊기는 문제

• 문제 요약 : MySQL로 요청 후 일정시간동안 재요청이 없으면 MySQL로부터 연결이 끊기게 되고 이를 위해 SQLAlchemy에서 pool_recycle 옵션을 사용하여 해결
  

MySQL 로의 요청이 있을 경우 연결을 위한 프로세스가 생성되고 다시 요청을 하기 전까지 sleep 상태로 세션이 유지된다. 이 때 wait_timeout에 지정된 시간 동안 재요청이 없을 경우 MySQL에서 해당 세션의 연결을 끊어버린다.

▶ 연결 상태 확인 (show processlist)

MariaDB [db]> show processlist;
Current database: db

+-----+--------------+----------------------+--------------+---------+------+-------+------------------+----------+
| Id  | User         | Host                 | db           | Command | Time | State | Info             | Progress |
+-----+--------------+----------------------+--------------+---------+------+-------+------------------+----------+
| 436 | yongho       | 192.168.x.x:52338    | db           | Sleep   |   10 |       | NULL             |    0.000 |
| 438 | root         | localhost            | db           | Query   |    0 | init  | show processlist |    0.000 |
+-----+--------------+----------------------+--------------+---------+------+-------+------------------+----------+
2 rows in set (0.00 sec)

▶ timeout 설정 (/etc/mysql/my.cnf)

[mysqld]
max_connections         = 100
connect_timeout         = 5
wait_timeout            = 600
max_allowed_packet      = 16M
thread_cache_size       = 128
sort_buffer_size        = 4M
bulk_insert_buffer_size = 16M
tmp_table_size          = 32M
max_heap_table_size     = 32M
interactive_timeout     = 1000

▶ 설정 후 mysql 재시작

$ sudo service mysql restart

▶ timeout 설정 값 확인 (show [global] variables like '%timeout%';)

MariaDB [(none)]> show variables like '%timeout%';
+-----------------------------+----------+
| Variable_name               | Value    |
+-----------------------------+----------+
| connect_timeout             | 5        |
| deadlock_timeout_long       | 50000000 |
| deadlock_timeout_short      | 10000    |
| delayed_insert_timeout      | 300      |
| innodb_flush_log_at_timeout | 1        |
| innodb_lock_wait_timeout    | 50       |
| innodb_rollback_on_timeout  | OFF      |
| interactive_timeout         | 1000     |
| lock_wait_timeout           | 31536000 |
| net_read_timeout            | 30       |
| net_write_timeout           | 60       |
| slave_net_timeout           | 3600     |
| thread_pool_idle_timeout    | 60       |
| wait_timeout                | 1000     |
+-----------------------------+----------+
14 rows in set (0.00 sec)

Tip) 명령에 global을 사용하지 않은 경우 세션 단위의 설정 값이 출력된다. 세션 값에서는 interactive_timeout 값을 디폴트로 wait_timeout 값이 설정된다. 그래서 위의 설정에서 my.cnf 파일에는 interactive_timeout=1000, wait_timeout=600으로 셋팅 했는데 두 값 모두 1000으로 출력되는 것을 볼 수 있다. show global variables like '%timeout%'; 명령으로 global 값을 확인해보면 my.cnf에서 설정한 값 그대로 설정 된 것을 확인할 수 있다.

연결이 끊어진 후 요청을 하게되면 연결이 끊어 졌다는("mysql+pymysql://"로 연결 한 경우에는 'Lost connection to MySQL server during query', "mysql://"로 연결한 경우에는 'MySQL server has gone away') exception 에러가 발생하므로 이에 대한 처리가 필요하다.

▶ "mysql://"을 사용하려면 python-mysqldb 패키지 설치

$ sudo apt-get install python-mysqldb

▶ 연결이 끊어진 상태에서 쿼리를 요청한 결과

File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
    context)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 436, in do_execute
    cursor.execute(statement, parameters)
  File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
sqlalchemy.exc.OperationalError: (OperationalError) (2006, 'MySQL server has gone away') "INSERT INTO TQK_ACCOUNT(ACCOUNT_ID)
 VALUES('test14')" ()
<sqlalchemy.orm.session.Session object at 0x7f262cfc4d50>
2014-11-20 17:32:08,045 INFO sqlalchemy.pool.QueuePool Invalidate connection <_mysql.connection open to '192.168.x.x' at 
227d100> (reason: OperationalError:(2006, 'MySQL server has gone away'))

Process finished with exit code 137

SQLAlchemy 에서는 쿼리 요청이 없더라도 일정 주기로 갱신하는 pool_recycle을 사용하여 해결한다. pool_recycle의 주기가 wait_timeout 시간보다 작아야 한다.

▶ pool_recycle로 인해 재연결 메시지

2014-11-20 17:00:57,485 INFO sqlalchemy.pool.QueuePool Connection <_mysql.connection open to '127.0.0.1' at 2adcf90> exceeded timeout; recycling
INFO:sqlalchemy.pool.QueuePool:Connection <_mysql.connection open to '127.0.0.1' at 2adcf90> exceeded timeout; recycling

위의 메시지를 보기 위해서는 logger 셋팅과 SQLAlchemy의 create_engine 함수에 옵션 지정이 필요하다. 

(logger의 Level이 INFO 또는 그 아래의 Level로 셋팅되어야 한다.)

▶ logger 셋팅

import logging

logging.basicConfig()
logging.getLogger('sqlalchemy.pool').setLevel(logging.DEBUG)

engine = create_engine(
    'mysql://', pool_recycle=500, pool_size=5, max_overflow=20, echo=False, echo_pool=True)