[시스템 관리] 03. MySQL 로깅

Date: 2023.07.07 Updated: 2023.07.07

카테고리: SYS_MGMT

🔔 MySQL 로길

■ MySQL 로그 종류

종류	내용
오류 관련	오류 로그, 일반 쿼리 로그, 슬로 쿼리 로그(문제 해결을 위한 MySQL의 동작 관련 로그)
백업 관련	바이너리 로그(데이터베이스 내용을 백업하기 위한 로그)

■ 테스트용 DB, Table 생성

MariaDB [(none)]> CREATE DATABASE SAMPLEDB;
Query OK, 1 row affected (0.000 sec)


MariaDB [(none)]> USE SAMPLEDB;
Database changed


MariaDB [SAMPLEDB]> CREATE TABLE SAMPLETABLE (NAME TEXT);
Query OK, 0 rows affected (0.003 sec)


MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("TARO");
Query OK, 1 row affected (0.001 sec)


MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+------+
| NAME |
+------+
| TARO |
+------+
1 row in set (0.000 sec)

■ 오류 로그

오류 로그는 시스템 로깅이라고도 하며, mysqld의 시작, 실행, 정지 로깅 또는 발생한 오류 정보를 로깅한다.

▶ 오류 로그 설정

# https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html
# 5.7.2 버전 이전 -> log-warning
# 5.7.2 버전 이후 -> log_error_verbosity
$ cat <<EOF >> /etc/my.cnf

[mysqld_safe]
log_error=/var/log/mariadb/mariadb.log
log_error_verbosity=1
EOF

옵션	내용
log_error	오류 로그 출력 대상 설정, 오류 로그의 파일명을 설정한다.
log_error_verbosity	오류 로그에 오류, 경고 및 참고 메시지를 기록 할 때 서버의 자세한 정보를 제어

log_error_verbosity Value	메시지 내용
1	Errors only
2	Errors and warnings
3	Errors, warnings, and notes

■ 일반 쿼리 로그

일반 쿼리 로그는 쿼리 로깅이라고도 하며, mysqld가 클라이언트와 접속했을 때의 정보 및 실행한 쿼리 정보를 로깅한다.

▶ 일반 쿼리 로그 설정

# https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html
$ cat <<EOF >> /etc/my.cnf

[mysqld]
# Query Log
general_log=1
general_log_file=/var/log/mariadb/sql.log
log_output=FILE
EOF


# mysqld 다시시작
$ systemctl restart mysqld

옵션	내용
general_log	일반 쿼리 로그가 활성화되었는지 여부를 나타내는 값, 로그를 비활성화하려면 0(또는 OFF)을 사용하고, 로그를 활성화하려면 1(또는 ON)을 사용
general_log_file	일반 쿼리 로그 파일의 이름을 설정, 지정하지 않으면 ‘호스트명.log’ 파일로 저장됨
log_output	일반 쿼리 로그와 슬로 쿼리 로그의 출력 위치를 설정 (TABLE: 테이블로 로그, FILE: 파일로 로그, NONE: 테이블이나 파일로 로그하지 않음)

▶ 일반 쿼리 로그 확인

MariaDB [(none)]> USE SAMPLEDB;
Database changed

MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("JIRO");
Query OK, 1 row affected (0.001 sec)

MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+------+
| NAME |
+------+
| TARO |
| JIRO |
+------+
2 rows in set (0.000 sec)

# cat /var/log/mariadb/sql.log
/usr/libexec/mariadbd, Version: 10.5.16-MariaDB-log (MariaDB Server). started with:
Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock
Time                Id Command  Argument
230727 23:54:06      3 Connect  root@localhost on  using Socket
                     3 Query    select @@version_comment limit 1
230727 23:54:12      3 Query    SELECT DATABASE()
                     3 Init DB  SAMPLEDB
                     3 Query    show databases
                     3 Query    show tables
                     3 Field List       SAMPLETABLE
230727 23:54:22      3 Query    INSERT INTO SAMPLETABLE (NAME) VALUES("JIRO")
230727 23:54:29      3 Query    SELECT * FROM SAMPLETABLE
230727 23:54:32      3 Quit

■ 슬로 쿼리 로그

슬로 쿼리 로그는 슬로 쿼리(디버그) 로깅이라고도 하며, mysqld는 long_query_time으로 지정한 시간(초)보다 시간을 필요로 한 쿼리 또는 인덱스를 사용하지 않은 쿼리를 로깅한다.

▶ 슬로 쿼리 로그 설정

# https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html
$ cat <<EOF >> /etc/my.cnf

# Slow Query log
slow_query_log=1
slow_query_log_file=/var/log/mariadb/slow.log
long_query_time=1
log_queries_not_using_indexes
log_slow_admin_statements
EOF


# mysqld 다시시작
$ systemctl restart mysqld

옵션	내용
slow_query_log	슬로 쿼리 로그의 출력 여부를 설정 (1: 출력함, 0: 출력하지 않음)
slow_query_log_file	슬로 쿼리 로그의 파일명을 설정 (지정하지 않으면 general_log에 따른다.)
long_query_time	쿼리 처리 시간(초 단위)을 설정, 초를 초과하면 슬로 쿼리 로그로 출력함 (기본값 10초)
log_queries_not_using_indexes	인덱스를 사용하지 않는 쿼리를 모두 출력할 때 지정, 이 설정을 지정해 두면 앞서 생성한 테스트용 테이블은 인덱스를 생성해 두지 않았으므로 테스트용 테이블을 조작하는 모든 쿼리가 출력된다.
log_slow_admin_statements	관리용 SQL 문(OPTIMIZE TABLE, ANALYZE TABLE, ALTER TABLE, …) 처럼 처리하는데 시간이 걸리는 쿼리를 출력하고자 할 때 지정

▶ 슬로 쿼리 로그 확인

MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+------+
| NAME |
+------+
| TARO |
| JIRO |
| TOTO |
+------+
3 rows in set (0.001 sec)

$ cat /var/log/mariadb/slow.log
/usr/libexec/mariadbd, Version: 10.5.16-MariaDB-log (MariaDB Server). started with:
Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock
Time                Id Command  Argument
# Time: 230728  0:10:12
# User@Host: root[root] @ localhost []
# Thread_id: 3  Schema: SAMPLEDB  QC_hit: No
# Query_time: 0.000792  Lock_time: 0.000617  Rows_sent: 3  Rows_examined: 3
# Rows_affected: 0  Bytes_sent: 115
use SAMPLEDB;
SET timestamp=1690470612;
SELECT * FROM SAMPLETABLE;

log 내용	설명
User@Host	접속 사용자와 호스트명을 출력
Query_time	쿼리 실행 시간
Lock_time	테이블 또는 데이터베이스가 잠긴 시간
Rows_examined	처리 대상이 된 열수

여기서 출력된 슬로 쿼리 로그 정보는 지연이 발생해서가 아니라 log_queries_not_using_indexes를 설정해서 출력된 것이다.

쿼리 지연이 발생하는 로그 정보라면 앞에 설정에서는 Query_time이 적어도 10초 이상이어야 한다. 이번 출력에서는 Query_time: 0.000792이므로 전혀 문제가 되지 않는다. Query_time은 CPU 처리 시간이 아니라 실제로 응답할 때까지 걸리는 시간이므로, 여기에 출력된 시간은 사용자에게 응답한 시간과 같다. 이 값이 크다면 로그 정보에서 실행한 SQL을 분석해서 데이터베이스에서 지연이 발생한 곳을 확정할 수 있고 응답 시간을 개선시킬 수 있다.

■ 바이너리 로그

바이너리 로그는 바이너리(백업) 로깅이라고도 하며, mysqld에서 데이터 갱신을 일으키는 문장(Statement)을 바이너리 정보로 로깅하며 리플리케이션에도 사용된다.

▶ 바이너리 로그 설정

# https://dev.mysql.com/doc/refman/5.7/en/replication-options-binary-log.html
$ cat <<EOF >> /etc/my.cnf

# Slow Query log
log_bin=/var/log/mariadb/bin.log
log_bin_index=/var/log/mariadb/bin.list
max_binlog_size=1M
expire_logs_days=1
EOF


# mysqld 다시시작
$ systemctl restart mysqld

옵션	내용
log_bin	바이너리 로그의 출력 여부를 설정, 로그 파일명을 지정하면 출력이 활성화됨
log_bin_index	바이너리 로그의 인덱스 파일명을 설정, 바이너리 로그 파일명을 관리하기 위한 파일명
max_binlog_size	바이너리 로그의 최대 파일 크기를 지정, 지정한 파일 크기를 초과하면 파일을 자동으로 변경하며 설정 가능한 값은 4096B 이상 1GB 이하이다.
expire_logs_days	바이너리 로그의 저장 기간을 일수로 지정, 일수를 초과하면 제거 (기본값 0, 0: 제거하지 않는다는 의미)

▶ 바이너리 로그 확인

바이너리 로그(/var/log/mariadb/bin.000001)는 이름 그대로 바이너리 정보이므로, mysqlbinlog 명령을 통해서 로깅되어 있는 내용을 확인한다. (mysqlbinlog 명령은 바이너리 로그를 텍스트(쿼리 로그)로 변환하는 유틸리티)

$ mysqlbinlog /var/log/mariadb/bin.000001

MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("SAKURA");
Query OK, 1 row affected (0.002 sec)

MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+--------+
| NAME   |
+--------+
| TARO   |
| JIRO   |
| TOTO   |
| SAKURA |
+--------+
4 rows in set (0.001 sec)

“at 256”의 256이 롤백에서 사용할 포지션 번호

$ mysqlbinlog /var/log/mariadb/bin.000001
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#230728  0:47:57 server id 1  end_log_pos 256 CRC32 0xefadb4d1  Start: binlog v 4, server v 10.5.16-MariaDB-log created 230728  0:47:57 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
rZHCZA8BAAAA/AAAAAABAAABAAQAMTAuNS4xNi1NYXJpYURCLWxvZwAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAACtkcJkEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgHRtK3v
'/*!*/;
# at 256
#230728  0:47:57 server id 1  end_log_pos 285 CRC32 0xcfef43a4  Gtid list []
# at 285
#230728  0:47:57 server id 1  end_log_pos 322 CRC32 0xdc0aa6b7  Binlog checkpoint bin.000001
# at 322
#230728  0:53:44 server id 1  end_log_pos 364 CRC32 0xf2c32d83  GTID 0-1-1 trans
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
/*!100001 SET @@session.server_id=1*//*!*/;
/*!100001 SET @@session.gtid_seq_no=1*//*!*/;
START TRANSACTION
/*!*/;
# at 364
#230728  0:53:44 server id 1  end_log_pos 482 CRC32 0x332ec7ab  Query   thread_id=4     exec_time=0     error_code=0
use `SAMPLEDB`/*!*/;
SET TIMESTAMP=1690473224/*!*/;
SET @@session.pseudo_thread_id=4/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1, @@session.sql_if_exists=0/*!*/;
SET @@session.sql_mode=1411383296/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
INSERT INTO SAMPLETABLE (NAME) VALUES("SAKURA")
/*!*/;
# at 482
#230728  0:53:44 server id 1  end_log_pos 513 CRC32 0x9e60ac9c  Xid = 5
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

▶ 바이너리 로그를 이용해 롤백

풀 백업 + 바이너리 로그가 있으면 풀 백업을 수행한 시점부터 바이너리 로그가 존재하는 범위 내에서 원하는 상태까지 롤백할 수 있다.
“mysqldump 명령”은 SQL 형식으로 데이터베이스를 백업하는 명령으로 명령 자체는 콘솔 SQL 문을 출력하므로 > 리다이렉트를 사용해서 파일로 저장한다.

# (1) mysqldump 명령을 이용해 풀 백업
$ mysqldump -u root -p --all-databases > /var/log/mariadb/all_backup.sql


# (2) 풀 백업 상태 확인
$ mysql -u root -e "show master status;"
+------------+----------+--------------+------------------+
| File       | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------+----------+--------------+------------------+
| bin.000001 |      513 |              |                  |
+------------+----------+--------------+------------------+


# (3) 바이너리 로그를 갱신
MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("rollback1");
Query OK, 1 row affected (0.001 sec)

MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("rollback2");
Query OK, 1 row affected (0.001 sec)

MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("rollback3");
Query OK, 1 row affected (0.001 sec)

MariaDB [SAMPLEDB]> INSERT INTO SAMPLETABLE (NAME) VALUES("rollback4");
Query OK, 1 row affected (0.001 sec)

MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+-----------+
| NAME      |
+-----------+
| TARO      |
| JIRO      |
| TOTO      |
| SAKURA    |
| rollback1 |
| rollback2 |
| rollback3 |
| rollback4 |
+-----------+
8 rows in set (0.000 sec)


# (4) 롤 백 수행

# 모든 바이너리 로그 파일을 복사(백업)
$ mkdir /var/log/mariadb/rollback
$ cp /var/log/mariadb/bin* /var/log/mariadb/rollback/

# rollback2 삽입 위치 검색
$ mysqlbinlog /var/log/mariadb/rollback/bin.000001 --start-datetime "2023-07-28 17:03:20" --stop-datetime "2023-07-28 17:04:00"

~(생략)~

# at 364
#230728 17:03:20 server id 1  end_log_pos 485 CRC32 0xb6e4d19e  Query   thread_id=6     exec_time=0     error_code=0
use `SAMPLEDB`/*!*/;
SET TIMESTAMP=1690531400/*!*/;
SET @@session.pseudo_thread_id=6/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1, @@session.sql_if_exists=0/*!*/;
SET @@session.sql_mode=1411383296/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
INSERT INTO SAMPLETABLE (NAME) VALUES("rollback1")
/*!*/;

~(생략)~


# (5) 풀백업한 상태까지로 롤백

$ mysql -u root -p < /var/log/mariadb/all_backup.sql

MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+--------+
| NAME   |
+--------+
| TARO   |
| JIRO   |
| TOTO   |
| SAKURA |
+--------+


# (6) rollback2를 삽입한 위치까지 업데이트

$ mysqlbinlog /var/log/mariadb/rollback/bin.000001 --start-position 364 --stop-position 752 | mysql -u root -p

MariaDB [SAMPLEDB]> SELECT * FROM SAMPLETABLE;
+-----------+
| NAME      |
+-----------+
| TARO      |
| JIRO      |
| TOTO      |
| SAKURA    |
| rollback1 |
| rollback2 |
+-----------+
4 rows in set (0.001 sec)

revenge1005 🧗

[시스템 관리] 03. MySQL 로깅

🔔 MySQL 로길

SYS_MGMT 카테고리 내 다른 글 보러가기

댓글 남기기

최근 글 10 개 :)