[Real Mysql 1권] 슬로우 쿼리 로그

 

1) MySQL 서버의 쿼리 튜닝  

- MySQL 서버의 쿼리 튜닝은 크게 서비스가 적용되기 전에 전체적으로 튜닝하는 경우와
  서비스 운영 중에 MySQL 서버의 전체적인 성능 저하를 검사하거나 정기적인 점검을 위한 튜닝으로 나눌 수 있다.

 

- 전자의 경우에는 검토해야 할 대상 쿼리가 전부라서 모두 튜닝하면 되지만,

  후자의 경우에는 어떤 쿼리가 문제의 쿼리인지 판단하기가 상당히 어렵다.
  이런 경우에 서비스에서 사용되는 쿼리 중에서 어떤 쿼리가 문제인지를 판단하는 데

  슬로우 쿼리 로그가 상당히 많은 도움이 된다. 

 

 

2) 슬로우 쿼리 로그

- 슬로우 쿼리 로그 파일에는 long_query_time 시스템 변수에 설정한 시간

  (long_query_time 파라미터는 초단위로 설정하지만 소수점 값으로 설정하면 마이크로 초 단위로 설정 가능함) 

  이상의 시간이 소요된 쿼리가 모두 기록된다.
 

- 슬로우 쿼리 로그는 MySQL이 쿼리를 실행한 후, 실제 소요된 시간을 기준으로

  슬로우 쿼리 로그에 기록할지 여부를 판단하기 때문에 반드시 쿼리가 정상적으로 실행이 완료돼야 

  슬로우 쿼리 로그에 기록될 수 있다.

 

-즉, 슬로우 쿼리 로그 파일에 기록되는 쿼리는 일단 정상적으로 실행이 완료됐고,

 실행하는 데 걸린 시간이 long_query_time에 정의된 시간보다 많이 걸린 쿼리인 것이다.

 

 

3) 슬로우 쿼리 로그의 log_output 옵션

- log_output 옵션을 이용해 슬로우 쿼리 로그를 파일로 기록할지 테이블로 기록할지 선택할 수 있다.
  log_output 옵션을 TABLE로 설정하면 제너럴 로그나 슬로우 쿼리 로그를

  mysql DB의 테이블(general_log와 slow_log 테이블)에 저장하며,
  FILE로 설정하면 로그의 내용을 디스크의 파일로 저장한다.

 

- log_output 옵션을 TABLE로 설정하더라도 mysql DB의 slow_log 테이블과 general_log 테이블은

  CSV 스토리지 엔진을 사용하기 때문에 결국 CSV 파일로 저장하는 것과 동일하게 작동한다.

 

 

4) 슬로우 쿼리 로그 분석 

- 위와 같이 설정하면 실제 슬로우 쿼리 로그 파일에는 다음과 같은 형태로 내용이 출력된다.
   MySQL의 잠금 처리는 MySQL 엔진 레벨과 스토리지 엔진 레벨의 두 가지 레이어로 처리되는데,

   MyISAM이나 MEMORY 스토리지 엔진과 같은 경우에는 별도의 스토리지 엔진 레벨의 잠금을 가지지 않지만,
   InnoDB의 경우 MySQL 엔진 레벨의 잠금과 스토리지 엔진 자체 잠금을 가지고 있다.
   이런 이유로 슬로우 쿼리 로그에 출력되는 내용이 상당히 혼란스러울 수 있다.

# Time: 2020-07-19T15:44:22. 178484+09:00
# User@Host: root[root] @ localhost [] Id: 14
# Query_time: 1.180245  Lock_time: 0.002658  Rows_sent: 1  Rows_examined: 2844047
use employees;
SET timestamp=1595141060
select emp_no, max(salary) from salaries;

- 위의 슬로우 쿼리 로그 내용은 한 번 확인해 보자.
   이 내용은 슬로우 쿼리가 파일로 기록된 것을 일부 발췌한 내용인데,
   테이블로 저장된 슬로우 쿼리도 내용은 동일하다.

(1) Time 

-  이 항목은 쿼리가 시작된 시간이 아니라 쿼리가 종료된 시점을 의미한다.
   그래서 쿼리가 언제 시작됐는지 확인하려면 'Time' 항목에 나온 시간에서 'Query_time'만큼 빼야 한다.

(2) 'User@Host'

- 쿼리를 실행한 사용자의 계정이다.

(3) 'Query_time'

-  쿼리가 실행되는데 걸린 전체 시간을 의미한다.
    많이 혼동되는 부분 중 하나인 'Lock_time'은 사실 위에서 설명한 두 가지 레벨의 잠금 가운데 

    MySQL 엔진 레벨에서 관장하는 테이블 잠금에 대한 대기 시간만 표현한다.

   

-  위 예제의 경우, 이 SELECT 문장을 실행하기 위해 0.002658초간 테이블 락을 기다렸다는 의미가 되는데,
    여기서 한 가지 더 중요한 것은 이 값이 0이 아니라고 해서 무조건 잠금 대기가 있었다고 판단하기는 어렵다는 것이다.
   

-  'Lock_time'에 표기된 시간은 실제 쿼리가 실행되는데 필요한 잠금 체크와 같은 코드 실행 부분의 시간까지 모두 포함된다.
    즉, 이 값이 매우 작은 값이면 무시해도 무방하다.

(4) 'Rows examined'

-   이 쿼리가 처리되기 위해 몇 건의 레코드에 접근했는지를 의미하며,
     'Rows_sent'는 실제 몇 건의 처리 결과를 클라이언트로 보냈는지를 의미한다.
     일반적으로 'Rows_examined'의 레코드 건수는 높지만, 'Rows_sent'에 표시된 레코드 건수가 상당히 적다면

     이 쿼리는 조금 더 적은 레코드만 접근하도록 튜닝해 볼 가치가 있는 것이다.

     (GROUP BY나 COUNT(), MIN(), MAX(), AVG() 등과 같은 집합 함수가 아닌 쿼리인 경우만 해당)

 

 

5) 슬로우 쿼리 로그에서  Lock_time의 의미

- MyISAM이나 MEMORY 스토리지 엔진에서는 테이블 단위의 잠금을 사용하고 

  MVCC와 같은 메커니즘이 없기 때문에 SELECT 쿼리라고 하더라도 Lock_time이 1초 이상 소요될 가능성이 있다.
  하지만 가끔 InnoDB 테이블에 대한 SELECT 쿼리의 경우에도 Lock_time이 상대적으로 큰 값이 발생할 수 있는데,
  이는 InnoDB의 레코드 수준의 잠금이 아닌 MySQL 엔진 레벨에서 설정한 테이블 잠금 때문일 가능성이 높다.
  그래서 InnoDB 테이블에만 접근하는 쿼리 문장의 슬로우 쿼리 로그에서는

  Lock_time 값은 튜닝이나 쿼리 분석에 별로 도움이 되지 않는다.

 

 

6) 튜닝할 쿼리 선별하기 

- 일반적으로 슬로우 쿼리 또는 제너럴 로그 파일의 내용이 상당히 많아서 직접 쿼리를 하나씩 검토하기에는 

  시간이 너무 많이 걸리거나 어느 쿼리를 집중적으로 튜닝해야 할지 식별하기가 어려울 수도 있다.
  이런 경우에는 Percona에서 개발한 Percona Toolkit의 pt-query-digest 스크립트를 이용하면 

  쉽게 빈도나 처리 성능별로 쿼리를 정렬해서 살펴볼 수 있다.  

## General Log 파일 분석
linux> pt-query-digest --type='genlog' general.log > parsed_general.log

## Slow Log 파일 분석
linux> pt-query-digest --type='slowlog' mysql-slow.log > parsed_mysql-slow.log

 

- 로그 파일의 분석이 완료되면 그 결과는 다음과 같이 3개의 그룹으로 나뉘어 저장된다.