배치가 표를 잡고 있었다

수집 서버에서 INSERT 가 간헐적으로 실패했고 남은 오류는 시간 초과였다. 확인해 보니 그때마다 같은 시각에 통계 배치가 함께 돌고 있었다.

Open Table of contents

무엇이 잡고 있는지 봤다
한 번에 너무 많이 바꾸고 있었다
나눠서 처리했다
인덱스와 그 작업의 영향
검증 — 읽기 분리와 감시
정리

무엇이 잡고 있는지 봤다

문제가 나는 시각에 접속해서 확인했다.

SHOW PROCESSLIST;

Id     Time   State                  Info
1042   183    Sending data           UPDATE device_data SET flag=1 WHERE ...
1103    28    Waiting for table lock  INSERT INTO device_data ...
1104    27    Waiting for table lock  INSERT INTO device_data ...

배치의 UPDATE 가 183초째 돌고 INSERT 가 Waiting for table lock 에 걸려 있다. 저장이 실패한 것이 아니라 자기 차례를 못 받은 것이었다.

SELECT * FROM information_schema.INNODB_TRX\G

시작 시각과 잠근 행 수가 나온다. 오류 메시지도 InnoDB 가 잠금을 기다리다 innodb_lock_wait_timeout 에 걸렸다는 쪽이었다.

한 번에 너무 많이 바꾸고 있었다

배치 쿼리를 봤다.

UPDATE device_data
SET processed = 1
WHERE processed = 0 AND reg_date < DATE_SUB(NOW(), INTERVAL 1 HOUR);

processed = 0 인 행이 200만 개였고 한 문장으로 200만 행을 바꾼다. 그동안 그 표에 들어오는 저장이 기다린다.

나눠서 처리했다

UPDATE device_data
SET processed = 1
WHERE processed = 0 AND reg_date < DATE_SUB(NOW(), INTERVAL 1 HOUR)
LIMIT 5000;

LIMIT 5000 으로 나눠서 바꾸고 rowcount 가 0이 될 때까지 반복한다.

while True:
    cur.execute(sql)
    n = cur.rowcount
    conn.commit()
    if n == 0:
        break
    time.sleep(0.1)

각 묶음 사이에 짧게 쉬고 그 틈에 저장이 들어간다. 전체 시간은 조금 늘었지만 다른 요청이 안 막힌다.

인덱스와 그 작업의 영향

5,000행씩 해도 조건 조회가 느리면 소용없다.

EXPLAIN UPDATE device_data SET processed=1
WHERE processed=0 AND reg_date < '2016-09-12 12:00' LIMIT 5000;

type: ALL   rows: 4210000

type 이 ALL 이라 전체를 훑는다.

ALTER TABLE device_data ADD INDEX idx_proc_date (processed, reg_date);

processed 를 앞에 뒀는데 값이 0과 1뿐이라 선택도가 낮지만 0인 행이 전체의 5%라 유효했다.

type: range   key: idx_proc_date   rows: 8420

인덱스 추가 자체가 표를 잠글 것으로 보고 시험 서버에서 시간을 쟀다.

시험 서버(같은 행 수): 4분 12초

문서를 보니 보조 인덱스를 더하는 ALTER TABLE 은 제자리에서 돌고 표를 다시 만들지 않으며 그 사이 읽기와 쓰기를 그대로 받는다고 적혀 있다. 그래도 새벽에 했고 그동안 들어오는 자료를 어떻게 할지 정해 뒀다.

try:
    save_to_db(data)
except OperationalError:
    save_to_file(data)      # 나중에 재처리

표를 새로 만드는 종류의 변경이었으면 이 준비가 없을 때 수집이 통째로 멈췄을 자리다.

검증 — 읽기 분리와 감시

통계 배치는 읽기가 대부분이라 읽기만 하는 것은 다른 서버에서 하게 했다.

STAT_DB = 'db-replica'   # 읽기 전용
MAIN_DB = 'db-master'

읽기 부하가 주 서버에서 빠졌다. 복제본은 Seconds_Behind_Master 에 찍히는 만큼 늦으므로 통계는 몇 초 늦어도 되지만 방금 저장한 것을 바로 읽어야 하는 조회는 주 서버에 남겼다.

같은 문제를 미리 알 수 있게 감시도 넣었다.

SELECT COUNT(*) FROM information_schema.PROCESSLIST
WHERE COMMAND != 'Sleep' AND TIME > 30;

30초 넘게 도는 쿼리 수를 1분마다 기록했다. 평소 0이고 배치 시간에 1~2이며 5를 넘으면 알렸다.

SELECT ID, TIME, LEFT(INFO, 100) FROM information_schema.PROCESSLIST
WHERE COMMAND != 'Sleep' ORDER BY TIME DESC LIMIT 3;

가장 오래 도는 쿼리도 같이 기록하니 알림이 왔을 때 무엇이 원인인지 바로 나온다. 숫자만 오면 그때 다시 조사를 시작해야 한다.

정리

오래 도는 갱신이 같은 표의 다른 요청을 세운다
저장이 실패한 것이 아니라 차례를 못 받은 것이다
무엇이 잡고 있는지는 SHOW PROCESSLIST 에서 본다
한 문장으로 수백만 행을 바꾸지 않고 묶음으로 나누고 사이를 쉰다
나눠도 조건 조회가 느리면 소용없으니 실행 계획과 인덱스를 본다
보조 인덱스 추가는 제자리에서 돌고 그 사이 읽기와 쓰기를 받는다
표를 다시 만드는 변경은 다르므로 어느 쪽인지 먼저 본다
걸리는 시간을 미리 재고 그동안의 유입을 처리할 방법을 둔다
읽기 부하는 복제본으로 빼되 복제본은 조금 늦다
오래 도는 쿼리 수를 감시하고 알림에 무엇이 도는지 같이 낸다