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)
로그인하면 댓글을 남길 수 있습니다.