슬로우쿼리
Slow Query(슬로우쿼리)
Slow Query(슬로우쿼리)는 지정한 시간보도 실행하는데 오래걸리는 쿼리에 대한 log를 것입니다
특정 작업이 오래 걸린다면 로그를 통해 원인을 파악할 수 있겠습니다.
또한 대량이 데이터를 조회하거나 잘못된 인덱스 사용으로 인한 장시간 MySQL 프로세스가 물리는 현상이 발생 할 경우 어떤 쿼리문에 이런 현상을 발생 하였느냐에 대해서 분석시 Slow Query를 사용하면 부하가 증가되는 쿼리를 찾을 수 있을꺼라고 생각됩니다.
출처 : https://itstudyblog.tistory.com/384
slow query 란 ? DBMS 가 client로부터 요청받은 query를 수행할때 일정시간 이상 수행되지 못한 query
즉 길어야 1~2초 걸리는 db 쿼리가 예상보다 오래걸리는 경우를 뜻함.
출처 : https://shutcoding.tistory.com/6
오라클(Oracle)
오라클의 경우 슬로우 쿼리를 로그로 관리하고 있지는 않은 것으로 보입니다.
오라클 오래걸리는 쿼리 LONG 쿼리 찾기(Oracle Database 11.2.0.4)
- EX) 실행시간 5초 이상 걸린 쿼리 조회
SELECT * FROM(
SELECT ROUND(NVL((ELAPSED_TIME / DECODE(EXECUTIONS, 0, NULL, EXECUTIONS)/1000000 ), 0),3) AS ELAPSED_TIME
, LAST_ACTIVE_TIME
, HASH_VALUE
, SQL_TEXT
FROM V$SQL
WHERE parsing_schema_name = 'SYS'
AND LAST_ACTIVE_TIME >= TO_DATE('20180307', 'YYYYMMDD')
)
WHERE ELAPSED_TIME > 5
order by ELAPSED_TIME desc;WHERE 절에 ELAPSED_TIME 의 값을 초단위로 설정하여 몇초 이상 걸린 쿼리에 대한 값을 지정하여 오래 걸린 쿼리를 측정 할 수 있다
쿼리 실행 결과
참고: https://positivemh.tistory.com/346
MS-SQL
SELECT TOP 100
[Object_Name] = object_name(st.objectid),
creation_time,
last_execution_time,
total_cpu_time = total_worker_time / 1000,
avg_cpu_time = (total_worker_time / execution_count) / 1000,
min_cpu_time = min_worker_time / 1000,
max_cpu_time = max_worker_time / 1000,
last_cpu_time = last_worker_time / 1000,
total_time_elapsed = total_elapsed_time / 1000 ,
avg_time_elapsed = (total_elapsed_time / execution_count) / 1000,
min_time_elapsed = min_elapsed_time / 1000,
max_time_elapsed = max_elapsed_time / 1000,
avg_physical_reads = total_physical_reads / execution_count,
avg_logical_reads = total_logical_reads / execution_count,
execution_count,
SUBSTRING(st.text, (qs.statement_start_offset/2) + 1,
(
(
CASE statement_end_offset
WHEN -1 THEN DATALENGTH(st.text)
ELSE qs.statement_end_offset
END
- qs.statement_start_offset
) /2
) + 1
) as statement_text
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) st
WHERE Object_Name(st.objectid) IS NOT NULL
AND st.dbid = DB_ID()
ORDER BY db_name(st.dbid), total_worker_time / execution_count DESC출처: https://m.blog.naver.com/PostView.naver?isHttpsRedirect=true&blogId=iyagi15&logNo=10141721794 [MSSQL - 작업 모니터의 느린 쿼리 TOP 100 추출하는 쿼리]
MS-SQL 2005버전 이상 슬로우쿼리 조회 쿼리
SELECT TOP 20 SUBSTRING(qt.text, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(qt.text)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2)+1),
qs.execution_count,
qs.total_logical_reads, qs.last_logical_reads,
qs.min_logical_reads, qs.max_logical_reads,
qs.total_elapsed_time, qs.last_elapsed_time,
qs.min_elapsed_time, qs.max_elapsed_time,
qs.last_execution_time,
qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
WHERE qt.encrypted=0
ORDER BY qs.total_logical_reads DESC또는
/*Debug query */
SELECT TOP 100
qt.text as QUERY,
qs.execution_count,
qs.total_logical_reads, qs.last_logical_reads,
qs.min_logical_reads, qs.max_logical_reads,
qs.total_elapsed_time, qs.last_elapsed_time,
qs.min_elapsed_time, qs.max_elapsed_time,
qs.last_execution_time,
qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
WHERE qt.encrypted=0
and qt.text not like ‘/*Debug query */%’
ORDER BY qs.last_execution_time DESC, qs.total_logical_reads DESC출처: http://www.flogiston.net/blog/2010/03/01/ms-sql-server-log-slow-queries/
[MSSQL] 서버에서 지연되는(처리시간이 오래 걸리는) 쿼리(Query)찾기
MS-SQL에서 어떤 쿼리를 처리할 때 처리시간이 너무 오래 걸리는 경우가 있습니다. 이는 서버 전체의 처리시간을 늘려 장애를 발생시키는 요인이 될 수 있는데 이런 경우 아래 쿼리를 SSMS에서 날려 처리시간이 오래 걸리는 쿼리를 찾아낼 수 있습니다.
Select Distinct dm_ws.wait_duration_ms, dm_t.[TEXT], dm_ws.session_ID
From sys.dm_os_waiting_tasks As dm_ws Inner Join sys.dm_exec_requests As dm_r
On dm_ws.session_id = dm_r.session_id Inner Join sys.dm_exec_sessions As dm_es
On dm_es.session_id = dm_r.session_id Cross Apply sys.dm_exec_sql_text (dm_r.sql_handle) As dm_t Cross Apply sys.dm_exec_query_plan (dm_r.plan_handle) As dm_qp
Where dm_es.is_user_process = 1 And DB_NAME(dm_r.database_id) = '[대상DB]'
Order By dm_ws.wait_duration_ms Desc;대부분의 경우 select 구문에서 시간이 지연되는 경우가 많으므로 다음처럼 조건을 걸어 찾을 수도 있을 것입니다.
Select Distinct dm_ws.wait_duration_ms, dm_t.[TEXT], dm_ws.session_ID
From sys.dm_os_waiting_tasks As dm_ws Inner Join sys.dm_exec_requests As dm_r
On dm_ws.session_id = dm_r.session_id Inner Join sys.dm_exec_sessions As dm_es
On dm_es.session_id = dm_r.session_id Cross Apply sys.dm_exec_sql_text (dm_r.sql_handle) As dm_t Cross Apply sys.dm_exec_query_plan (dm_r.plan_handle) As dm_qp
Where dm_es.is_user_process = 1 And DB_NAME(dm_r.database_id) = '[대상DB]'
And dm_t.[TEXT] Like '%Select%'
Order By dm_ws.wait_duration_ms Desc;출처: https://lab.cliel.com/entry/MSSQL-서버에서-지연되는처리시간이-오래-걸리는-쿼리Query찾기
가장 긴 평균 실행 시간
지난 1시간 내에 평균 실행 시간이 가장 긴 쿼리 수:
SELECT TOP 10 rs.avg_duration, qt.query_sql_text, q.query_id,
qt.query_text_id, p.plan_id, GETUTCDATE() AS CurrentUTCTime,
rs.last_execution_time
FROM sys.query_store_query_text AS qt
JOIN sys.query_store_query AS q
ON qt.query_text_id = q.query_text_id
JOIN sys.query_store_plan AS p
ON q.query_id = p.query_id
JOIN sys.query_store_runtime_stats AS rs
ON p.plan_id = rs.plan_id
WHERE rs.last_execution_time > DATEADD(hour, -1, GETUTCDATE())
ORDER BY rs.avg_duration DESC;가장 긴 대기 기간
SELECT TOP 10
qt.query_text_id,
q.query_id,
p.plan_id,
sum(total_query_wait_time_ms) AS sum_total_wait_ms
FROM sys.query_store_wait_stats ws
JOIN sys.query_store_plan p ON ws.plan_id = p.plan_id
JOIN sys.query_store_query q ON p.query_id = q.query_id
JOIN sys.query_store_query_text qt ON q.query_text_id = qt.query_text_id
GROUP BY qt.query_text_id, q.query_id, p.plan_id
ORDER BY sum_total_wait_ms DESC;최근에 성능이 저하된 쿼리
다음 쿼리 예제는 지난 48 시간에 계획 선택 변경으로 인해 실행 시간이 두 배가 된 모든 쿼리를 반환합니다. 이 쿼리는 모든 런타임 통계 간격을 나란히 비교합니다.
SELECT
qt.query_sql_text,
q.query_id,
qt.query_text_id,
rs1.runtime_stats_id AS runtime_stats_id_1,
rsi1.start_time AS interval_1,
p1.plan_id AS plan_1,
rs1.avg_duration AS avg_duration_1,
rs2.avg_duration AS avg_duration_2,
p2.plan_id AS plan_2,
rsi2.start_time AS interval_2,
rs2.runtime_stats_id AS runtime_stats_id_2
FROM sys.query_store_query_text AS qt
JOIN sys.query_store_query AS q
ON qt.query_text_id = q.query_text_id
JOIN sys.query_store_plan AS p1
ON q.query_id = p1.query_id
JOIN sys.query_store_runtime_stats AS rs1
ON p1.plan_id = rs1.plan_id
JOIN sys.query_store_runtime_stats_interval AS rsi1
ON rsi1.runtime_stats_interval_id = rs1.runtime_stats_interval_id
JOIN sys.query_store_plan AS p2
ON q.query_id = p2.query_id
JOIN sys.query_store_runtime_stats AS rs2
ON p2.plan_id = rs2.plan_id
JOIN sys.query_store_runtime_stats_interval AS rsi2
ON rsi2.runtime_stats_interval_id = rs2.runtime_stats_interval_id
WHERE rsi1.start_time > DATEADD(hour, -48, GETUTCDATE())
AND rsi2.start_time > rsi1.start_time
AND p1.plan_id <> p2.plan_id
AND rs2.avg_duration > 2*rs1.avg_duration
ORDER BY q.query_id, rsi1.start_time, rsi2.start_time;성능 저하 기록이 있는 쿼리
최근 실행을 기록 실행과 비교하는 다음 쿼리에서는 실행 기간을 기준으로 쿼리 실행을 비교합니다. 이 특정 예제의 쿼리는 최근 기간(1시간) 및 기록 기간(어제)의 실행을 비교하고 additional_duration_workload를 초래한 쿼리를 식별합니다. 이 메트릭은 최근 평균 실행 기간과 기록 평균 실행 간의 차이에 최근 실행 수를 곱한 값으로 계산됩니다. 이 값은 실제로 기록에 비해 최근 실행으로 초래된 추가 기간을 나타냅니다.
--- "Recent" workload - last 1 hour
DECLARE @recent_start_time datetimeoffset;
DECLARE @recent_end_time datetimeoffset;
SET @recent_start_time = DATEADD(hour, -1, SYSUTCDATETIME());
SET @recent_end_time = SYSUTCDATETIME();
--- "History" workload
DECLARE @history_start_time datetimeoffset;
DECLARE @history_end_time datetimeoffset;
SET @history_start_time = DATEADD(hour, -24, SYSUTCDATETIME());
SET @history_end_time = SYSUTCDATETIME();
WITH
hist AS
(
SELECT
p.query_id query_id,
ROUND(ROUND(CONVERT(FLOAT, SUM(rs.avg_duration * rs.count_executions)) * 0.001, 2), 2) AS total_duration,
SUM(rs.count_executions) AS count_executions,
COUNT(distinct p.plan_id) AS num_plans
FROM sys.query_store_runtime_stats AS rs
JOIN sys.query_store_plan AS p ON p.plan_id = rs.plan_id
WHERE (rs.first_execution_time >= @history_start_time
AND rs.last_execution_time < @history_end_time)
OR (rs.first_execution_time <= @history_start_time
AND rs.last_execution_time > @history_start_time)
OR (rs.first_execution_time <= @history_end_time
AND rs.last_execution_time > @history_end_time)
GROUP BY p.query_id
),
recent AS
(
SELECT
p.query_id query_id,
ROUND(ROUND(CONVERT(FLOAT, SUM(rs.avg_duration * rs.count_executions)) * 0.001, 2), 2) AS total_duration,
SUM(rs.count_executions) AS count_executions,
COUNT(distinct p.plan_id) AS num_plans
FROM sys.query_store_runtime_stats AS rs
JOIN sys.query_store_plan AS p ON p.plan_id = rs.plan_id
WHERE (rs.first_execution_time >= @recent_start_time
AND rs.last_execution_time < @recent_end_time)
OR (rs.first_execution_time <= @recent_start_time
AND rs.last_execution_time > @recent_start_time)
OR (rs.first_execution_time <= @recent_end_time
AND rs.last_execution_time > @recent_end_time)
GROUP BY p.query_id
)
SELECT
results.query_id AS query_id,
results.query_text AS query_text,
results.additional_duration_workload AS additional_duration_workload,
results.total_duration_recent AS total_duration_recent,
results.total_duration_hist AS total_duration_hist,
ISNULL(results.count_executions_recent, 0) AS count_executions_recent,
ISNULL(results.count_executions_hist, 0) AS count_executions_hist
FROM
(
SELECT
hist.query_id AS query_id,
qt.query_sql_text AS query_text,
ROUND(CONVERT(float, recent.total_duration/
recent.count_executions-hist.total_duration/hist.count_executions)
*(recent.count_executions), 2) AS additional_duration_workload,
ROUND(recent.total_duration, 2) AS total_duration_recent,
ROUND(hist.total_duration, 2) AS total_duration_hist,
recent.count_executions AS count_executions_recent,
hist.count_executions AS count_executions_hist
FROM hist
JOIN recent
ON hist.query_id = recent.query_id
JOIN sys.query_store_query AS q
ON q.query_id = hist.query_id
JOIN sys.query_store_query_text AS qt
ON q.query_text_id = qt.query_text_id
) AS results
WHERE additional_duration_workload > 0
ORDER BY additional_duration_workload DESC
OPTION (MERGE JOIN);MYSQL
슬로우 쿼리 로그는 설정에서 정의된 시간보다(second) 오랫동안 실행 된 쿼리에 대해서 기록을 한다
슬로우 쿼리 로그 활성화(설정 파일)
슬로우 쿼리 로그를 활성화하기 위해서는 MySQL Configuration 파일을 찾아야 한다. 아래 명령어를 수행하면 my.cnf 파일을 찾을 수 있다. 아래 디렉터리 중 한 곳에 my.cnf가 있을 것이다. 여러 디렉토리에 동시에 my.cnf 파일이 존재하면 왼쪽 디렉토리 순서대로 우선 적용된다.
$ mysql --verbose --help | grep my.cnf
/etc/my.cnf /etc/mysql/my.cnf /usr/local/etc/my.cnf ~/.my.cnf파일을 찾았다면 아래처럼 수정한다.
[mysqld]
# 슬로우 쿼리를 TABLE로 출력한다. FILE로도 설정할 수 있다
# FILE로 설정했다면 slow_query_log_file로 출력할 파일 위치를 설정할 수 있다
log_output = TABLE
# 슬로우 쿼리 활성화
slow_query_log = 1
# 아래 변수에 지정된 초(seconds)이상 쿼리가 수행되면 슬로우 쿼리에 기록된다
# 여기서는 테스트를 위해 0.05초로 지정했다
long_query_time = 0.05
# log_ouput을 TABLE로 설정했다면 slow_query_log_file 변수는 주석 처리하자
# MySQL 버그인지 필자의 개발환경 문제인지 모르겠지만, log_output을 TABLE로 설정했을 때
# 해당 변수가 설정되어 있으면 슬로우 쿼리가 활성화되지 않는 문제가 발생했다
# slow_query_log_file=...
# ...파일을 수정했다면 MySQL 서버를 재시작한다. 만약 MySQL 서버를 재시작하지 않고 슬로우 쿼리를 활성화하고 싶다면 MySQL 서버에서 아래 명령어를 실행하면 된다. 다만 MySQL 서버가 재시작했을 때 원상 복구된다.
SET GLOBAL log_output = 'TABLE';
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 0.05;아래 명령어를 MySQL 서버에서 실행하면 슬로우 쿼리가 설정되었는지 확인할 수 있다.
SHOW VARIABLES WHERE
Variable_Name LIKE 'slow_query_log' OR
Variable_Name LIKE 'long_query_time' OR
Variable_Name LIKE 'log_output';아래는 필자가 MySQL Workbench에서 위 명령어를 수행했을 때 출력된 결과이다.
2. 슬로우 쿼리 로그 조회
슬로우 쿼리를 활성화 했으니 잘 동작하는지 확인해보자. 필자는 테스트를 위해 아래 깃허브의 덤프를 사용했다. https://github.com/datacharmer/test_db/blob/master/employees.sql
덤프를 모두 로드했으면 아래 쿼리를 실행해 보자. 컴퓨터 성능에 따라 다르겠지만 InnoDB 에서 전체 테이블 레코드의 개수를 세는 것은 보통 인덱스 풀 스캔을 해야 하기 때문에 0.05초 이상 걸릴 것이다. 필자의 컴퓨터에서는 0.054 초가 걸렸다. 여러 번 같은 쿼리를 수행하면 쿼리 캐시 때문에 결과가 금방 나올 수도 있다. 그럴 때는 long_query_time 을 조절해서 테스트하면 된다.
SELECT COUNT(*) FROM employees; # 0.054 secSQL 사용
mysql DB의 slow_log 테이블을 조회하면 슬로우 쿼리를 확인할 수 있다. sql_text 컬럼이 blob이기 때문에 sql_text 컬럼을 CONVERT 해서 실제 쿼리를 확인하자. 2번째 쿼리는 주요한 내용만 뽑은 쿼리이다.
SELECT * FROM mysql.slow_log;
# 또는
SELECT start_time, user_host, query_time, lock_time, rows_sent, rows_examined, db, CONVERT(sql_text USING utf8 ) sql_text
FROM mysql.slow_log;필자는 2번째 쿼리를 실행했을 때 아래와 같은 결과를 얻을 수 있었다.
각 컬럼의 의미는 대략 아래와 같다. 공식 설명은 아래 페이지에서 찾을 수 있지만, 자세하게 나와 있지는 않다.
https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html#slow-query-log-contents
- start_time: 쿼리가 시작된 시간
- user_host: 쿼리를 실행한 사용자
- query_time: 쿼리가 실행되는 데 걸린 시간(초)
- lock_time: 테이블 잠금에 대한 대기 시간(초)
- rows_sent: 실제 클라이언트에 전달된 레코드의 수
- rows_examined: 쿼리가 처리되기 위해 실제 접근한 레코드의 수
- db: 쿼리가 수행된 데이터베이스
- sql_text: 실제 수행된 쿼리
출처: https://velog.io/@breadkingdom/MySQL-성능-개선을-위한-프로파일링-1
PostgreSQL
1. postgresql.conf 파일 설정
log_min_duration_statement = 1000
X- 밀리세컨드 단위로 설정
- 설정값보다 오래 걸리는 쿼리를 로그 파일에 기록 (default - $PGDATA/pg_log)
- 0으로 설정하면 모든 로그 기록
- 수정 후 reload 하여 적용 (restart 필요 없음)
2. Query를 통하여 검출 (간단함)
SELECT current_timestamp - query_start AS runtime, datname, usename, query
FROM pg_stat_activity
WHERE state = 'active' AND current_timestamp - query_start > '1 sec'`
ORDER BY 1 DESC;출처 : https://brufen97.tistory.com/5
postgreSQL에서도 오라클의 ASH처럼 active session에 대한 활동 기록을 하고 있습니다.
pg_stat_activity 가 프로세스의 현재 활동 중인 트랜잭션에 대한 정보를 확인 할 수 있습니다.
https://www.postgresql.org/docs/current/monitoring-stats.html#PG-STAT-ACTIVITY-VIEW
위의 쿼리에서 WHERE절 조건으로 들어가 있는 current_timestamp - query_start > '1 sec'는 현재 활성화 된 쿼리가 시작된 시간이니 현재시간 - 느린쿼리가 활성화가 시작된 시간 = 쿼리가 걸린 시간이 추출되어 ‘[숫자][단위]’로 느린 쿼리를 추출하여 해당 쿼리에 대한 정보를 추출
로그 지원 RDBMS
Oracle - 미지원으로 보임
Mysql - 지원
MS-SQL - 미지원
PostgreSQL - 지원
'RDBMS' 카테고리의 다른 글
| MySQL에서 특정 문자로 문자열 SPLIT 하기 - SUBSTRING_INDEX (2) | 2022.04.19 |
|---|---|
| [MySQL] 컬럼 추가, 컬럼 삭제, 컬럼명 변경, 컬럼 타입 변경 (2) | 2022.03.03 |
| [오라클 ORACLE] ASH란? (0) | 2022.01.11 |
