slow query 슬로우 쿼리 로그 설정 및 확인방법 (mysql, mariadb)

슬로우 쿼리 로그 파일에는 long_query_time 시스템 변수에 설정한 시간 이상의 시간이 소요된 쿼리가 모두 기록된다.
(long_query_time 파라미터는 초단위로 설정하지만 소수점 값으로 설정하면 마이크로 초 단위로 설정 가능함)

 

ex)

만약 2초이상 걸리는 쿼리를 슬로우쿼리로 보고 파일로 쌓는 구조를 만드려면?

 

solution)

my.cnf에서 2군데 추가해주면 된다 

 

vi /etc/my.cnf

 

[mysqld]
slow_query_log_file=/data/mysqldb_logs/slow/mysql-slow-query.log /* 슬로우쿼리가 파일로 들어갈 경로 지정 */
long_query_time=2 /* 몇초 이상의 쿼리를 슬로우 쿼리로 만들지 파라미터 값 지정 */

#슬로우 쿼리 설정여부 확인

mysql> show global variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 2.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

슬로우 쿼리 로그는 Mysql이 쿼리를 실행한 후, 실제 소요된 시간을 기준으로 슬로우 쿼리 로그에 기록할지 여부를 판단하기 때문에 반드시 쿼리가 정상적으로 실행이 완료되야 슬로우 쿼리로그에 기록될 수 있다. 

즉 슬로우 쿼리 록 파일에 기록되는 쿼리는 일단 정상적으로 실행이 완료됐고 실행하는데 걸린 시간이 long_query_time에 정의된 시간보다 많이 걸린 쿼리인 것이다.
(ex 장애나서 급하게 kill session_id; 시킨 쿼리는 슬로우 쿼리 로그에 남지 않는다^^;)

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

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

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

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

 

 

하지만 테이블에 굳이 DB에 슬로우쿼리 로그를 쌓을 이유가 없다

 

일단 테이블에 쌓는다면 로그를 삭제 할 때도 DB부하가 발생하고

삭제도 마음대로 못함!

 

그리고  DB부하 발생시 정상적인 쿼리도

처리가 지연되면서 slow query log에 쌓일 텐데
이럴경우 DB 부하가 x2배가 되는 상황을 볼 것이기 때문

 

괜히 건드리지말고 그냥 default 로 둔다^^

 

#log_output 옵션 확인

mysql> show global variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.00 sec)

#slow query 파일로그  확인 방법

# Time: 2023-04-25T16:49:49.018595+09:00
# User@Host: xxxapp[xxxapp] @  [192.168.141.108]  Id: 9000323
# Query_time: 2.529181  Lock_time: 0.000406 Rows_sent: 22  Rows_examined: 781358
SET timestamp=1682408989;
/* sql_id */   SELECT  *    FROM  (     SELECT xxx_CD

파일에서 보는 것 처럼 

Time, User@Host, Query_time, Lock_time, Rows_sent, Rows_examined, ,slow query  sql 등
총 7가지 정도의 정보를 확인할 수 있다

다른 건 다 건너뛰고 장애시 로그 분석할 때 유용한 것과 튜닝할 때 필요한 것만 확인한다.

 

1. DB부하나 장애 발생했을 때

 

#1) User@Host

 

부하를 발생시킨 어플리케이션 서버이다.
일단 평소보다 호출이 많았는지 서버 로그에서 확인하고
DDos등 공격이 아니라면

xxxapp 계정으로 192.168.141.108 서버 -> DB로 들어온 query 처리가 지연되어서
슬로우쿼리가 되었고 실행계획을 확인해서 튜닝할지를 결정한다.

 

#2) Time

 

여기서 가장 중요한 것은 Time은 query가 끝난 시각이다.
(slow query는 쿼리실행이 종료되어야만 로그에 남는다.
중간에 kill 하거나 수행실패한 경우는 general log를 on 하지 않는 이상 남지 않는다)

 

이 말은 부하 시점은  2023-04-25T16:49:49 에서 Query_time: 2.529181(초) 을 뺀 시각이
처음 쿼리 수행일 시작한 시각이 되고 
부하를 일으킨 app 서버에서 DB로 쿼리수행요청을 한 시각이 된다.

그렇다면 위 query가 시작한 시각은  2023-04-25 / 16:49:46초 이다.

 

2. 슬로우쿼리 튜닝 때

 

#3) Query_time

 

#1) 로그 분석방법
장애 때는 context switching이 발생하여 쿼리 수행이 지연되기 때문에
정상적인 쿼리도 전부 slow query로 전부 슬로우 쿼리로 찍히는 경우가 많다.

이럴 경우 정상적일 때 slow query 로그와 비교해서
장애 때만 특별히 길게 수행된 쿼리를 찾아낸다.

 

 

#2) 실제 확인할 값
Query_time: 2.529181 말고는 나머지는 딱히 도움될 만한 게 없다.
explain을 확인후 실제 쿼리를 돌려보고 정말
Query_time 만큼의 시간이 걸린다면 튜닝을 하면 된다.

 

 

 

 

#참조 : real mysql 8.0