MySQL 로그 파일

MySQL 로그 파일

MySQL은 다른 상용 DBMS와 비교하면 DBA나 개발자를 위한 진단 도구가 상당히 부족한 편이다. 그렇지만 로그 파일을 이용하면 MySQL의 상태나 부하를 일으키는 원인을 찾아서 해결할 수 있다. 많은 사용자가 로그 파일의 내용을 무시하고 다른 방법으로 해결책을 찾으려고 노력하곤 하는데, 무엇보다 MySQL 서버에 문제가 생겼을 때는 다음에 설명하는 각 용도별 로깅 기능이나 로그 파일을 자세히 확인하는 습관을 들일 필요가 있다.

1. 에러 로그 파일

MySQL이 실행되는 도중에 발생하는 에러나 경고 메시지가 출력되는 로그 파일이다. 에러 로그 파일의 위치는 MySQL 컨피규레이션 파일에 "log_error"라는 이름의 파라미터에 정의된 경로에 있는 파일이거나 별도로 정의되지 않은 경우에는 데이터 디렉터리("datadir" 파라미터에 설정된 디렉터리)에 ".err"이라는 확장자가 붙은 파일이다. 여러 가지 메시지가 다양하게 출력되지만 다음에 소개되는 메시지를 가장 자주 보게 될 것이다.

MySQL이 시작하는 과정과 관련된 정보성 및 에러 메시지

MySQL의 컨피규레이션 파일을 변경하거나 데이터베이스가 비정상적으로 종료된 이후 다시 시작하는 경우에는 반드시 MySQL 에러 로그 파일을 통해 설정된 변수의 이름이나 값이 명확하게 설정되고 의도한 바대로 적용됐는지 확인해야 한다. MySQL 서버가 정상적으로 기동했고("mysqld started" 메시지 확인). 새로 변경하거나 추가한 파라미터에 대한 특별한 에러나 경고성 메시지가 없다면 정상적으로 적용된 것으로 판단하면 된다. 그렇지 않고 특정 변수가 무시(ignore)된 경우에는 MySQL 서버는 정상적으로 기동하지만 해당 파라미터는 MySQL에 적용되지 못했음을 의미한다. 그리고 변수명을 인식하지 못하거나 설정된 파라미터 값의 내용을 인식하지 못하는 경우에는 MySQL 서버가 에러 메시지를 출력하고 시작하지 못했다는 메시지를 보여줄 것이다.

마지막으로 종료할 때 비정상적으로 종료된 경우 나타나는 InnoDB의 트랜잭션 복구 메시지

InnoDB의 경우에는 MySQL 서버가 비정상적 또는 강제적으로 종료됐다면 다시 시작되면서 완료되지 못한 트랜잭션을 정리하고 디스크에 기록되지 못한 데이터가 있다면 다시 기록하는 재처리 작업을 하게 된다. 이 과정에 대한 간단한 메시지가 출력되는데 간혹 문제가 있어서 복구되지 못할 때는 해당 에러 메시지를 출력하고 MySQL은 다시 종료될 것이다. 일반적으로 이 단계에서 발생하는 문제는 상대적으로 해결하기가 어려운 문제점일 때가 많고, 때로는 innodb_force_recovery 파라미터를 0보다 큰 값으로 설정하고 재시작해야만 MySQL이 시작될 수도 있다.

쿼리 처리 도중에 발생하는 문제에 대한 에러 메시지

쿼리 도중 발생하는 문제점은 사전 예방이 어려우며, 주기적으로 에러 로그 파일을 검토하는 과정에서 알게 된다. 쿼리의 실행 도중 에러가 발생했다거나, 복제에서 문제가 될 만한 쿼리에 대한 경고 메시지가 에러 로그에 기록된다. 그래서 자주 에러 로그 파일을 검토하는 것이 데이터베이스의 숨겨진 문제점을 해결하는 데 많이 도움될 것이다.

비정상적으로 종료된 커넥션 메시지(Aborted connection)

어떤 데이터베이스 서버의 로그 파일을 보면 이 메시지가 상당히 많이 누적돼 있는 경우가 있다. 클라이언트 애플리케이션에서 정상적으로 접속 종료를 하지 못하고 프로그램이 종료된 경우, MySQL 서버의 에러 로그 파일에 이런 내용이 쌓인다. 물론, 중간에 네트워크 문제가 있어서 의도하지 않게 접속이 끊어지는 경우에도 이런 메시지가 발생한다. 만약 이런 메시지가 아주 많이 발생한다면 애플리케이션의 커넥션 종료 로직을 한번 검토해볼 필요가 있다. max_connect_errors 시스템 변수 값이 너무 낮게 설정된 경우, 클라이언트 프로그램이 MySQL 서버에 접속하지 못하고 "Host 'host_name' is blocked'라는 에러가 발생할 수도 있다. 이 메시지는 클라이언트 호스트에서 발생한 에러(커넥션 실패나 강제 연결 종료와 같은)의 횟수가 max_connect_errors 변수의 값을 넘게 되면 발생한다.

InnoDB의 모니터링 명령이나 상태 조회 명령("SHOW ENGINE INNODB STATUS" 같은)의 결과 메시지

InnoDB의 테이블 모니터링이나 락 모니터링, 또는 InnoDB의 엔진 상태를 조회하는 명령은 상대적으로 큰 메시지를 에러 로그 파일에 기록한다. 만약 InnoDB의 모니터링을 활성화 상태로 만들어 두고 그대로 유지하는 경우에는 에러 로그 파일이 매우 커져서 파일 시스템의 공간을 다 사용해 버릴지도 모른다. 반드시 모니터링을 사용한 이후에는 다시 비활성화해서 에러 로그 파일이 커지지 않게 만들어야 한다.

MySQL의 종료 메시지

가끔 MySQL이 아무도 모르게 종료돼 있거나 때로는 아무도 모르게 재시작되어 버리는 경우를 본 적이 있을 것이다. 이런 경우 에러 로그 파일에서 MySQL이 마지막으로 종료되면서 출력한 메시지를 확인하는 것이 왜 MySQL 서버가 종료됐는지 확인하는 유일한 방법이다. 만약 누군가가 MySQL 서버를 종료시켰다면 에러 로그 파일에서 "Normal shutdown"이라는 메세지를 확인할 수 있을 것이다. 그렇지 않고 아무런 종료 관련 메시지가 없거나 스택 트레이스(대표적으로 16진수의 주소값이 잔뜩 출력되는)와 같은 내용이 출력되는 경우에는 MySQL 서버가 세그먼테이션 풀트(Segmentation fault)로 비정상적으로 종료된 것으로 판단할 수 있다. 세그멘테이션 풀트로 종료된 경우에는 스택 트레이스의 내용을 최대한 참조해서 MySQL의 버그와 연관이 있는지 조사한 후 MySQL의 버전을 업그레이드하거나 회피책(WorkAround)을 찾는 것이 최적의 방법이다.

2. 제너럴 쿼리 로그 파일(제너럴 로그 파일, General log)

가끔 MySQL 서버에서 실행되는 쿼리로 어떤 것들이 있는지 전체 목록을 뽑아서 검토해 볼 때가 있는데, 이때는 쿼리 로그를 활성화해서 쿼리를 쿼리 로그 파일로 기록하게 한 다음, 그 파일을 검토하면 된다. 쿼리 로그 파일에는 다음과 같이 시간 단위로 실행됐던 쿼리의 내용이 모두 기록된다. 슬로우 쿼리 로그와는 조금 다르게 제너럴 쿼리 로그는 실행되기 전에 MySQL이 쿼리 요청을 받으면 바로 기록하기 때문에 쿼리 실행 중에 에러가 발생해도 일단 로그 파일에 기록된다.

101012 13:52:53		2 Query SELECT 'tab1.* FROM 'tab1' WHERE (fd1 = 1) LIMIT 1
			2 Query SELECT 'tab1.* FROM 'tab' WHERE (fd1 = 1) LIMIT 1
                    	2 Query SELECT 'tab2.* FROM 'tab2' WHERE (fd2 = 'fd_value') LIMIT 1
                    	2 Query SELECT * FROM tab3
                    	2 Quit

쿼리 로그 파일은 MySQL 5.1.12 이전 버전에서는 컨피규레이션 파일에서 "general-log"라는 이름의 파라미터에 정의된 경로에 있는 파일이고, MySQL 5.1.12 이상의 버전에서는 "general_log_file"이라는 이름의 파라미터에 정의된 경로에 있는 파일이다. MySQL 5.1 이상에서는 쿼리 로그를 파일이 아닌 테이블에 저장하도록 설정할 수 있으므로 이 경우에는 파일이 아닌 테이블을 SQL로 조회해서 검토해야 한다. 쿼리 로그를 파일로 저장할지 테이블로 저장할지는 "log_output" 파라미터에 의해 결정된다.

3. 슬로우 쿼리 로그

MySQL 서버의 쿼리 튜닝은 크게 서비스가 적용되기 전에 전체적으로 튜닝하는 경우와 서비스 운영 중에 MySQL 서버의 전체적인 성능 저하를 검사하거나 또는 정기적인 점검을 위한 튜닝으로 나눌 수 있다. 전자의 경우에는 검토해야 할 대상 쿼리가 전부라서 모두 튜닝하면 되지만, 후자의 경우에는 어떤 쿼리가 문제의 쿼리인지 판단하기가 상당히 어렵다. 이런 경우에 사용되고 있는 쿼리 중에서 어떤 쿼리가 문제인지를 판단하는 데 슬로우 쿼리 로그가 상당히 많은 도움이 된다.

슬로우 쿼리 로그 파일에는 컨피규레이션에 정의한 시간(long_query_time 파라미터에 초 단위로 설정됨) 이상의 시간이 소요된 쿼리가 모두 기록된다. 슬로우 쿼리 로그는 MySQL이 쿼리를 실행한 후, 실제 소요된 시간을 기준으로 슬로우 쿼리 로그에 기록할지 여부를 판단하기 때문에 반드시 쿼리가 정상적으로 실행이 완료되어야 슬로우 쿼리 로그에 기록될 수 있다. 즉, 슬로우 쿼리 로그 파일에 기록되는 쿼리는 일단 정상적으로 실행이 완료됐고 실행하는 데 걸린 시간이 "long_query_time"에 정의된 초(Second)보다 많이 걸린 쿼리인 것이다.

MySQL 5.1 미만에서 슬로우 쿼리 로그를 설정하는 방법은 다음과 같다.

long_query_time = 1
log_slow_queries = /var/log/mysql-slow.log

MySQL 5.1 이상에서 슬로우 쿼리 로그를 설정하는 방법은 MySQL 5.0과 조금 다르게 "log_output" 설정 옵션을 이용해 쿼리를 파일로 기록할지 테이블로 기록할지 선택할 수 있다. log_output 옵션을 TABLE로 설정하면 제너럴 로그나 슬로우 쿼리 로그를 "mysql" DB의 테이블(general_log와 slow_log 테이블)에 저장하며, FILE로 설정하면 기존 버전과 같이 파일로 저장한다.

log-output = FILE 또는 TABLE
slow-query-log = 1
long_query_time = 1
slow_query_log_file = /var/log/mysql-slow.log

위와 같이 설정하면 실제 슬로우 쿼리 로그 파일에는 다음과 같은 형태로 내용이 출력된다. MySQL의 잠금 처리는 MySQL 엔진 레벨과 스토리지 엔진 레벨의 두 가지 레이어로 처리되는데, MyISAM이나 MEMORY 스토리지 엔진과 같은 경우에는 별도의 스토리지 엔진 레벨의 잠금을 가지지 않지만 InnoDB의 경우 MySQL 엔진 레벨의 잠금과 스토리지 엔진 자체적인 잠금을 가지고 있다. 위와 같은 이유로 슬로우 쿼리 로그에 출력되는 내용이 상당히 혼란스러울 수 있다.

# Time: 110202 12:13:14
# User@Host: root[root] @ localhost []
# Query_time: 15.407663 Lock_time: 0.000197 Rows_sent: 0 Rows_examined: 5
update tab set fd=100 where fd=10;

위와 같은 슬로우 쿼리 내용을 한번 확인해 보자. 이 내용은 슬로우 쿼리가 파일로 기록된 것을 일부 발췌한 내용인데, 테이블로 저장된 슬로우 쿼리도 내용은 동일하다. MySQL 5.0 이하 버전에서는 소요 시간(초 단위)에서 소수점 이하 부분은 무시되지만, MySQL 5.1 이상에서는 마이크로 초까지 표시된다. 하지만 MySQL 5.1 이상에서도 슬로우 쿼리 로그를 테이블로 기록하는 경우에는 MySQL 5.0 이하에서와 같이 소수점 이하의 부분은 무시된다(이는 MySQL에서 밀리초 이하를 관리할 수 있는 데이터 타입이 없기 때문이다).

• "Time" 항목은 쿼리가 시작된 시간이 아니라 쿼리가 종료된 시점을 의미한다. 그래서 쿼리가 언제 시작됐는지 확인하려면 "Time" 항목에 나온 시간에서 Query_time 만큼 빼야 한다.
• "User@Host"는 쿼리를 실행한 사용자의 계정이다.
• "Query_time"은 쿼리가 실행되는데 걸린 전체 시간을 의미한다. 많이 혼동되는 부분 중 하나인 "Lock_time"은 사실 위에서 설명한 두 가지 레벨의 잠금 가운데 MySQL 엔진 레벨에서 관장하는 테이블 잠금에 대한 대기 시간만 표현한다. 위 예제의 경우, 이 UPDATE 문장을 실행하기 위해 0.000197초 간 테이블 락을 기다렸다는 의미가 되는데, 여기서 한 가지 더 중요한 것은 이 값이 0이 아니라고 무조건 잠금 대기가 있었다고 판단하기는 어렵다는 것이다. Lock_time에 표기된 시간은 실제 쿼리가 실행되는 데 필요한 잠금 체크와 같은 코드의 실행 부분의 시간까지 모두 포함되기 때문이다. 즉, 이 값이 너무 작은 값이면 무시해도 무방하다.
• "Rows_examined"는 이 쿼리가 처리되기 위해 몇 건의 레코드에 접근했는지를 의미하며, "Rows_sent"는 실제 몇 건의 처리 결과를 클라이언트로 보냈는지를 의미한다. 일반적으로 "Rows_examined"의 레코드 건수는 높지만 "Rows_sent"에 표시된 레코드 건수가 상당히 적다면 이 쿼리는 조금 더 적은 레코드만 접근하도록 튜닝해 볼 가치가 있는 것이다(GROUP BY나 COUNT(), MIN(), MAX(), AVG() 등과 같은 집합 함수가 아닌 쿼리인 경우만 해당).

MyISAM이나 MEMORY 스토리지 엔진에서는 테이블 단위의 잠금을 사용하고 MVCC와 같은 메커니즘이 없기 때문에 SELECT 쿼리라 하더라도 Lock_time이 1초 이상 소요될 가능성이 있다. 하지만 가끔 InnoDB 테이블에 대한 SELECT 쿼리의 경우에도 Lock_time이 0이 아닌 경우가 발생할 수 있는데, 이는 InnoDB의 레코드 수준의 잠금이 아닌 MySQL 엔진 레벨에서 설정한 테이블 잠금 때문일 가능성이 높다. 그래서 InnodDB 테이블에만 접근하는 쿼리 문장의 슬로우 쿼리 로그에서는 Lock_time 값은 튜닝이나 쿼리 분석에 별로 도움이 되지 않는다.

그리고 왜 이렇게 설계됐는지는 잘 모르겠지만 사용자가 명시적으로 "LOCK TABLES tb_test" 명령으로 획득한 잠금을 기다리는 쿼리는 슬로우 쿼리 로그에 기록되지 않는다. 슬로우 쿼리 로그의 내용을 분석해 쿼리 단위로 평균을 산출해서 많이 실행된 쿼리 순서대로 정렬한 후 파일로 기록하는 스크립트도 있으므로, 만약 많은 슬로우 쿼리 로그를 분석해야 할 때는 참고한다. MySQL에 기본적으로 포함된 mysqlslowdump라는 프로그램으로도 이러한 분석이 가능하다.

4. 바이너리 로그와 릴레이 로그

바이너리 로그 파일은 마스터 MySQL 서버에 생성되고 릴레이 로그는 슬레이브 MySQL 서버에 생성된다는 것 말고는 바이너리 로그와 릴레이 로그 파일의 내용이나 포맷은 동일하다. 즉, 여기서부터 언급되는 내용은 바이너리 로그로 주로 설명되지만 릴레이 로그도 동일하게 적용할 수 있는 기능이다. 그리고 바이너리 로그에는 순수한 SELECT 문장과 같이 데이터의 구조나 내용을 변경하지 않는 쿼리는 기록되지 않는다.

가끔 바이너리 로그 파일의 내용을 열어서 눈으로 확인하거나 MySQL 서버에 다시 실행해야 할 때가 있는데, 바이너리 로그는 이름 그대로 이진 파일로 돼 있어서 사람의 눈으로 보거나 MySQL 서버에서 바로 실행할 수는 없다. 이진 형태의 바이너리 로그 파일을 텍스트 형태로 바꾸려면 MySQL 홈 디렉터리의 bin 디렉터리에 있는 mysqlbinlog라는 프로그램을 이용할 수 있는데, 기본적으로 mysqlbinlog는 특정 시간(또는 특정 바이너리 로그 위치)부터 특정 시간(또는 특정 바이너리 로그 위치)까지의 로그 내용을 SQL 형태로 읽어서 화면으로 출력하는 일만 할 수 있다.

다음 명령으로 바이너리 로그 파일의 전체 내용을 SQL 텍스트로 읽은 다음 다른 파일로 저장해서 확인할 수 있다.

shell > mysqlbinlog binlog.0000012 > mysql-binlog.sql

날짜와 시간을 정해서 바이너리 로그 파일의 내용을 SQL 텍스트로 읽은 다음 다른 파일로 저장해서 확인할 수 있다. 이 명령은 주로 언제부터 언제까지 발생했던 쿼리 중에서 문제가 될 만한 쿼리를 찾아낼 때 사용된다.

shell > mysqlbinlog --start-datetime="2011-01-18 10:00:00" --stop-datetime="2011-01-18 10:10:00" binlog.0000012 > mysql-binlog.sql

바이너리 로그 파일에서 특정 위치(포지션)만 뽑아서 SQL 문장을 만들어 낸 후, 그 결과를 다시 다른 파일로 저장할 수 있다. 이 명령은 복제가 실패했거나 장애로 인해 문제가 발생했을 때 바이너리 로그에 기록된 위치를 대략적으로 알고 있을 때 자주 사용된다.

shell > mysqlbinlog --start-position=100000 --stop-position=20000 binlog.0000012 > mysql-binlog.sql

위와 같은 방식으로 텍스트 형태로 바꾼 바이너리 로그는 바로 MySQL에서 실행 가능한 형태로 만들어진다. 때로는 다음과 같은 명령으로 바이너리 로그의 SQL 내용을 텍스트 파일로 변환해 바로 MySQL에서 실행할 수도 있다.

shell > mysqlbinlog binlog.0000012 | mysql -uroot -p

또는

shell > mysqlbinlog binlog.0000012 > mysql-binlog.sql
mysql > SOURCE mysql-binlog.sql

위 예제에서 시간이나 바이너리 로그의 위치로 시작 값 또는 종료 값만 설정할 수도 있다. 이 경우에는 인자로 지정한 바이너리 로그 파일의 처음부터 종료 값까지 또는 시작 값부터 로그 파일의 끝까지 SQL 텍스트를 분석해서 출력한다. 사용 중인 운영체제의 종류별로 가능한 방식을 선택해서 사용하면 된다.

참고

• Real MySQL