포캐스트 시스템 개발 기록 (3) 50초 걸리던 페이지를 0.2초대로, 그리고 조용한 실패 잡기

첫 사용자만 50초를 기다렸다 포케스트 시스템의 재고 운영 관리표(jego12)와 재고운영 대시보드(jego13)는 숫자 대부분을 회계서버 API에서 가져온다. 재고 스냅샷, 최근 6개월 평균판매, 3개월 평균재고, 월중 채널별 판매, 입고 수량, 품목별 최초 입고일 같은 것들이다. 매 요청마다 회계서버를 부르면 느리기도 하고 회계서버에도 부담이 되니, 처음부터 결과를 파일로 캐시했다. 그런데 대시보드에 지표가 하나씩 늘면서 이상한 증상이 생겼다. 대부분은 페이지가 바로 뜨는데, 가끔 누군가는 한참을 기다렸다. 특히 3개월 평균재고를 추가한 뒤로는 캐시가 빈 상태에서 페이지를 열면 50초 안팎이 걸렸다. 같은 페이지를 다시 열면 금방 떴다. 이 글은 이 지연을 없앤 과정과, 그 과정에서 알게 된 "조용한 실패"를 잡는 점검 크론 이야기다. 구조: 회계 API 호출과 파일 캐시 회계서버 호출은 acc_metrics.php 한 파일에 모았다. 함수마다 하는 일은 같다. 시스템 임시 디렉터리에 조회 월별 JSON 캐시 파일이 있고 유효 시간 안이면 그걸 쓰고, 아니면 API를 호출한 뒤 결과를 캐시에 쓴다. 유효 시간은 데이터 성격에 맞춰 달리 잡았다. 지표 캐시 유효 시간 월 재고·평균출고·월중 누적판매, 채널별 판매 5분 입고 수량 10분 품목 마스터 보완, 6개월 평균판매, 3개월 평균재고 6시간 최초 입고일(신제품 판정) 24시간 캐시 쓰기는 임시 파일에 먼저 쓰고 rename 으로 바꿔치기한다. 두 요청이 동시에 같은 캐시를 쓰더라도 읽는 쪽이 반쯤 쓰인 파일을 보지 않게 하기 위해서다. 회계서버가 느릴 때 페이지가 같이 매달리지 않도록 연결 3초, 전체 8초 타임아웃도 걸었다. $cacheFile = sys_get_temp_dir() . '/acc_forecast_metrics_' . $month . '.json'; if (is_file($cacheFile) && (time() - filemtime($cacheFile)) < 300) { $cached = json_decode((string) @file_get_contents($cacheFile), true); if (is_array($cached) && !empty($cached['items'])) { return $cached; } } // ... curl: CONNECTTIMEOUT 3초, TIMEOUT 8초, Bearer 토큰 ... if ($code !== 200 || !$resp) { return null; // 호출부가 기존 데이터로 폴백 } // 원자적 기록: 임시 파일 → rename $tmp = $cacheFile . '.' . getmypid() . '.tmp'; if (@file_put_contents($tmp, $resp) !== false) { @rename($tmp, $cacheFile); } 실패하면 null 을 돌려주고, 호출하는 화면은 기존 DB 데이터로 폴백하면서 경고를 띄운다. 예를 들어 입고 수량 API가 응답하지 않으면 발주 시스템의 입고예정 데이터를 대신 쓰고 "회계 입고 조회 실패"를 표시한다. 시행착오 캐시는 있는데 첫 사용자가 비용을 낸다 5분짜리 캐시는 문제가 없었다. 회계서버가 미리 집계해 둔 숫자를 받아오는 거라 한 번 호출이 짧았다. 문제는 6시간·24시간짜리였다. 6개월 평균판매는 월별 판매를 여섯 번 받아 품목별로 평균을 내고, 3개월 평균재고는 월말 재고 스냅샷을 세 번 받는다. 최초 입고일은 입고 이력을 전부 훑는다. 이 수집만으로 수십 초가 걸렸다. 캐시가 살아 있는 동안에는 아무도 이 비용을 느끼지 못한다. 하지만 6시간이 지나 캐시가 만료되면, 그 직후 페이지를 연 사람이 수집 전체를 기다리게 된다. 아침에 출근해 처음 대시보드를 연 사람이 50초를 기다리고, 그 뒤 사람들은 0.2초 만에 보는 식이었다. 재현도 들쭉날쭉해서 "가끔 느리다"는 말만 돌았다. 해결은 단순하게 갔다. 사람이 캐시를 채우게 두지 말고 크론이 미리 채우게 했다. cron_forecast_cache_warm.php 가 당월과 전월에 대해 재고 지표, 채널 판매, 품목 마스터, 6개월·3개월 평균판매, 3개월 평균재고, 입고 수량을 차례로 호출하고, 전월말 재고 스냅샷과 최초 입고일까지 채운다. 대시보드는 당월, 관리표는 직전 마감월을 기본으로 열기 때문에 두 달을 같이 데운다. 크론은 3시간 간격으로 돌려 6시간 캐시가 만료되기 전에 항상 새로 채워지게 했다. function warm(string $label, callable $fn, array &$log): void { $t = microtime(true); try { $n = $fn(); $log[] = sprintf(' %-28s %6.1fs %s', $label, microtime(true) - $t, $n); } catch (Throwable $e) { $log[] = sprintf(' %-28s %6.1fs ERROR %s', $label, microtime(true) - $t, $e->getMessage()); } } $months = [date('Ym'), date('Ym', strtotime('-1 month'))]; foreach ($months as $ym) { warm("[$ym] avg-sales 6m", fn() => count(acc_avg_sales_months($ym, 6)) . '품목', $log); warm("[$ym] avg-stock 3m", fn() => count(acc_avg_stock_months($ym, 3)) . '품목', $log); // ... forecast-metrics, channel-sales, sku-master, inbound } warm('first-inbound', fn() => count(acc_fetch_first_inbound()) . '품목', $log); 항목마다 걸린 시간과 품목 수를 로그로 남기게 한 건 다음에 또 느려졌을 때 어디가 느린지 바로 보기 위해서다. 실제로 첫 실행 로그에서 워밍 한 번에 36.7초가 걸렸고, 그중 19.4초가 최초 입고일 수집이었다. 한 항목이 실패해도 나머지는 계속 데우도록 try/catch 를 항목 단위로 감쌌다. 크론을 돌렸는데도 계속 느렸다: /tmp 스티키 비트 워밍 스크립트를 서버 작업용 계정으로 돌려 보면 캐시 파일은 잘 생기는데, 페이지는 그 뒤에도 매번 재수집하고 있었다. 캐시 파일 소유자를 확인해 보니 웹 서버(php-fpm) 계정이 아니라 작업용 계정 소유였다. 임시 디렉터리 /tmp 에는 스티키 비트가 걸려 있다. 누구나 파일을 만들 수는 있지만, 다른 사람이 만든 파일을 지우거나 덮어쓸 수는 없다. 그래서 웹 서버가 만료된 캐시를 새로 쓰려고 rename 으로 덮어쓰는 순간 권한 오류가 났다. 그런데 캐시 코드는 @rename 으로 오류를 삼키고 있었다. 결과적으로 웹 서버는 만료된 파일을 갱신하지 못한 채 매 요청마다 회계서버에서 다시 수집했고, 어디에도 에러가 남지 않았다. 워밍 크론은 웹 서버와 같은 www-data 계정의 crontab에 등록하고, 기존에 다른 계정 소유로 만들어진 캐시 파일을 정리했다. 스크립트 주석 맨 위에 "반드시 www-data로 실행할 것"을 적어 두었다. 다음에 누가 서버를 옮기거나 크론을 다시 등록할 때 같은 함정에 빠지지 않게 하려는 것이다. 이후 페이지 조회는 0.2초대로 떨어졌다. 배치가 안 돌았는데 아무도 몰랐다 캐시를 정리하고 며칠 뒤, 다른 화면에서 비슷한 종류의 사고가 났다. 원가·매출 추이 화면이 8월 말일에 보니 7월까지만 나오고 있었다. 이 화면도 포케스트의 월 실적 테이블을 쓴다. 월 실적은 두 곳에서 적재된다. 사내 PC의 작업 스케줄러가 말일 밤에 잠정치를, 서버 크론이 1일 새벽에 확정치를 넣는다. 둘이 겹쳐 중복이 생기는 문제는 이미 유니크 키와 upsert로 막아 두었다. 하지만 배치가 아예 돌지 않아 전월 데이터가 비는 경우는 막을 방법도, 알아챌 방법도 없었다. 1편에서 다룬 집계 테이블 정체와 같은 종류의 실패였다. 그래서 매월 1일 오전 9시, 두 적재기가 모두 끝난 뒤에 전월분을 점검하는 크론을 만들었다. 판정 기준은 네 가지다. 미적재: 전월 행이 0건 부분 적재: 품목 수가 직전 3개월 평균의 60% 미만 중복: 행 수와 품목 수가 다름(유니크 키가 있으니 정상이면 같아야 한다) 값 없음: 전 채널 수량 합계가 0 하나라도 걸리면 플랫폼개발팀에 네이버웍스 메시지를 보내고, 정상이면 로그만 남긴다. 수량 합계는 2편에서 만든 채널 단일 정의 헬퍼로 계산하니 채널이 늘어도 점검식을 고칠 필요가 없다. 판정만 해 보는 --dry , 정상이어도 발송해 알림 경로를 시험하는 --force , 특정 월을 지정하는 인자도 붙였다. 알림 메시지에는 "같은 달 재실행해도 중복되지 않으니 재적재하면 된다"는 조치 방법까지 넣었다. 결과 캐시 워밍 크론 적용 후, 콜드 상태에서 50초 안팎이던 재고 지표 페이지 조회가 0.2초대로 떨어졌다. 워밍 비용(1회 36.7초)은 3시간마다 크론이 대신 낸다. 월 실적 적재가 빠지거나 일부만 들어오면 다음 달 1일 오전에 팀이 알림을 받는다. 회고 캐시를 "있으면 빠르다"로만 생각하면 만료 직후의 사용자를 놓친다. 수집 비용이 큰 캐시는 사람이 아니라 스케줄러가 채워야 한다는 걸 이번에 체감했다. 또 @ 로 오류를 삼키는 코드는 캐시 쓰기 실패처럼 "실패해도 동작은 한다"는 경우에 편하지만, 그 실패가 반복되면 아무 흔적 없이 성능만 깎아 먹는다. 다시 만든다면 캐시 쓰기 실패는 최소한 로그 한 줄은 남기게 하겠다. 그랬다면 스티키 비트 문제를 소유자 목록을 뒤지기 전에 로그에서 바로 찾았을 것이다. 점검 크론도 같은 교훈에서 나왔다. 숫자가 0이거나 비어 있는 건 에러가 아니라서 시스템은 조용하다. 조용한 실패를 잡으려면 "정상이라면 이 정도는 있어야 한다"는 기준을 직접 정하고, 그 기준으로 매달 확인하는 수밖에 없었다. 기간: 2026.06 ~ 2026.09 기술: PHP, MySQL, cron, Linux 파일 권한, 회계서버 JSON API, 네이버웍스 알림 관련 프로젝트: 포캐스트 시스템