오래 도는 쿼리를 찾으려고 트랜잭션 목록을 봤다.
SELECT trx_id, trx_started, trx_query FROM information_schema.INNODB_TRX;trx_started trx_query
2016-11-21 04:12:33 UPDATE device_data ...지금 시각이 13시인데 04시에 시작한 트랜잭션이 보였다. 아홉 시간째 도는 것으로 읽혔고 그런 것이 있으면 이미 큰 문제다.
Table of contents
Open Table of contents
시간대가 달랐다
다른 지표에는 그런 정황이 없어서 숫자 자체를 의심했다. 먼저 시간대 설정을 봤다.
SELECT @@global.time_zone, @@session.time_zone, @@system_time_zone;+09:00 +09:00 UTC전역과 세션은 한국 시각인데 @@system_time_zone 만 협정 세계시였다. 셋이 같을 것이라고 생각한 것이 틀렸다.
INNODB_TRX.trx_started 는 시스템 시간대를 따르고 세션 설정과 무관하다. 그래서 NOW() 와 그냥 빼면 두 기준의 차이인 아홉 시간이 통째로 경과 시간으로 잡힌다.
같은 서버 안에서도 값에 따라 해석이 달랐다. 서버 하나에 시간대가 하나라고 생각한 것이 이번 착오의 뿌리였다.
검증 — 경과 시간으로 보기
한 값만 보면 또 헷갈릴 것이라 두 가지를 같이 뽑게 했다.
SELECT trx_id,
trx_started,
CONVERT_TZ(trx_started, '+00:00', '+09:00') AS started_kst,
TIMESTAMPDIFF(SECOND, trx_started, UTC_TIMESTAMP()) AS elapsed_sec
FROM information_schema.INNODB_TRX;CONVERT_TZ 로 한국 시각을 만들되 TIMESTAMPDIFF 로 경과 초도 함께 계산했다. 어느 쪽에서 세든 경과는 같은 값이 나온다.
started_kst elapsed_sec
2016-11-21 13:12:33 183183초였다. 아홉 시간이 아니라 3분이었던 것이다.
경과로 보면 시간대가 개입할 자리가 없다. 두 시각을 같은 기준으로 맞춰 빼기만 하면 되고 그 기준이 무엇이든 차이는 보존된다.
다른 목록과 대조했다
프로세스 목록에도 경과가 들어 있다.
SELECT ID, TIME, LEFT(INFO, 60) FROM information_schema.PROCESSLIST
WHERE COMMAND != 'Sleep' ORDER BY TIME DESC;PROCESSLIST 의 TIME 이 초 단위 경과이므로 앞의 elapsed_sec 와 비슷하게 나와야 한다.
두 목록이 같은 말을 하면 그것은 사실로 봐도 된다. 한쪽만 보고 판단했다가 이번처럼 어긋나면 멀쩡한 연결을 강제로 끊는 조치까지 갈 수 있었다.
같은 문제가 있는 다른 자리
이 어긋남이 트랜잭션 목록에만 있는 것이 아니었다. 시각을 다루는 자리마다 같은 구조가 있었다.
서버 로그는 시스템 시간대를 따르고 애플리케이션 로그는 그 애플리케이션의 설정을 따른다. 두 로그를 나란히 놓고 같은 사건을 찾으면 아홉 시간 떨어져 보인다.
DATETIME 열에는 시간대 정보가 아예 없다. 넣을 때 무엇을 넣었는지를 사람이 알고 있어야 읽을 수 있다.
외부에서 받는 시각도 마찬가지였다. 상대가 어느 기준으로 주는지를 확인해야 하고 대개는 협정 세계시로 준다.
설정 — 저장은 협정 세계시로
새로 만드는 것에는 규칙을 정했다.
저장 협정 세계시로 저장 (DATETIME)
조회 필요하면 변환해서 보여 줌
표시 화면에서만 한국 시각변환이 한 자리에서만 일어나면 어디서 틀렸는지를 찾을 자리도 하나다. 저장과 조회 양쪽에서 변환하면 두 번 바뀐 값이 나온다.
열에는 주석으로 기준을 적었다.
ALTER TABLE device_data
MODIFY COLUMN collected_at DATETIME NOT NULL
COMMENT 'UTC 기준. 표시 시 +9시간';COMMENT 한 줄이 있으면 다음 사람이 값을 의심하지 않아도 된다. TIMESTAMP 형을 쓰면 자동으로 변환되지만 그 변환이 세션 설정에 달려 있어 또 다른 헷갈림이 생겼다.
그래서 자동 변환에 맡기지 않고 DATETIME 으로 두고 직접 다루기로 했다. 규칙이 눈에 보이는 쪽이 관리하기 나았다.
이미 저장된 것을 확인했다
옛 자료가 어느 기준으로 들어갔는지도 봐야 했다.
SELECT MIN(collected_at), MAX(collected_at) FROM device_data;최대값이 지금보다 아홉 시간 뒤였다. 한국 시각으로 들어가 있다는 뜻이다.
분포로도 확인했다.
SELECT DATE_FORMAT(collected_at, '%H') AS h, COUNT(*)
FROM device_data GROUP BY h ORDER BY h;DATE_FORMAT 으로 시만 잘라 세어 보니 새벽 3시에서 5시에 자료가 몰려 있었다. 실제로는 낮에 몰려야 하는 자료이므로 아홉 시간 밀린 것이 맞았다.
값 하나만 보면 판단이 안 서는데 분포를 보면 드러난다. 사람이 움직이는 시간과 자료가 몰리는 시간이 안 맞으면 기준이 어긋난 것이다.
조치 — 경계 시점으로 나눠 읽기
옛 자료를 변환할지를 정해야 했다. 변환하면 그 시점 이전 통계가 전부 바뀌고 그대로 두면 경계에서 아홉 시간이 겹친다.
경계 시점을 기록해 두고 조회할 때 나누기로 했다.
CASE WHEN collected_at < '2016-11-22 00:00:00'
THEN CONVERT_TZ(collected_at, '+09:00', '+00:00')
ELSE collected_at END경계 앞의 값만 CONVERT_TZ 를 태우고 뒤는 그대로 쓴다. 조회문이 지저분해지는 대신 이미 쌓인 자료를 안 건드린다.
저장된 값을 고치는 것은 한 번 틀리면 확인할 원본이 없어진다. 읽는 쪽에서 맞추면 틀려도 조회문만 고치면 됐다.
확인 목록에 넣었다
시각을 다루는 작업에 볼 것을 적어 뒀다.
1. 이 값이 어느 시간대인가
2. 저장할 때 어느 시간대로 넣는가
3. 다른 기록과 대조할 때 맞춰져 있는가
4. 경과 시간으로 확인할 수 있는가이 중 넷째가 가장 안전했다. 시간대를 모르는 상태에서도 경과는 맞는 값이 나온다.
절대 시각이 꼭 필요한 자리가 아니면 경과로 판단한다. 이번 일도 처음부터 경과를 봤으면 3분짜리를 아홉 시간으로 읽는 일이 없었다.
정리
- 같은 서버 안에서도 값에 따라 시간대 해석이 다르다
@@global과@@session과@@system_time_zone이 서로 다를 수 있다trx_started는 시스템 시간대를 따르므로NOW()와 그냥 빼면 안 된다TIMESTAMPDIFF로 경과를 보면 시간대가 개입하지 않는다PROCESSLIST의TIME과 대조하고 나서 조치한다- 서버 로그와 애플리케이션 로그가 서로 다른 기준일 수 있다
- 저장은 협정 세계시로 통일하고 화면에서만 변환한다
- 열 주석에 기준을 적고
TIMESTAMP의 자동 변환에 맡기지 않는다 - 이미 쌓인 것은 시각 분포로 어느 기준인지 확인한다