포인트 소급 적립 5,604건에 12초, 대기 1위가 log file sync다

기초INSERT이커머스434 / 700

이 문제는 교재 18화 졸업 과제와 같은 이커머스 데이터베이스를 씁니다. 『튜너의 1년』을 순서대로 읽고 있다면 졸업 과제를 먼저 풀고 오세요. 아래 「테이블과 인덱스」 칸에 과제의 답 일부(제약 조건, 인덱스, 통계의 실제 상태)가 나옵니다.

상황

CRM팀은 적립 정책을 바꾸면서 2024년에 배송 완료된 주문에 주문 금액의 1%를 소급 적립하기로 했다. 개발자가 만든 Java 프로그램은 대상 주문을 한 번에 읽어 온 뒤 한 건씩 INSERT를 보낸다. 시험 DB에서 5,604건에 11.8초가 걸렸고, 세션의 대기 이벤트 1위는 log file sync였다. 개발자: "DB 서버 디스크가 느린 거 아닐까요?"

테이블과 인덱스

orders: 34,908행 · 193블록 · status 6종(DELIVERED가 약 80%) · 2024년 DELIVERED 5,604건
point_transactions: 45,000행 · 210블록 · PK tx_id(시퀀스 seq_tx_id)만 있다.
JDBC 연결은 기본값(autocommit 켜짐) 그대로다. 앱 서버와 DB 서버 사이 왕복은 약 0.4ms다.

원본 SQL

sql

// PointBackfill.java (CRM팀) — 연결은 기본값: autocommit = true
List<Row> rows = jdbc.query(
    "SELECT order_id, customer_id, total_amount FROM orders " +
    " WHERE status = 'DELIVERED' " +
    "   AND order_date >= DATE '2024-01-01' AND order_date < DATE '2025-01-01'");

for (Row r : rows) {                       // 5,604 번
    jdbc.update(
        "INSERT INTO point_transactions (tx_id, customer_id, amount, tx_type, created_at) " +
        "VALUES (seq_tx_id.NEXTVAL, ?, ?, 'EARN', SYSDATE)",
        r.customerId, Math.round(r.totalAmount * 0.01));
}

실행계획 학습용 예시

xplan

[세션 통계 · 대기 이벤트 — 프로그램 한 번 (V$SESSTAT · V$SESSION_EVENT 증가분)]
  경과 시간                           11.8 초
  execute count                       5,607
  user commits                        5,604
  SQL*Net roundtrips to/from client   5,611
  redo size                           약 3.3 MB

  EVENT                          WAITS    TIME(s)   AVG(ms)
  log file sync                  5,604      6.28      1.12
  SQL*Net message from client    5,611      4.71      0.84
  (DB CPU                                   0.64)

문제

log file sync가 무엇을 기다린 시간인지, 이 프로그램에서 왜 5,604번이나 기다렸는지 설명하시오.
같은 적립을 하도록 고치고, 고친 뒤의 숫자를 적으시오. 프로그램을 남겨야 할 때의 방법도 쓰시오.

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

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

모범답안

모범 답안 SQL

sql

-- 대상 선정과 적립을 DB 안에서 한 문장으로 — 왕복 한 번 · 커밋 한 번
INSERT INTO point_transactions (tx_id, customer_id, amount, tx_type, created_at)
SELECT seq_tx_id.NEXTVAL, o.customer_id, ROUND(o.total_amount * 0.01), 'EARN', SYSDATE
  FROM orders o
 WHERE o.status = 'DELIVERED'
   AND o.order_date >= DATE '2024-01-01'
   AND o.order_date <  DATE '2025-01-01';
COMMIT;

-- 프로그램을 남겨야 한다면
--   conn.setAutoCommit(false);
--   for (Row r : rows) { ps.setLong(1, r.customerId); ps.setLong(2, …); ps.addBatch();
--                        if (++n % 1000 == 0) ps.executeBatch(); }
--   ps.executeBatch(); conn.commit();       // 커밋은 끝에 한 번

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

xplan

-------------------------------------------------------------------------------------------------------
| Id  | Operation                | Name               | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |                    |      1 |        |      0 |00:00:00.05 |    6047 |
|   1 |  LOAD TABLE CONVENTIONAL | POINT_TRANSACTIONS |      1 |        |      0 |00:00:00.05 |    6047 |
|   2 |   SEQUENCE               | SEQ_TX_ID          |      1 |        |   5604 |00:00:00.02 |     193 |
|*  3 |    TABLE ACCESS FULL     | ORDERS             |      1 |   5580 |   5604 |00:00:00.01 |     193 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("O"."STATUS"='DELIVERED' AND "O"."ORDER_DATE">=TO_DATE(' 2024-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')
              AND "O"."ORDER_DATE"<TO_DATE(' 2025-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

[세션 통계 · 대기 이벤트]
  경과 0.06초 · user commits 1 · SQL*Net roundtrips 4 · redo 약 1.6 MB
  log file sync 1번 (0.9 ms)

모범 답안 서술

대기 1위인 log file sync는 커밋한 세션이 'LGWR가 내 redo를 디스크에 다 썼나'를 기다린 시간이다. JDBC가 autocommit 기본값으로 문장마다 커밋했기 때문에 커밋이 5,604번이고, 그때마다 평균 1.12ms를 기다려 6.28초가 됐다. 한 번은 1ms 남짓이라 디스크가 느린 것이 아니라 커밋 횟수가 많은 것이다. 여기에 행마다 앱 서버와 DB 사이를 한 번씩 오가는 왕복(SQL*Net message from client 5,611번, 4.71초)이 더해져 11.8초가 됐다. 대상 선정과 적립을 DB 안에서 INSERT … SELECT 한 문장으로 하고 커밋은 끝에 한 번 한다. 경과 시간은 11.8초 → 0.06초, log file sync는 5,604번 → 1번, 왕복은 5,611번 → 4번으로 준다. 프로그램을 남겨야 한다면 setAutoCommit(false)로 자동 커밋을 끄고 addBatch와 executeBatch로 1,000건씩 묶어 보낸 뒤 끝에 한 번 커밋한다. 한 문장, 한 커밋이므로 중간에 실패하면 전부 되돌아가 반쯤 적립된 상태가 남지 않는다. 대신 성공한 뒤 다시 돌리면 중복 적립이 되므로, 소급 회차를 기록해 두고 같은 회차는 다시 돌지 않게 막는다.

해설

log file sync와 디스크: 한 번의 대기가 수 ms를 넘으면 LGWR 쪽 I/O(log file parallel write)를 의심한다. 여기서는 1.12ms로 정상이고, 횟수가 문제였다(교재 13화: 커밋할 때마다 기다리는 세션은 log file sync가 커밋 수만큼 쌓인다).
PL/SQL 루프 안의 COMMIT은 세션이 매번 기다리지 않는다(교재 13화 실측: 10만 번 커밋에 log file sync 2번). 앱이 건마다 커밋하면 매번 기다린다. 같은 '건마다 커밋'이라도 앱에서 할 때 더 비싸다.
NEXTVAL은 INSERT … SELECT 안에서 행마다 하나씩 붙는다. 시퀀스 CACHE가 작으면(기본 20) 시퀀스 갱신이 recursive call로 늘어나므로 대량 적립 전에 CACHE를 확인해 둔다.
point_transactions에는 어느 주문에서 나온 적립인지 적는 칸이 없다. 소급 적립처럼 한 번만 해야 하는 작업은 회차 기록이나 원천 키 칸을 두어 다시 돌려도 안전하게 만든다.

상황 ​

테이블과 인덱스 ​

원본 SQL ​

실행계획 학습용 예시 ​

문제 ​

모범 답안 SQL ​

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

모범 답안 서술 ​

해설 ​

관련 교재 ​

상황