재기동하니 세던 값이 사라졌다

발송 건수를 하루 한도까지만 보내게 만들었다. 세는 값을 클래스 변수에 뒀다. 배포하고 나니 그날 발송이 한도의 두 배로 나갔다.

Open Table of contents

값이 초기화됐다
세는 자리를 옮겼다
세고 나서 쓰는 사이를 봤다
사라져도 되는 값과 안 되는 값
정리

값이 초기화됐다

세는 코드는 이랬다.

public class SmsSender {
    private static int todayCount = 0;

    public boolean send(String to, String msg) {
        if (todayCount >= DAILY_LIMIT) return false;
        ...
        todayCount++;
        return true;
    }
}

이 값은 메모리에 있다. 서버를 다시 띄우면 0이 된다. 배포로 재기동했더니 그날 이미 보낸 것을 잊고 처음부터 셌다.

메모리에만 있는 값은 프로세스가 끝나면 없어진다. 한도를 세는 값이 거기 있으면 재기동이 곧 한도 초기화다.

세는 자리를 옮겼다

발송 기록이 이미 MySQL 에 있었다. 그걸 세면 된다.

public int getTodayCount() {
    String sql = "SELECT COUNT(*) FROM sms_log WHERE DATE(send_date) = CURDATE() AND result = 'OK'";
    return jdbcTemplate.queryForInt(sql);
}

기록이 원본이니 재기동해도 값이 유지된다.

그런데 EXPLAIN 을 걸어 보니 인덱스를 안 탔다. send_date 에 인덱스가 있는데도 type 이 ALL 이었다. DATE(send_date) 처럼 컬럼을 함수로 감싸면 MySQL 이 인덱스를 못 쓴다.

범위로 바꾸니 range 가 됐다.

WHERE send_date >= CURDATE()
  AND send_date <  CURDATE() + INTERVAL 1 DAY
  AND result = 'OK'

날짜가 넘어가는 것도 자동으로 처리됐다. 오늘 날짜로 세니 자정이 지나면 값이 저절로 0부터다. 전에는 자정에 값을 되돌리는 작업이 따로 있어야 했고 그 작업이 죽으면 다음 날 발송이 막혔다.

세고 나서 쓰는 사이를 봤다

세고 나서 보내는 사이에 다른 요청이 들어오면 한도를 넘는다. 발송 전에 기록을 먼저 넣는 방식으로 바꿨다.

int logNo = insertLog(to, msg, "SENDING");   // 먼저 기록
if (getTodayCount() > DAILY_LIMIT) {         // 방금 것 포함해 확인
    updateLog(logNo, "LIMIT");
    return false;
}
boolean ok = smsClient.send(to, msg);
updateLog(logNo, ok ? "OK" : "FAIL");

기록이 먼저 들어가니 동시에 들어와도 둘 다 세어진다. 한도를 넘은 쪽이 걸린다.

그래도 두 세션으로 동시에 눌러 보니 둘 다 통과할 때가 있었다. 찾아보니 InnoDB 의 기본 격리 수준 때문이었다. REPEATABLE READ 에서는 그냥 SELECT 가 트랜잭션 시작 시점의 사진을 본다. 그 사이 다른 쪽이 커밋한 INSERT 는 안 보인다.

SELECT ... FOR UPDATE 는 사진이 아니라 지금 것을 본다. 세는 쪽을 그걸로 바꾸니 둘 다 통과하는 일이 없어졌다.

사라져도 되는 값과 안 되는 값

static 으로 선언된 값을 grep 으로 전부 찾았다. 일곱 개였고 그중 셋이 문제였다.

발송 건수와 마지막 처리 시각과 재시도 횟수는 사라지면 안 된다. 재기동하면 한도를 다시 채우고 처음부터 다시 처리하고 무한히 재시도한다. 접속자 수와 캐시 적중 횟수와 오류 누적은 통계라 다시 계산되고, 초기화 여부는 프로세스 단위 값이라 사라지는 것이 맞다.

가르는 기준은 하나였다. 재기동 뒤에 이 값이 0이면 무슨 일이 일어나는지 물어보면 갈린다.

고친 뒤 실제로 Tomcat 을 다시 띄워 확인했다. 재기동 전과 후의 건수가 같았다. 한도까지 채운 상태에서 재기동하니 그다음 발송이 거부됐다. 한 번 띄워 놓고 시험하면 이 문제는 안 드러난다.

정리

메모리에만 있는 값은 프로세스가 끝나면 없어진다
한도를 세는 값이 거기 있으면 재기동이 곧 한도 초기화다
기록이 이미 있으면 그것을 센다
컬럼을 DATE() 로 감싸면 인덱스를 못 쓴다. 범위 조건으로 쓴다
EXPLAIN 의 type 이 ALL 이면 전부 읽고 있는 것이다
기록에서 세면 날짜 초기화 작업이 필요 없다
세고 나서 쓰는 사이에 끼어들 수 있으니 기록을 먼저 넣는다
그래도 REPEATABLE READ 의 그냥 SELECT 는 사진을 본다. FOR UPDATE 로 센다
메모리에 있는 값을 찾아 사라져도 되는지 하나씩 판단한다
기준은 재기동 뒤 이 값이 0이면 무슨 일이 나는가다
재기동해 봐야 이 문제가 드러난다