타임세일이 시작되면 결제 완료 콜백이 3초를 넘겨 결제 대행사가 같은 콜백을 다시 보낸다

중급UPDATE한빛유통558 / 700

상황

한빛유통 쇼핑몰은 결제 대행사(PG)가 결제 완료를 알려 오면(콜백) 주문의 상태와 결제 정보를 고친다. 평소에는 초당 몇 건이지만, 저녁 8시 타임세일이 시작되면 처음 10분 동안 초당 140건까지 몰린다. PG는 3초 안에 응답이 없으면 같은 콜백을 다시 보낸다. 지난 금요일 20:00 ~ 20:10에 들어온 재시도 콜백만 11,400건이었다.

테이블과 인덱스

T_ORD: 100,000행 · 896블록 · PK_T_ORD (ORD_SEQ) · ORD_ST(PENDING → COMPLETE) · PAY_TP(CARD, BANK, POINT) · PAY_DT · PAY_AMT
콜백 API 서버 8대가 스레드 16개씩 DB에 붙는다.
CURSOR_SHARING = EXACT

원본 SQL

sql

// PgCallbackController.java : 콜백 값을 문자열로 이어 붙여 UPDATE 한다
String sql = "UPDATE T_ORD SET ORD_ST = 'COMPLETE', PAY_DT = SYSDATE, PAY_TP = '" + payTp
           + "', PAY_AMT = " + payAmt + " WHERE ORD_SEQ = " + ordSeq;
try (Statement st = conn.createStatement()) {
    st.executeUpdate(sql);
}
conn.commit();

실행계획 학습용 예시

xplan

[ASH · 금요일 20:00 ~ 20:10 · 콜백 세션의 표본 비율]
  CPU                               38%
  latch: shared pool                26%
  library cache: mutex X            11%
  enq: TX - row lock contention      9%    (재시도 콜백이 아직 처리 중인 같은 주문을 고치려고 기다린다)
  row cache mutex                    6%

[V$SYSSTAT · 20:00 ~ 20:10 증가분]
  execute count                  97,100
  parse count (hard)             95,860
  parse time cpu                 61,400 cs
  CPU used by this session       84,900 cs

[V$SQLAREA · 20:10 · FORCE_MATCHING_SIGNATURE로 묶은 맨 위 무리]
  PARENTS   EXECS     MB   SAMPLE
    6,210   6,480   98.4   UPDATE T_ORD SET ORD_ST = 'COMPLETE', PAY_DT = SYSDATE, PAY_TP = 'CARD', PAY_AMT = 38500 WHERE ORD_SEQ = 98431

[콜백 응답 시간]  평소 p99 0.04초 · 20:00 ~ 20:10 p99 2.9초 · 3초 넘김 11,400건 (모두 재시도로 돌아왔다)

[한 번 실행의 계획]
-------------------------------------------------------------------------------------------
| Id  | Operation          | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT   |          |      1 |        |      0 |00:00:00.01 |       4 |
|   1 |  UPDATE            | T_ORD    |      1 |        |      0 |00:00:00.01 |       4 |
|*  2 |   INDEX UNIQUE SCAN| PK_T_ORD |      1 |      1 |      1 |00:00:00.01 |       2 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("ORD_SEQ"=98431)

문제

행 하나를 고치는 UPDATE가 3초를 넘기는 이유를 위 자료로 설명하시오. 재시도 콜백이 상황을 어떻게 키우는지도 쓰시오.
콜백 처리 SQL을 고치시오. 문장 안의 상수 가운데 바인드 변수로 바꿀 것과 그대로 둬도 되는 것을 가려 쓰시오.

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

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

모범답안

모범 답안 SQL

sql

// PgCallbackController.java : 콜백마다 바뀌는 값은 바인드 변수로 · 늘 같은 상수는 그대로
String sql = "UPDATE T_ORD "
           + "   SET ORD_ST = 'COMPLETE', PAY_DT = SYSDATE, PAY_TP = ?, PAY_AMT = ? "
           + " WHERE ORD_SEQ = ? "
           + "   AND ORD_ST  = 'PENDING'";         // 재시도 콜백은 0건을 고치고 끝난다
try (PreparedStatement ps = conn.prepareStatement(sql)) {
    ps.setString(1, payTp);
    ps.setLong(2, payAmt);
    ps.setLong(3, ordSeq);
    int n = ps.executeUpdate();                   // 0이면 이미 처리된 콜백 : 성공으로 응답한다
}
conn.commit();

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

xplan

[고친 뒤 · 다음 타임세일 20:00 ~ 20:10 (학습용 예시)]
  parse count (hard)          6
  parse time cpu              2 cs
  CPU used by this session    9,800 cs
  latch: shared pool          표본 1% 미만
  콜백 p99                    0.05초 · 3초 넘김 0건 · 재시도 0건
  V$SQLAREA                   부모 1 · 실행 84,200

---------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT             |          |      1 |        |      0 |00:00:00.01 |       5 |
|   1 |  UPDATE                      | T_ORD    |      1 |        |      0 |00:00:00.01 |       5 |
|*  2 |   TABLE ACCESS BY INDEX ROWID| T_ORD    |      1 |      1 |      1 |00:00:00.01 |       3 |
|*  3 |    INDEX UNIQUE SCAN         | PK_T_ORD |      1 |      1 |      1 |00:00:00.01 |       2 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("ORD_ST"='PENDING')
   3 - access("ORD_SEQ"=:3)

모범 답안 서술

콜백마다 결제 금액과 주문번호가 SQL 텍스트에 들어가므로 콜백 하나하나가 처음 보는 문장이다. 10분 동안 실행 97,100번에 하드 파싱이 95,860번이고, CPU 849초 가운데 614초가 파싱이다. 128개 스레드가 동시에 하드 파싱을 하면서 공유 풀에 새 자리를 만들려고 latch: shared pool을 두고 다투고(26%), 라이브러리 캐시 뮤텍스와 딕셔너리 캐시에서도 기다린다. 행 하나를 고치는 일은 4블록인데 응답 시간 p99가 2.9초가 된 까닭이다. 재시도가 이 줄을 더 길게 만든다. 3초를 넘긴 콜백 11,400건을 PG가 다시 보내면 그것도 새 문장이라 하드 파싱을 한 번 더 하고, 아직 처리 중인 같은 주문을 고치려다 enq: TX - row lock contention으로 기다린다(9%). 느려질수록 재시도가 늘고, 재시도가 늘수록 더 느려진다. 콜백마다 바뀌는 값(PAY_TP, PAY_AMT, ORD_SEQ)은 바인드 변수로 넘긴다. ORD_ST = 'COMPLETE'와 PAY_DT = SYSDATE는 모든 콜백에서 똑같은 상수라 리터럴로 둬도 문장은 하나다. 상수를 모조리 바인드 변수로 바꿀 필요는 없고, 실행마다 달라지는 값만 바꾸면 된다. 여기에 AND ORD_ST = 'PENDING'을 붙이면 재시도 콜백은 0건을 고치고 끝나서 같은 결제가 두 번 반영되지 않는다. 고친 뒤 하드 파싱은 95,860 → 6, 콜백 p99는 2.9초 → 0.05초다.

해설

무엇을 바인드 변수로 바꾸나: 실행마다 달라지는 값(입력)은 바인드 변수, 코드가 늘 같은 값으로 쓰는 상수는 리터럴이다. 상수까지 바인드 변수로 바꾸면 SQL만 읽기 어려워진다.
PAY_TP는 세 가지뿐이라 리터럴로 두어도 문장이 셋이다. 그래도 PG가 보낸 값을 문자열에 이어 붙이는 코드는 SQL 주입 구멍이 되므로, 입력으로 들어오는 값은 바인드 변수로 넘긴다.
래치와 뮤텍스 대기는 하드 파싱이 동시에 몰릴 때 커진다. 혼자 돌리는 테스트에서는 이 줄이 보이지 않는다(교재 11화 §3: 네 명이 동시에 누르자 Concurrency 대기가 나타났다).
재시도 폭주는 응답 시간 문제이면서 결과 문제이기도 하다. 상태 조건이 없으면 늦게 도착한 재시도가 이미 처리된 결제를 한 번 더 고친다.

상황 ​

테이블과 인덱스 ​

원본 SQL ​

실행계획 학습용 예시 ​

문제 ​

모범 답안 SQL ​

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

모범 답안 서술 ​

해설 ​

관련 교재 ​

상황