log_slow_extra

MySQL에서 슬로우 쿼리를 모니터링 하다 보면 해당 쿼리가 임시 테이블이나, 소팅, 스캔 등을 어떻게 했는지 확인이 필요할떄가 있다. 

Ex) DB 서버에서 sorting 작업이 많이 발생하는게 모니터링 되었는데 어떤 쿼리에서 발생하는지 알고 싶을때 

Performance_schema를 통해서도 어느정도 가능하지만 Performance_schema의 경우 DB 시작 부터 현재까지 쌓이는 값이기 떄문에 특정 시점에 많이 발생한 쿼리를 발견하기는 쉽지 않다.

 

 Log_slow_extra? 

• 기본적인 슬로우 쿼리 정보 ( Duration / Lock time / Rows sent 등 ) 이외에 해당 쿼리에 대한 상태 정보들을 확인할수 있게 해준다. ( 임시 테이블 생성 / 정렬 작업 / 풀스캔 작업 등.. ) 
• Default는 OFF이며 다이나믹하게 활성화가 가능하다.
• 이걸 어떻게 활용하나?
• AS-IS: Performance_schema의 history 테이블들에 의존하여 쿼리들을 식별해낼 수 밖에 없었다. 하지만 해당 정보들은 축적되는 값들을 보여주기 떄문에 부정확한 부분들이 존재 할 수 있다.
• TO-BE : 성능 테스트시 Grafana를 통해 볼 수 있는 Sorting / Tmp / TABLE SCAN이 발생하는 쿼리를 확인 할 수 잇다.

 

ASIS

• 슬로우 쿼리에대한 기본적인 정보만 보여준다.

# Time: 2025-01-24T16:53:43.775549+09:00
# User@Host: lee[lee] @ localhost [] Id: 111598
# Query_time: 1.813863 Lock_time: 0.000015 Rows_sent: 0 Rows_examined: 0
use test;
SET timestamp=1737705221;
select * From history;

# Time: 2025-01-24T16:53:51.565336+09:00
# User@Host: lee[lee] @ localhost [] Id: 111598
# Query_time: 1.886473 Lock_time: 0.000013 Rows_sent: 0 Rows_examined: 0
SET timestamp=1737705229;
select * From history_log;

 

TOBE

• 아래 내용을 보면 해당 슬로우 쿼리에 대한 Status들을 볼 수있다.
• Ex) 2번째 쿼리는 Read_rnd_next 값이 올라간것으로 보아 FULLSCAN하는 쿼리일 확률이 높다

# Time: 2025-01-31T11:33:29.014491+09:00
# User@Host: lee[lee] @ [127.0.0.1] Id: 131187
# Query_time: 0.030395 Lock_time: 0.000004 Rows_sent: 35 Rows_examined: 6092 Thread_id: 131187 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 2400 Read_first: 2 Read_last: 0 Read_key: 627 Read_next: 5915 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2025-01-31T11:33:28.984096+09:00 End: 2025-01-31T11:33:29.014491+09:00
SET timestamp=1738290808;
select * from test.sysbench1 where id > 100;

# Time: 2025-01-31T11:33:29.070748+09:00
# User@Host: lee[lee] @ [127.0.0.1] Id: 131187
# Query_time: 0.028397 Lock_time: 0.000001 Rows_sent: 367 Rows_examined: 367 Thread_id: 131187 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 18888 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 368 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2025-01-31T11:33:29.042351+09:00 End: 2025-01-31T11:33:29.070748+09:00

SET timestamp=1738290809;
select * from test.sysbench3 where id > 100;

 

 

pt-query-digest로 슬로우 쿼리 분석 확인

- 해당 파라미터를 ON으로 켜두어도 pt-query-digest 를 사용하는데 특이사항이 없다.

- 툴사용에 문제가 없으며 더 자세한 내용들이 출려된다. ( Read ~~등 )

# Query 1: 0.03 QPS, 0.00x concurrency, ID 0xE6B83E9DFFF633F892D094A82BA1330A at byte 9393551
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2025-02-01T00:00:29 to 2025-02-02T23:59:29
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 49 5759
# Exec time 53 187s 30ms 74ms 33ms 36ms 3ms 31ms
# Lock time 83 39ms 3us 102us 6us 8us 2us 6us
# Rows sent 8 196.84k 35 35 35 35 0 35
# Rows examine 94 33.46M 5.95k 5.95k 5.95k 5.95k 0 5.95k
# Bytes sent 11 13.18M 2.34k 2.34k 2.34k 2.34k 0 2.34k
# Query size 80 2.65M 483 483 483 483 0 483
# Bytes receiv 0 0 0 0 0 0 0 0
# Created tmp 0 0 0 0 0 0 0 0
# Created tmp 0 0 0 0 0 0 0 0
# Errno 0 0 0 0 0 0 0 0
# Read first 100 11.25k 2 2 2 2 0 2
# Read key 100 3.44M 627 627 627 627 0 627
# Read last 0 0 0 0 0 0 0 0
# Read next 100 32.49M 5.78k 5.78k 5.78k 5.78k 0 5.78k
# Read prev 0 0 0 0 0 0 0 0
# Read rnd 0 0 0 0 0 0 0 0
# Read rnd nex 0 0 0 0 0 0 0 0
# Sort merge p 0 0 0 0 0 0 0 0
# Sort range c 0 0 0 0 0 0 0 0
# Sort rows 0 0 0 0 0 0 0 0
# Sort scan co 0 0 0 0 0 0 0 0
# String:
# End 2025-02-01... (1/0%), 2025-02-01... (1/0%)... 5757 more
# Hosts 127.0.0.1
# Start 2025-02-01... (1/0%), 2025-02-01... (1/0%)... 5757 more
# Users db_heimdall_user
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'sysbench1'\G
# SHOW CREATE TABLE `test`.`sysbench1`\G

# EXPLAIN /*!50100 PARTITIONS*/

select * from test.sysbench1 where id >100 ;

 

 

활용처

- AWS의 경우 Cloud Watch를 통해 Slowquery를 모니터링하고 특정 sorting, tmp 사용, full scan이 발생할때 알람을 받도록 스크립팅을 할 수 있을것 같다.

- 로그 모니터링 툴 (ELK, Graylog)등을 통해 슬로우를 모니터링하고 특정 sorting, tmp 사용, full scan이 발생할때 알람을 받도록 스크립팅을 할 수 있을것 같다.

- 성능 테스트간 더 자세하게 쿼리의 상태를 확인 할 수 있다고 생각된다.