늘모자란, 개발 :: MySQL 시간과 slow query 로그시간이 다를때

늘모자란, 개발

slow query 로그를 모니터링하다가 괴이한걸 발견했다.

 # Time: 2017-06-07T21:02:08.862259Z
# User@Host:  @ localhost []  Id: 369414
# Query_time: 5.894014  Lock_time: 0.000000 Rows_sent: OOOO  Rows_examined: OOOO
use DB;
SET timestamp=1496869328;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `table`;


/*40001 SQL_NO_CACHE*/ 라는것도 처음보고, DB를 풀스캔하고 있는데 시간대를 보니 밤 9시라고 한다. 밤9시엔 이런 작업을 할리가 없는데..  그래서 이래저래 검색을 해보니 40001 은 mysql 버전 4.0.0 이상에서 진행된 쿼리라는거고, 뒤에는 말그대로 캐시없이 돌리겠다는 명령어라고 한다. 그리고 mysqldump에서 이렇게 질의한다고 하는데...

문제는 9시에 mysqldump를 진행하지 않는다. 혹시 해서 select now()를 해도 정상시간으로 되어있고, OS시간도 정상이다.
판타즘넷 DB서버는 새벽6시와 또 다른 특정시간대에 백업을 진행하는데, 친구와 얘기하다보니 로그 시간뒤에 Z가 붙어있는걸 확인했다. 그렇다. 이건 UTC +0 시간이었던것이다...

mysql 5.7.2 부터는 로그시간의 혼동을 피하기위해 따로 변수를 추가해 관리하는것이다. 이걸 확인하려면,

show variables;


를 통해 log_timestamps의 값을 확인하면 되는데 나의 경우

log_timestamps | UTC


로 설정되어 있다.
해당 변수의 값은 SYSTEM 혹은 UTC로만 설정할 수 있으며, 서버시간대로 로그를 확인하고 싶다면 SYSTEM으로 맞춰주면된다.
my.cnf 에 mysqld 밑에 다음과 같이 적어주자

 log_timestamps = SYSTEM


Ref:
https://serverfault.com/questions/759532/mysql-logs-different-time-than-now
https://stackoverflow.com/questions/8282788/what-does-select-n-sql-no-cache-from-mytable-mean-in-in-mysqls-slow

2017/06/08 11:09 2017/06/08 11:09