4.4 MySQL 로그 파일

MySQL 서버에서 상태를 진단할 수 있는 많은 도구들이 지원되지만, 이런 기능들은 많은 지식을 필요로 하는 경우가 많다.
하지만 로그 파일을 이용하면 MySQL 서버의 깊은 내부 지식이 없어도 상태나 부하를 일으키는 원인을 쉽게 찾아서 해결할 수 있다.

에러 로그 파일

MYSQL이 실행하는 도중에 발생하는 에러나 경고 메시지가 출력되는 로그 파일.
에러 로그 파일의 위치는 MySQL 설정 파일(my.cnf, my.ini)에서 log_error라는 이름의 파라미터로 정의된 경로에 생성.
MySQL 설정 파일에 별도로 정의되지 않은 경우, datadir 파라미터에 .err라는 확장자가 붙은 파일로 생성된다.

또는 `show variables like 'log_error'; 명령어를 통해 확인 가능!

• datadir 경로
  

• my.ini
  

• BOOK-CP502735AV.err
  

여러가지 메시지가 다양하게 출력되지만, 그중 자주 보이는 메시지 정리

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

설정 파일을 변경하거나 데이터베이스가 비정상적으로 종료된 이후 다시 시작하는 경우에는
반드시 MySQL 에러 로그 파일을 통해 설정된 변수의 이름이나 값이 명확하게 설정되고 의도한 대로 적용됐는지 확인해야한다.

• MYSQL 서버가 정상적으로 기동 : mysqld: ready for connections 메시지 확인, 새로 추가한 파라미터에 대한 특별한 에러나 경고성 메시지가 없으면 정상
• 특정 변수가 무시된 경우 : MySQL 서버는 정상적으로 기동하지만 해당 파라미터는 MySQL에 적용되지 못했음을 의미.
• 변수명이나 값을 인식하지 못하는 경우 : 에러 메시지 출력하고, 시작하지 못했다는 메시지를 보여줄 것

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

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

innodb_Force_recovery : https://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html 참고

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

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

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

• [Warning] Aborted connection 7937 to db: 'test_db' user: 'test_db' host: 'localhost' (Got an error reading communication packets)
  mysql 운영중 이런 로그가 지속적으로 계속 쌓였던 문제.
  클라이언트가 정상적으로 연결되었지만, 이후 강제적으로 종료되었을 때 Aborted_clients 상태값의 카운트를 증가한 후 에러 로그에 남게 된다.
  이때 에러 로그에 기록을 남기려면 --log-warning 옵션 활셩화 해야함.

MYSQL Refernce Manual을 보면 주요 원인은 다음과 같다.

• 클라이언트 프로그램이 종료 전에 mysql_close()를 호출하지 않은 경우
• 데이터 전송 중, 클라이언트 프로그램이 갑자기 종료된 경우
• 클라이언트가 wait_timeout과 같이 설정된 시간 이상으로 동작이 없는 경우
• 클라이언트가 데이터베이스에 접근할 권한이 없는 경우
• connection packet이 올바른 정보를 가지고 있지 않은 경우
• max_allowd_packet 변수 값이 너무 작게 설정되어 있거나 쿼리가 mysqld에 할당한 메모리보다 많은 양을 요구할 경우 (Packet Too Large)

위와 같은 원인들로 커녁션이 부족한 현상 등 비정상적인 현상이 일어날 수 있다.

default connection은 150개 정도지만, connection이 닫히지 않아 커넥션 부족 현상 등..

이런 경우, 에러 로그를 확인해 원인을 살펴보는 것이 좋다.

겪었던 문제 상황

• connection을 proxy하는 클래스를 사용중, close()로직이 정상적으로 동작되지 않아 부하를 가했을 때, 초반엔 정상적으로 동작하다가 deadLock(?), connection 부족현상 등의 문제를 겪었음
• k8s를 사용함에 있어 app을 scale out했을 때, dbms의 max-connection이 200개 였고, 한 app당 connection pool size를 50개 씩 줬을 때, connection을 가져올 수 없었던 문제

InnoDB의 모니터링과 같은 결과 메시지

SET GLOBAL innodb_status_output=ON; 명령어를 사용하게 된다면 InnoDB의 상태 정보를 err_log에 기록하게 된다.

InnoDB 모니터링을 활성화 해두면 로그가 무척 커져서 파일 시스템의 공간을 다 사용해 버릴지도 모른다.
모니터링을 사용한 후에는 다시 비활성화 해서 에러 로그파일이 커지지 않게 만들어야 한다.

MySQL의 종료 메시지

MySQL이 아무도 모르게 종료/재시작 되는 경우가 있을 수 있다.
이러한 경우 에러 로그 파일에서 MySQL이 마지막으로 종료되면서 출력한 메시지를 확인하는 것이
왜 MySQL 서버가 종료됐는지 확인하는 유일한 방법이다.
만약 누군가가 MYSQL 서버를 종료시켰다면 에러 로그 파일에서 Received SHUTDOWN from user ...과 같은 메시지를 확인할 수 있다.
그렇지 않고 종료 관련 메시지가 없거나 스택 트레이스와 같이 출력되는 경우에는 스택트레이스를 참조해서 MYSQL의 버전을 업그레이드 하거나 회피책을 찾는것이
최선의 방법이다.

General Log

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

• general_log 설정 및 확인하기
  https://m.blog.naver.com/maestrois/222164588313

슬로우 쿼리 Log

MySQL서버의 쿼리 튜닝은 크게 서비스가 적용되기 전에 전체적으로 튜닝하는 경우와 서비스 운영중 튜닝으로 구분할 수 있다.
전자의 경우엔 검토해야 될 대상이 전부라서 모두 튜닝을 하면 되지만, 후자의 경우엔 어떤 쿼리가 문제인지 판단하기가 어렵다.
이 경우, 슬로우 쿼리 로그가 상당히 많은 도움이 된다.

long_query_time 시스템 변수에 설정한 시간 이상의 시간이 소요된 쿼리가 모두 기록되게 된다.
(반드시 쿼리가 정상적으로 실행이 완료되야 슬로우 쿼리로그에 기록)

log_output 옵션을 사용하여, 테이블로 기록할지, 파일로 기록할지 선택할 수 있다.

• 만약 2초이상 걸리는 쿼리를 슬로우쿼리로 보고 파일로 쌓는 구조를 만들려면?
  solution) my.cnf(my.cnf)에서 변경 또는 set global명령어를 사용하여 런타임 시 사용 가능
  

슬로우 쿼리 로그 분석

• Time : 쿼리가 종료된 시점. 쿼리가 언제 시작됐는지 확인하려면 Time항목에 나온 시간에서 Query_time을 빼야함.
• User@Host : 쿼리를 실행한 사용자의 계정
• Query_time : 쿼리가 실행되는 데 걸린 전체 시간
• Lock_time : 테이블 잠금에 대한 대기 시간, 값이 0이 아니라고 해서 무조건 잠금 대기가 있었다고 판단하기 어렵다. 잠금 체크와 같은 코드 실행 부분의 시간까지 모두 포함되기 때문이다. 즉, 이 값이 매우 작은 값이면 무시해도 무방.
• Rows_examined : 쿼리가 처리되기 위해 몇 건의 레코드에 접근했는지를 의미
• Rows_sent : 실제 몇 건의 처리 결과를 클라이언트로 보냈는지 의미로,
  Rows_examined의 레코드 건수는 높지만 Rows_sent가 상당히 적다면, 이 쿼리는 조금 더 적은 레코드만 접근하도록 튜닝해 볼 가치가 있다는 것.

슬로우 쿼리 활용하기

어떤 쿼리를 튜닝하기 위해 정기적으로 슬로우 쿼리 로그를 확인하는 것 보다는, 슬로우 쿼리 로그를 수집하여 자동으로 어떤 쿼리가 문제인지 알람을 보내주는 서비스를 만드는 것이 어떨까...

Slack으로 알람

https://jojoldu.tistory.com/570

ELK 모니터링

https://m.blog.naver.com/sory1008/220756173973

또는 prometheus, grafana를 사용하여 알람을 보내줄 수 있는 백엔드도 만들수 있을듯...