통계 화면의 학습시간이 이상하게 길다는 이야기가 나왔다. 콘텐츠 하나에 10분이면 끝나는데, 기록에는 20분, 30분이 찍혀 있었다.

결론부터 쓰면 원인은 한 줄짜리 계산식이었다. 그런데 거기까지 가는 동안 가설을 다섯 번 틀렸다. 이 글은 버그보다 그 다섯 번이 더 중요한 이야기다.

구조

학습시간은 클라이언트가 보내지 않는다. 서버가 시각 차이로 계산한다.

학습 시작 (/init)  → startAt 기록
학습 중 저장 (여러 번) → studyTime 누적
학습 종료 저장       → studyTime 누적

앱은 학습 중간중간 진행 상태를 저장한다. 콘텐츠 종류에 따라 저장이 한 번일 때도, 대여섯 번일 때도 있다.

첫 번째 실수: 평균으로 판단하기

처음에는 이렇게 봤다.

SELECT AVG(study_time) / AVG(TIMESTAMPDIFF(SECOND, start_at, end_at))
FROM study_action;
-- 약 2.0

“기록된 학습시간이 실제 경과 시간의 2배다. 전체가 2배로 쌓이고 있다.”

그럴듯했고, 틀렸다. 평균의 평균은 소수의 극단값이 분자를 끌어올리면 “전체가 2배”처럼 보인다. 건별로 비율을 구해 분포를 봤다.

SELECT FLOOR(study_time / TIMESTAMPDIFF(SECOND, start_at, end_at) * 2) / 2 AS ratio_bucket,
       COUNT(*)
FROM study_action
WHERE TIMESTAMPDIFF(SECOND, start_at, end_at) > 0
GROUP BY ratio_bucket;
  • 70.5% 는 비율 1.0 근처 — 정상이었다.
  • 이상한 건 나머지였고, 그중 98.2% 가 플레이어 유형 4개에 몰려 있었다.

“전체가 2배”가 아니라 “특정 콘텐츠만 몇 배”였다. 원인을 찾을 범위가 확 줄었다.

하나 더. ROUND(ratio) 로 “정수에 97% 가 몰려 있다”고 주장한 적도 있는데 의미가 없었다. 1.5 ~ 5.5 의 모든 값은 반올림하면 정수가 된다. 정수성을 보려면 소수부 분포를 봐야 한다.

원인: 저장할 때마다 시작 시각부터 다시 계산

몰려 있던 콘텐츠의 공통점은 학습 중 저장이 여러 번 온다는 것이었다. 저장 코드를 보니 이랬다.

// 저장 요청마다 호출
long elapsed = Duration.between(action.getStartAt(), now).getSeconds();
action.setStudyTime(action.getStudyTime() + elapsed);

startAt 은 학습 시작 때 한 번만 찍힌다. 그런데 저장할 때마다 시작 시각부터 지금까지를 다시 더하고 있었다.

10:00 시작
10:05 저장 → +5분
10:10 저장 → +10분   (10:00~10:05 를 또 셈)
10:15 저장 → +15분   (10:00~10:10 을 또 셈)
실제 15분인데 기록은 30분

저장이 등간격으로 N 번 오면 전체 시간 T 에 대해

T/N × (1 + 2 + … + N) = T × (N + 1) / 2

배수가 (N+1)/2 가 된다. 저장 3번이면 2배, 5번이면 3배, 7번이면 4배. 분포에서 본 2 · 3 · 4 배 덩어리가 정확히 이 값이었다.

해결

1. 누적 기준을 “직전 저장 시각”으로

// 엔티티 메서드로 한 곳에 모음
public void accumulateStudyTime(LocalDateTime now) {
    LocalDateTime from = (this.endAt != null) ? this.endAt : this.startAt; // 직전 저장 시각, 없으면 시작 시각
    long elapsed = Math.max(0, Duration.between(from, now).getSeconds());
    this.studyTime += elapsed;
    this.endAt = now;
}

컬럼은 추가하지 않았다. endAt 이 이미 “저장마다 갱신되고, 학습 시작 때 비워지는” 값이라 그대로 “직전 저장 시각”으로 쓸 수 있었다.

startAt 을 저장마다 밀어 버리는 방법은 쓰지 않았다. 재학습 여부를 startAt 과 첫 완료 시각의 선후로 판정하고 있어서, 건드리면 재학습이 아닌데도 완료 횟수가 올라간다. 고치기 전에 그 값을 누가 읽는지 먼저 찾아야 하는 이유다.

2. 복사된 계산식 하나로 합치기

같은 계산식이 다른 저장 경로에도 복사돼 있었고, 거기엔 음수 방어가 없었다. 시각이 역전되면 UNSIGNED 컬럼에 음수가 들어갈 수 있었다. 위 엔티티 메서드 하나로 합쳤다.

3. 기준 시각은 master 에서 읽기

저장 대상 행을 replica(slave) 에서 읽고 있었다. 복제가 늦으면 이미 갱신된 endAt 이 아니라 옛 값을 읽어 같은 구간을 또 더한다. 누적의 기준점을 읽는 조회는 master 로 바꿨다.

검증

  • 로컬에서 같은 저장 패턴을 재현해 기록 / 실제 비율이 1.00 이 되는 것을 확인 (예: 14초 → 10초)
  • 비슷한 시기, 다른 통계에서 서비스 조건이 빠져 다른 서비스의 학습시간이 74% 섞여 있던 것도 찾았다. 고친 뒤 API 응답 35건을 전수 비교해 예측과 불일치 0건

남은 한계

저장이 한 번뿐인 “켜 두고 방치” 는 여전히 못 거른다. 겹칠 구간이 없기 때문이다. 3시간이 넘으면 경고 로그만 남기고 값은 그대로 둔다. 근거 없이 상한을 걸면 정상적인 장시간 학습까지 깎이기 때문이다.

배운 것

  • 평균 말고 분포를 봐라. 평균의 평균은 극단값 몇 개로 “전부 이상하다”는 착시를 만든다.
  • 기각한 가설도 기록하자. 다섯 번 틀린 덕에 여섯 번째에서 범위가 좁았다.
  • 고치기 전에 그 값을 누가 읽는지 찾아라. startAt 을 밀었으면 학습시간은 맞고 재학습 횟수가 틀어졌을 것이다.
  • “누적” 에는 기준점이 필요하다. 시작점부터 매번 다시 더하면 구간이 겹친다. 그리고 그 기준점을 복제 지연된 곳에서 읽으면 또 겹친다.