MariaDB binary log파일이 비정상적으로 커지는 원인과 이슈사항

Print
Tech Note 정보
카테고리: [ MariaDB ]
조회수: 8919

 

 
binary log size의 max값이 있으나 이를 초과하여 binary log가 비정상적으로 커져 이슈가 되었던 케이스입니다.
원인 및 조치했던 내역 공유드립니다.

-1. log 파일시스템 full 확인

 
[TESTSERVER:TESTUSER]/logs001/TESTUSER/TESTDB/error] df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/rootvg-root_vg
                       25G  6.3G   18G  27% /
tmpfs                 3.9G   72K  3.9G   1% /dev/shm
/dev/vda1             477M  189M  263M  42% /boot
/dev/mapper/TEST_VG001-engn_lv001
                      9.8G  1.3G  8.0G  14% /engn001
/dev/mapper/TEST_VG001-data_lv001
                       50G   28G   20G  59% /data001
/dev/mapper/TEST_VG001-logs_lv001
                      9.8G  9.3G   17M 100% /logs001
                      
[TESTSERVER:TESTUSER]/data001/TESTUSER] ls -ltr
total 9626148
-rw-rw---- 1 TESTUSER mysql 9857167360 Oct  8 09:59 mysql-bin.000004
 
=> binary log 하나가 DB의 log영역 파일시스템을 전부 사용하고 있는 상황.
사용중인 binary log 파일이기 때문에 삭제도 불가하며 다른 binary log 파일이 없기 때문에
다른 파일을 삭제하여 영역확보도 불가능한 상황임       

 

-2. 원인

max_binlog_size=512M
 
=> binary log의 최대 사이즈가 512M로 설정 되어 있으나 
하나의 트랜잭션이 여러개의 binary log 파일에 저장되지 않기 때문에 트랜잭션의 크기가 해당 설정보다 크면 binlog_size max 값을 초과해서 파일이 저장됨
이번 케이스는 트랜잭션 하나의 크기가 10GB가 넘어 mysql-bin.000004 파일 하나가 10GB 까지 커진 경우이며
이를 방지하기 위해서는 트랜잭션 중간에 커밋을 실행하여 트랜잭션의 크기를 조절해야함 
               

-3. DB 강제 종료

                      
[TESTSERVER:TESTUSER]/logs001/TESTUSER/TESTDB/error] ps -ef | grep mysql
TESTUSER  21859 29998 16 10:00 ?        00:00:14 /engn001/TESTUSER/TESTDB/mysql/bin/mysqld --defaults-file=/engn001/TESTUSER/TESTDB/mysql/my.cnf --basedir=/engn001/TESTUSER/TESTDB/mysql --datadir=/data001/TESTUSER/TESTDB --plugin-dir=/engn001/TESTUSER/TESTDB/mysql/lib/plugin --read-only=0 --log-error=/logs001/TESTUSER/TESTDB/error/TESTDB.err --open-files-limit=65535 --pid-file=TESTSERVER.pid --socket=/engn001/TESTUSER/TESTDB/mysql/mysql.sock --port=3306
TESTUSER  22004 20897  0 10:01 pts/1    00:00:00 grep mysql
TESTUSER  29998     1  0 Sep27 ?        00:00:00 /bin/sh ./bin/mysqld_safe --defaults-file=/engn001/TESTUSER/TESTDB/mysql/my.cnf --user=TESTUSER --basedir=/engn001/TESTUSER/TESTDB/mysql --read-only=0

[TESTSERVER:TESTUSER]/logs001/TESTUSER/TESTDB/error] kill -9 29998
[TESTSERVER:TESTUSER]/logs001/TESTUSER/TESTDB/error] kill -9 21859
[TESTSERVER:TESTUSER]/logs001/TESTUSER/TESTDB/error] ps -ef | grep mysql
TESTUSER  22008 20897  0 10:01 pts/1    00:00:00 grep mysql
 
=> log 영역이 full 발생한 상황에서는 DB 정상종료가 안되기 때문에 강제 종료
 

-4-1. 해당 binary log 없이 재기동 시도

 
2018-10-08 10:18:00 7fec8ee1b760  InnoDB: Starting recovery for XA transactions...
2018-10-08 10:18:00 7fec8ee1b760  InnoDB: Transaction 7058688 in prepared state after recovery
2018-10-08 10:18:00 7fec8ee1b760  InnoDB: Transaction contains changes to 5409819 rows
2018-10-08 10:18:00 7fec8ee1b760  InnoDB: 1 transactions in prepared state after recovery
2018-10-08 10:18:00 140653986166624 [Note] Found 1 prepared transaction(s) in InnoDB
2018-10-08 10:18:00 140653986166624 [ERROR] Found 1 prepared transactions! It means that mysqld was not shut down properly last time and critical recovery information (last binlog or tc.log file) was manually deleted after a crash. You have to start mysqld with --tc-heuristic-recover switch to commit or rollback pending transactions.

2018-10-08 10:18:00 140653986166624 [ERROR] Aborting
181008 10:18:00 server_audit: STOPPED
2018-10-08 10:18:00 7feb287f9700 InnoDB: Buffer pool(s) load completed at 181008 10:18:00 (/data001/TESTUSER/TESTDB/ib_buffer_pool was empty)
2018-10-08 10:18:00 140647973492480 [Warning] InnoDB: Dumping buffer pool(s) to /data001/TESTUSER/TESTDB/ib_buffer_pool
2018-10-08 10:18:00 140647973492480 [Warning] InnoDB: Buffer pool(s) dump completed at 181008 10:18:00
181008 10:18:03 mysqld_safe mysqld from pid file /data001/TESTUSER/TESTDB/TESTSERVER.pid ended
 
=> 해당 binary log를 삭제 후 DB 재기동 시엔 DB recovery 가 실패하여 기동이 안되므로 반드시 필요함
 

-4-2. 해당 binary log 를 여유공간 있는 파일시스템으로 옮긴 후 재기동 시도

 
-- my.cnf 수정
#log-bin=/logs001/TESTUSER/TESTDB/binary/mysql-bin
log-bin=/data001/TESTUSER/mysql-bin
 
=> 기존 logs001 파일시스템에서 data001로 binlog 사용하도록 설정
[TESTSERVER:TESTUSER]/data001/TESTUSER] ls
TESTDB  mysql-bin.000004  mysql-bin.index
 
=> 물리적인 binary log 파일도 다른 파일시스템으로 이동 후 재기동 시도
 
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 7060224
InnoDB: Last MySQL binlog file position 0 365653038, file name /logs001/TESTUSER/TESTDB/binary/mysql-bin.000004
2018-10-08 10:03:18 140436841572192 [Note] InnoDB: 128 rollback segment(s) are active.
2018-10-08 10:03:18 140430920378112 [Note] InnoDB: Starting in background the rollback of recovered transactions
2018-10-08 10:03:18 140430920378112 [Note] InnoDB: Rollback of non-prepared transactions completed
2018-10-08 10:03:18 140436841572192 [Note] InnoDB: Waiting for purge to start
2018-10-08 10:03:18 140436841572192 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 276029955102
2018-10-08 10:03:18 140430823892736 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-10-08 10:03:18 7fb8995fa700 InnoDB: Loading buffer pool(s) from /data001/TESTUSER/TESTDB/ib_buffer_pool
2018-10-08 10:03:18 140436841572192 [Note] Plugin 'FEEDBACK' is disabled.
181008 10:03:18 server_audit: MariaDB Audit Plugin version 1.4.1 STARTED.
181008 10:03:18 server_audit: logging started to the file server_audit.log.

2018-10-08 10:03:18 140436841572192 [Note] Recovering after a crash using /logs001/TESTUSER/TESTDB/binary/mysql-bin
2018-10-08 10:03:18 7fb8995fa700 InnoDB: Buffer pool(s) load completed at 181008 10:03:18
2018-10-08 10:04:04 140436841572192 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 1528, event_type: 24
2018-10-08 10:04:04 140436841572192 [Note] Starting crash recovery...
2018-10-08 10:04:04 7fba000e2760  InnoDB: Starting recovery for XA transactions...
2018-10-08 10:04:04 7fba000e2760  InnoDB: Transaction contains changes to 9377084 rows
2018-10-08 10:04:04 7fba000e2760  InnoDB: 1 transactions in prepared state after recovery
2018-10-08 10:23:09 140196411914080 [Note] Found 1 prepared transaction(s) in InnoDB

2018-10-08 10:29:44 140196411914080 [Note] Crash recovery finished.
2018-10-08 10:29:44 140196411914080 [Note] Server socket created on IP: '::'.
2018-10-08 10:29:44 140196411914080 [Warning] 'proxies_priv' entry '@% root@centos68' ignored in --skip-name-resolve mode.
2018-10-08 10:29:44 140196411914080 [Note] /engn001/TESTUSER/TESTDB/mysql/bin/mysqld: ready for connections.
Version: '10.1.24-MariaDB'  socket: '/engn001/TESTUSER/TESTDB/mysql/mysql.sock'  port: 3306  MariaDB Server
 
=> DB 강제 종료로 비정상 종료 되었기 때문에 recovery가 필요하며 이 때 마지막으로 사용하던 binary log가 필요함

 

-5. 정상 확인 

 
[TESTSERVER:TESTUSER]/engn001/TESTUSER/TESTDB/scripts] mysql
Enter password:
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 3
Server version: 10.1.24-MariaDB MariaDB Server
 
Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MariaDB [(none)]> show master status;
+------------------+----------+--------------+------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000005 |      313 |              |                  |
+------------------+----------+--------------+------------------+
 
=> DB 정상 기동 및 새로운 binary log 사용 중인 것 확인됨
더이상 mysql-bin.000004 를 사용하지 않기 때문에 삭제 후 설정 원복하면 완료 
binary log size를 비정상적으로 크게 한 트랜잭션을 찾아 commit 으로 트랜잭션 크기를 조절하거나 파일시스템 증설 등의 해결방법이 필요함