목차

InnoDB 장애 해결

— 이강우 2018/05/01 08:48

open files 문제

mysqld.log 파일을 보면 아래와 같은 부분이 발생하는 경우가 있다. 

2018-04-28T15:00:07.538122Z 0 [Warning] Changed limits: max_open_files: 5000 (requested 8410)
2018-04-28T15:00:07.538270Z 0 [Warning] Changed limits: table_open_cache: 2295 (requested 4000)

우선 아래와 같이 소프트와 하드 한계 open files를 확인 할 수 있다 

 $ ulimit -Sa | grep "open files"
 open files                    (-n) 1200

 $ ulimit -Ha | grep "open files"
 open files                    (-n) 8192

위에서 확인 된 수치는 아래와 같이 MySQL 클라이언트에서 확인하는 수치와 상응된다 

 mysql> show variables like 'open_files_limit';
 +-------------------+-------+
 | Variable_name     | Value |
 +-------------------+-------+
 | open_files_limit  | 1200  |
 +-------------------+-------+

 mysql> show variables like 'table_cache';
 +-------------------+-------+
 | Variable_name     | Value |
 +-------------------+-------+
 | table_cache       | 512   |
 +-------------------+-------+

 mysql> show variables like 'max_connections';
 +-------------------+-------+
 | Variable_name     | Value |
 +-------------------+-------+
 | max_connections   | 100   |
 +-------------------+-------+

해당 시스템의 open files 수가 부족하여 생기는 문제이다. 이 문제를 해결하려면 아래와 같이 설정한다.

1. mysql을 구동하는 사용자 계정의 ulimit 값을 수정한다.
/etc/security/limits.conf 

*            soft    nofile          1048576
*            hard    nofile          1048576

2. sysctl 값의 fs.file-max 수치를 변경한다.
/etc/sysctl.conf 

fs.file-max = 401483

3. RHEL/CentOS 7.x 이상인 경우 아래의 파일도 수정한다.
이부분을 수정하지 않으면 mysql데몬을 기동해도 기본값으로 기동된다.
/usr/lib/systemd/system/mysqld.service 

LimitNOFILE=65535

NO_ZERO_DATE, ERROR_FOR_DIVISION_BY_ZERO 문제

mysql운영시 간혹 아래와 같은 로그가 발견되는 경우가 있다. 

2018-04-28T15:00:07.778409Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-04-28T15:00:07.778444Z 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.

결론부터 말하자면 해당 데이터베이스의 일부 테이블 데이터가 깨진 경우다. 정상적으로 종료하지 않고 서버를 강제종료했다던지 디스크의 문제가 발생하여 저장된 테이블 데이터에 오류가 발생한 경우이다.
관련된 검색어는 mysql strict 모드로 검색하면 관련된 내용을 알수 있다.

이 문제의 경우는 NOT NULL인 필드에 널 값이 들어가게 된 경우나 기타 데이터 타입이 맞지 않거나 들어가지 않아야 할 값들이 들어가서 문제가 생기는경우이다.
mysqldump를 통해 전체 데이터 덤프를 시도해보면 어디서 문제가 발생한지 찾을수 있으며 해당 테이블의 스키마를 임시로 ALTER해보거나 인덱스를 재구성하거나 NOT NULL 조건을 없애거나 해보면 해소될 수 있다.

로그 예시

/var/log/mysql/mysqld.log 

2018-04-28T15:00:07.538122Z 0 [Warning] Changed limits: max_open_files: 5000 (requested 8410)
2018-04-28T15:00:07.538270Z 0 [Warning] Changed limits: table_open_cache: 2295 (requested 4000)
2018-04-28T15:00:07.778409Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-04-28T15:00:07.778444Z 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.
2018-04-28T15:00:07.780726Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.18-enterprise-commercial-advanced-log) starting as process 12984 ...
2018-04-28T15:00:07.784978Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-04-28T15:00:07.785014Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-04-28T15:00:07.785017Z 0 [Note] InnoDB: Uses event mutexes
2018-04-28T15:00:07.785020Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-04-28T15:00:07.785029Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-04-28T15:00:07.785032Z 0 [Note] InnoDB: Using Linux native AIO
2018-04-28T15:00:07.785857Z 0 [Note] InnoDB: Number of pools: 1
2018-04-28T15:00:07.786072Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-04-28T15:00:07.789404Z 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
2018-04-28T15:00:10.086029Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-04-28T15:00:10.320733Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-04-28T15:00:10.333461Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-04-28T15:00:10.498365Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 51460910261
2018-04-28T15:00:10.498413Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 51460910574
2018-04-28T15:00:10.662444Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 51460910574
2018-04-28T15:00:10.662776Z 0 [Note] InnoDB: Database was not shutdown normally!
2018-04-28T15:00:10.662786Z 0 [Note] InnoDB: Starting crash recovery.
2018-04-28T15:00:10.773535Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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
2018-04-28T15:00:12.286193Z 0 [Note] InnoDB: Apply batch completed
2018-04-28T15:00:12.398027Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-04-28T15:00:12.398056Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-04-28T15:00:12.398093Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-04-28T15:00:12.428109Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-04-28T15:00:12.429357Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-04-28T15:00:12.429369Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-04-28T15:00:12.429685Z 0 [Note] InnoDB: Waiting for purge to start
2018-04-28T15:00:12.479836Z 0 [Note] InnoDB: 5.7.18 started; log sequence number 51460910574
2018-04-28T15:00:12.481130Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/ib_buffer_pool
2018-04-28T15:00:12.481253Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-04-28T15:00:12.481730Z 0 [Note] InnoDB: Buffer pool(s) load completed at 180429  0:00:12
2018-04-28T15:00:12.487741Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2018-04-28T15:00:12.487768Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2018-04-28T15:00:12.488307Z 0 [Warning] CA certificate ca.pem is self signed.
2018-04-28T15:00:12.488361Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2018-04-28T15:00:12.488710Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2018-04-28T15:00:12.488786Z 0 [Note] IPv6 is available.
2018-04-28T15:00:12.488803Z 0 [Note]   - '::' resolves to '::';
2018-04-28T15:00:12.488822Z 0 [Note] Server socket created on IP: '::'.
2018-04-28T15:00:12.499018Z 0 [Note] Event Scheduler: Loaded 5 events
2018-04-28T15:00:12.499129Z 1 [Note] Event Scheduler: scheduler thread started with id 1
2018-04-28T15:00:12.499222Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.18-enterprise-commercial-advanced-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Enterprise Server - Advanced Edition (Commercial)