MySQL slow log 원인 찾기 / "commit; set timestamp" analysis using performance_schema table
MySQL slow query 를 보다보면 이해가 가지 않는 경우가 있다.
# Time: 2020-07-02T15:44:14.145642Z
# User@Host: mydatabase[mydatabase] @ [10.1.1.5] Id: 32026
# Query_time: 0.200300 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mydatabase;
SET timestamp=1575301453;
commit;select * from information_schema.innodb_trx;
실행 해보면 위와 비슷한 결과가 나오는데, application server 로부터 DB 에 connection 을 맺고 현재 진행중인 transaction 을 볼 수 있다. 왠만한 쿼리가 아닌 이상 매우 짧은 시간안에 끝나기 때문에 수행 할 때마다 결과 값이 바뀐다.
하지만 더 재미있는 테이블은 performance_shcema DB에 있다. MySQL 8.0부터 제공했던것 같다.
https://dev.mysql.com/doc/refman/8.0/en/performance-schema.html
여러가지 테이블이있지만 그중 가장 관심이 있는 테이블은 events_statements_history 와 threads 테이블이다. 이제 위 테이블의 trx_mysql_thread_id 컬럼의 값을 이용해서 performance_schema 를 조회해볼 수 있다. 그럼 저 trx_mysql_thread_id 에서 어떤 일들이 일어났는지를 알 수 있다.
select SQL_TEXT FROM performance_schema.events_statements_history ESH,
performance_schema.threads T
WHERE ESH.THREAD_ID = T.THREAD_ID AND ESH.SQL_TEXT IS NOT NULL AND T.PROCESSLIST_ID = 32172 ORDER BY ESH.EVENT_ID ;
추가로, 아래는 구글링을 하다가 찾은건데 events_statements_history 컬럼의 timer_wait 컬럼을 기준으로 정렬하여 slow query 로 의심되는 SQL Text 를 뽑을 수 있다. 아래는 15개의 time-consuming SQL 쿼리를 뽑은 결과이다.
select EVENT_ID, THREAD_ID, NESTING_EVENT_ID,SEC_TO_TIME(TIMER_WAIT/1000000000000) as wait_time, SQL_TEXT
from performance_schema.events_statements_history where NESTING_EVENT_ID in (
select t.NESTING_EVENT_ID from (select NESTING_EVENT_ID, sum(TIMER_WAIT) as summ
from performance_schema.events_statements_history group by NESTING_EVENT_ID order by sum(TIMER_WAIT) desc limit 15) as t)
order by NESTING_EVENT_ID, EVENT_ID asc;
NESTING_EVENT_ID 는 EVENT_ID 의 부모 ID 로 보인다. THREAD_ID 는 application 에서 맺은 connection 일테고. 이제 commit; 이 호출 되기 이전에 어떤 일들이 벌어졌는지늘 알 수있다. 실제 결과적으로 보면 0.1초, 0.2초 등 commit; 에서 가장 오래 걸렸기 때문에 slow query 에 commit; 이 찍힌것이 아닌가 싶다.
Comments
Post a Comment