주간 정산 보정이 0.3초에서 9초가 됐고, 실패한 날 다시 돌린 보정은 6만 건이 모자랐다

중급PLSQL한빛유통692 / 700

상황

주간 정산 보정 배치 P_STLM_ADJ는 0.3초쯤 걸렸다. 지난달 장애 회의에서 "배치가 어디까지 했는지 알 수 없다"는 말이 나와, 개발자가 정산 한 건을 처리할 때마다 PKG_LOG.WRITE로 한 줄씩 남기게 했다. 로그는 배치가 실패해 롤백돼도 남도록 자율 트랜잭션으로 쓴다. 그 뒤로 배치가 9초 넘게 걸린다. 지난주 목요일 새벽 배치가 테이블스페이스 부족으로 실패했다. 운영 담당은 공간을 늘린 뒤, 로그의 마지막 OK 번호 다음부터 다시 돌렸다. 월요일 정산 확정에서 보정이 64,000건 모자랐다.

테이블과 인덱스

T_ORD_STLM 정산: 이번 주 100,020행 · 약 640블록 · STLM_SEQ 1 ~ 100,020
M_CUS: 2,000행 · PK_M_CUS (CUS_ID) · 보정률은 등급 A 0.1%, B 0.2%, 그 밖 0.3%
T_STLM_ADJ 보정 이력(이 문제용): 주차(ADJ_WK)마다 지우고 다시 넣는다 · 인덱스 없음
T_BATCH_LOG(이 문제용): PK (LOG_SEQ) · LOG_SEQ는 시퀀스 SQ_BATCH_LOG(CACHE 20) · 지금 3,214,906행
p_from_seq 인자는 2021년에 1,000건마다 커밋하던 판의 재시작 인자다. 지금 판은 끝에 한 번만 커밋한다.
운영 담당은 배치가 도는 동안 T_BATCH_LOG를 조회해 진행 상황을 본다.

원본 SQL

sql

-- 로그 패키지 (지난달) — 배치가 롤백돼도 남도록 자율 트랜잭션
CREATE OR REPLACE PACKAGE BODY PKG_LOG IS
  PROCEDURE WRITE(p_job VARCHAR2, p_key NUMBER, p_msg VARCHAR2) IS
    PRAGMA AUTONOMOUS_TRANSACTION;
  BEGIN
    INSERT INTO T_BATCH_LOG (LOG_SEQ, LOG_DT, JOB_NM, KEY_NO, MSG)
    VALUES (SQ_BATCH_LOG.NEXTVAL, SYSTIMESTAMP, p_job, p_key, p_msg);
    COMMIT;
  END;
END;
/

-- 주간 정산 보정
PROCEDURE P_STLM_ADJ(p_wk VARCHAR2, p_from_seq NUMBER DEFAULT 0) IS
  CURSOR c IS
    SELECT s.STLM_SEQ, s.STLM_AMT, m.CUS_GD
      FROM T_ORD_STLM s, M_CUS m
     WHERE m.CUS_ID = s.CUS_ID
       AND s.STLM_SEQ > p_from_seq
     ORDER BY s.STLM_SEQ;
  TYPE t_rows IS TABLE OF c%ROWTYPE;
  TYPE t_num  IS TABLE OF NUMBER INDEX BY PLS_INTEGER;
  v      t_rows;
  v_rate t_num;
BEGIN
  PKG_LOG.WRITE('STLM_ADJ', NULL, 'START ' || p_wk);
  IF p_from_seq = 0 THEN
    DELETE FROM T_STLM_ADJ WHERE ADJ_WK = p_wk;
  END IF;
  OPEN c;
  LOOP
    FETCH c BULK COLLECT INTO v LIMIT 1000;
    EXIT WHEN v.COUNT = 0;
    FOR i IN 1 .. v.COUNT LOOP
      v_rate(i) := CASE v(i).CUS_GD WHEN 'A' THEN 0.001 WHEN 'B' THEN 0.002 ELSE 0.003 END;
      PKG_LOG.WRITE('STLM_ADJ', v(i).STLM_SEQ, 'OK');          -- 장애 때 어디까지 했는지 보려고 (지난달)
    END LOOP;
    FORALL i IN 1 .. v.COUNT
      INSERT INTO T_STLM_ADJ (ADJ_WK, STLM_SEQ, ADJ_RATE, ADJ_AMT)
      VALUES (p_wk, v(i).STLM_SEQ, v_rate(i), ROUND(v(i).STLM_AMT * v_rate(i)));
  END LOOP;
  CLOSE c;
  COMMIT;
  PKG_LOG.WRITE('STLM_ADJ', NULL, 'END');
EXCEPTION
  WHEN OTHERS THEN
    ROLLBACK;
    PKG_LOG.WRITE('STLM_ADJ', NULL, 'FAIL ' || SQLERRM);
    RAISE;
END;

실행계획 학습용 예시

xplan

[세션 통계 — 정상 한 판 (정산 100,020건)]
                                     로그 넣기 전      지금
  경과 시간                              0.31 초        9.4 초
  CPU used by this session              0.17 초        5.9 초
  recursive calls                         2,412       207,461
  user commits                                1       100,023
  session logical reads                  22,363       521,870
  redo size                             11.2 MB       78.4 MB
  log file sync (이 세션)                      1             3
  LGWR log file parallel write (같은 구간)    14         4,106
  T_BATCH_LOG 증가                         —       100,023행

[지난주 목요일 — T_BATCH_LOG]
  02:00:03  START 2024W23
  02:00:09  OK 64000                                   ← 마지막 OK
  02:00:09  FAIL ORA-01653: unable to extend table SQLP.T_STLM_ADJ by 128 in tablespace USERS
  09:30:41  START 2024W23      (공간을 늘리고 P_STLM_ADJ('2024W23', 64000)로 다시 돌림)
  09:30:44  END

[월요일 정산 확정 대조]
  정산 100,020 · 보정 이력 36,020 · 차이 64,000

문제

로그 한 줄 때문에 배치가 30배 느려진 이유를 세션 통계로 설명하시오. 이 세션의 log file sync가 3번뿐인데도 커밋이 원인인 까닭도 쓰시오.
다시 돌린 보정이 64,000건 모자란 이유를 설명하시오.
진행 상황을 볼 수 있으면서 두 문제가 없도록 배치를 고치시오.

개선 SQL원본 SQL을 고쳐 쓰세요. 인덱스 DDL과 힌트도 쓸 수 있습니다.

개선 사유무엇이 문제였고 왜 이렇게 고쳤는지 쓰세요.0자

모범답안

모범 답안 SQL

sql

PROCEDURE P_STLM_ADJ(p_wk VARCHAR2) IS          -- 재시작 인자를 없앤다: 끝에 한 번 커밋하므로 실패하면 처음부터
  CURSOR c IS
    SELECT s.STLM_SEQ, s.STLM_AMT, m.CUS_GD
      FROM T_ORD_STLM s, M_CUS m
     WHERE m.CUS_ID = s.CUS_ID;
  TYPE t_rows IS TABLE OF c%ROWTYPE;
  TYPE t_num  IS TABLE OF NUMBER INDEX BY PLS_INTEGER;
  v       t_rows;
  v_rate  t_num;
  v_total PLS_INTEGER;
  v_done  PLS_INTEGER := 0;
BEGIN
  SELECT COUNT(*) INTO v_total FROM T_ORD_STLM;
  DBMS_APPLICATION_INFO.SET_MODULE('P_STLM_ADJ', p_wk);
  PKG_LOG.WRITE('STLM_ADJ', v_total, 'START ' || p_wk);          -- 자율 트랜잭션 1번
  DELETE FROM T_STLM_ADJ WHERE ADJ_WK = p_wk;
  OPEN c;
  LOOP
    FETCH c BULK COLLECT INTO v LIMIT 1000;
    EXIT WHEN v.COUNT = 0;
    FOR i IN 1 .. v.COUNT LOOP
      v_rate(i) := CASE v(i).CUS_GD WHEN 'A' THEN 0.001 WHEN 'B' THEN 0.002 ELSE 0.003 END;
    END LOOP;
    FORALL i IN 1 .. v.COUNT
      INSERT INTO T_STLM_ADJ (ADJ_WK, STLM_SEQ, ADJ_RATE, ADJ_AMT)
      VALUES (p_wk, v(i).STLM_SEQ, v_rate(i), ROUND(v(i).STLM_AMT * v_rate(i)));
    v_done := v_done + v.COUNT;
    -- 진행 상황은 메모리에만 (V$SESSION.ACTION) — redo도 커밋도 없다
    DBMS_APPLICATION_INFO.SET_ACTION(v_done || ' / ' || v_total || ' (미커밋)');
  END LOOP;
  CLOSE c;
  COMMIT;                                                          -- 본 트랜잭션은 한 번
  PKG_LOG.WRITE('STLM_ADJ', v_done, 'END ' || v_done || '건 반영');  -- 커밋한 뒤에 '반영' 을 쓴다
  DBMS_APPLICATION_INFO.SET_MODULE(NULL, NULL);
EXCEPTION
  WHEN OTHERS THEN
    ROLLBACK;
    -- 실패 기록은 롤백과 상관없이 남아야 하므로 이것만 자율 트랜잭션이 맞다
    PKG_LOG.WRITE('STLM_ADJ', v_done, 'FAIL ' || SQLERRM || ' · 반영 0건, 처음부터 다시 돌린다');
    RAISE;
END;

개선 후 실행계획 학습용 예시

xplan

[세션 통계 — 정상 한 판 (고친 판)]
  경과 0.32 초 · CPU 0.18 초 · recursive calls 2,447 · user commits 3 (START, END 로그 + 본 커밋)
  session logical reads 22,421 · redo size 11.3 MB · T_BATCH_LOG 한 판에 2행

[도는 동안 운영 담당이 보는 곳]
  SELECT MODULE, ACTION FROM V$SESSION WHERE MODULE = 'P_STLM_ADJ';
  → P_STLM_ADJ   63000 / 100020 (미커밋)

[실패를 흉내 — 63,000건째에서 공간 부족]
  T_STLM_ADJ 0행 · T_BATCH_LOG: START → FAIL ORA-01653 … 반영 0건, 처음부터 다시 돌린다
  다시 돌림 → 보정 이력 100,020 = 정산 100,020

모범 답안 서술

세션 통계에서 user commits가 100,023이다. 본 배치는 끝에 한 번만 커밋하므로 나머지 100,022번은 PKG_LOG.WRITE의 자율 트랜잭션이 정산 한 건마다 INSERT하고 COMMIT한 것이다. 커밋마다 로그 한 행과 그 인덱스, 커밋 레코드의 redo가 생겨 redo가 11.2 → 78.4MB로 늘었고, 논리 읽기는 22,363 → 521,870, recursive calls는 2,412 → 207,461이 됐다. 그래서 0.31초이던 배치가 9.4초가 됐다. 이 세션의 log file sync가 3번뿐인 것은 PL/SQL 안의 COMMIT이 매번 LGWR를 기다리지 않기 때문이다. 세션은 기다리지 않지만 커밋 레코드는 그때마다 로그 버퍼에 쓰이고, LGWR는 그것을 내려보내느라 같은 구간의 log file parallel write가 14 → 4,106번으로 늘었다(교재 13화 §7). 대기 이벤트만 보고 커밋을 의심하지 않으면 이 비용을 놓친다. 64,000건이 모자란 이유는 자율 트랜잭션 로그가 배치의 롤백과 따로 남기 때문이다. OK 줄은 덩어리 1,000건을 배열에 받아 보정률을 계산하는 루프에서, FORALL INSERT보다 먼저 쓰였다. 64번째 덩어리(63,001 ~ 64,000)는 OK 1,000줄이 먼저 커밋된 뒤 FORALL INSERT가 ORA-01653으로 실패했다. 그 1,000건은 아예 들어가지도 않았고, 앞의 63,000건도 커밋 전이었다. ROLLBACK이 보정 이력을 전부 되돌렸지만 이미 커밋된 OK 64,000줄은 남았다. 운영 담당은 그것을 "여기까지 끝났다"로 읽고 p_from_seq = 64000으로 다시 돌렸다. 두 번째 판은 64,000 뒤의 36,020건만 넣었고, 앞의 64,000건은 어느 판에서도 반영되지 않았다. 재시작 인자는 1,000건마다 커밋하던 2021년 판의 것이라 한 번 커밋하는 지금 판과 맞지 않았다. 고친 판은 정산마다 쓰던 로그를 없앤다. 로그는 시작과 끝, 실패만 남기고, 끝 로그는 COMMIT 뒤에 쓴다. 자율 트랜잭션은 롤백과 상관없이 남아야 하는 실패 기록에만 맞는 도구다. 진행 상황은 DBMS_APPLICATION_INFO.SET_ACTION으로 덩어리마다 세션 정보에 띄운다. 메모리에만 쓰므로 redo도 커밋도 없고, 운영 담당은 V$SESSION.ACTION에서 "63000 / 100020 (미커밋)"처럼 본다. 실패하면 반영이 0건이므로 재시작 인자를 없애고 처음부터 다시 돌린다(한 판 0.3초). 경과는 9.4초 → 0.3초, user commits는 100,023 → 3, 로그는 한 판에 100,023행 → 2행이 된다.

해설

"롤백돼도 남는다"는 양날이다. 실패 사유처럼 롤백과 상관없이 남아야 하는 기록에는 맞지만, "처리했다"는 기록에 쓰면 롤백된 일을 처리한 것처럼 남긴다. 성공 기록은 본 트랜잭션 안에서 함께 커밋하거나 커밋한 뒤에 쓴다.
재시작 지점이 필요하다면 덩어리마다 커밋하고, 체크포인트(마지막으로 끝낸 번호)를 같은 트랜잭션 안에서 데이터와 함께 고친다(교재 13화 §8). 자율 트랜잭션으로 체크포인트를 적으면 오늘과 같은 어긋남이 생긴다.
진행률을 V$SESSION_LONGOPS에 띄우는 DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS도 같은 목적에 쓸 수 있다. 남은 시간까지 계산해 보여 준다.
log file sync가 작다고 커밋이 싸다는 뜻은 아니다. 클라이언트가 건마다 커밋하거나 COMMIT WRITE WAIT를 쓰면 세션이 커밋마다 기다리고, PL/SQL 안에서는 LGWR 쪽에 일이 쌓인다.

상황 ​

테이블과 인덱스 ​

원본 SQL ​

실행계획 학습용 예시 ​

문제 ​

모범 답안 SQL ​

개선 후 실행계획 학습용 예시 ​

모범 답안 서술 ​

해설 ​

관련 교재 ​

상황