SQL은 한 줄도 안 바꿨는데 배포 다음 날부터 하드 파싱이 실행 수만큼 찍힌다

기초SELECT한빛유통551 / 700

상황

한빛유통 개발팀은 지난주 화면 서버에 APM(성능 추적 도구)을 붙였다. 요청 하나가 어떤 SQL을 불렀는지 따라가려고, 데이터 접근 계층이 SQL을 보내기 직전에 요청마다 다른 추적 번호를 주석으로 앞에 붙이게 했다. 배포 다음 날부터 DB 서버(코어 4개)의 CPU 사용률이 12%에서 41%로 올랐다. 조민우가 말했다. "SQL은 한 줄도 안 바꿨어요. 바인드 변수도 그대로고요."

테이블과 인덱스

T_ORD: 100,000행 · 896블록 · PK_T_ORD (ORD_SEQ)
T_ORD_DET: 200,000행 · 896블록 · PK_T_ORD_DET (ORD_SEQ, ORD_DET_NO) · 주문당 1~3건
주문 상세 화면을 비롯한 화면 SQL은 모두 바인드 변수로 쓰여 있다. 주문 상세는 한 번에 7블록 안팎을 읽는다.
CURSOR_SHARING = EXACT · session_cached_cursors = 50

원본 SQL

sql

// SqlTraceInterceptor.java (지난주 배포) : SQL을 보내기 직전에 추적 번호를 주석으로 붙인다
public String beforePrepare(String sql) {
    String traceId = TraceContext.current().traceId();      // 요청마다 다르다 (16자리)
    return "/* trace_id=" + traceId + " */ " + sql;
}

-- 주문 상세 화면의 SQL (원래 문장 · 바꾸지 않았다)
SELECT o.ORD_SEQ, o.ORD_DT, o.ORD_ST, o.ORD_AMT, d.ITM_ID, d.ORD_QTY, d.UNT_PRC
  FROM T_ORD o, T_ORD_DET d
 WHERE o.ORD_SEQ = :1
   AND d.ORD_SEQ = o.ORD_SEQ

실행계획 학습용 예시

xplan

[배포 전후 같은 시간대 한 시간 · V$SYSSTAT 증가분]
                                  배포 전        배포 후
  execute count                 3,602,000      3,598,400
  parse count (total)           3,571,300      3,569,900
  parse count (hard)                9,800      3,566,200
  parse time cpu (cs)               2,100        428,500
  CPU used by this session (cs)   168,400        593,600

[배포 후 V$SQL · 주문 상세 문장을 찾아본 것]
  SQL_ID          EXECUTIONS  SQL_TEXT (앞부분)
  5a1c9f0d2k7wq            1  /* trace_id=4bf92f3577b34da6 */ SELECT o.ORD_SEQ, o.ORD_DT, o.ORD_ST, …
  g83m0x2bn1v5s            1  /* trace_id=7d0e41a9c2f35b18 */ SELECT o.ORD_SEQ, o.ORD_DT, o.ORD_ST, …
  1qw7z4c9h0d2u            1  /* trace_id=e19a5b0c77d24f63 */ SELECT o.ORD_SEQ, o.ORD_DT, o.ORD_ST, …
  …

[한 번 실행의 계획 (배포 전후가 같다)]
------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |              |      1 |        |      2 |00:00:00.01 |       7 |
|   1 |  NESTED LOOPS                        |              |      1 |      2 |      2 |00:00:00.01 |       7 |
|   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 |
|   4 |   TABLE ACCESS BY INDEX ROWID BATCHED| T_ORD_DET    |      1 |      2 |      2 |00:00:00.01 |       4 |
|*  5 |    INDEX RANGE SCAN                  | PK_T_ORD_DET |      1 |      2 |      2 |00:00:00.01 |       3 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("O"."ORD_SEQ"=:1)
   5 - access("D"."ORD_SEQ"=:1)

문제

SQL을 바꾸지 않았는데 하드 파싱이 실행 수만큼 늘어난 이유를 위 자료로 설명하시오.
추적 기능은 살리면서 문장이 공유되도록 고치시오.

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

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

모범답안

모범 답안 SQL

sql

// SqlTraceInterceptor.java : SQL 텍스트는 건드리지 않는다 · 추적 번호는 세션 속성으로 넘긴다
public String beforePrepare(String sql) {
    return sql;                                             // 문장 텍스트는 늘 같다
}

public void beforeExecute(Connection conn) throws SQLException {
    conn.setClientInfo("OCSID.CLIENTID", TraceContext.current().traceId());   // V$SESSION.CLIENT_IDENTIFIER
    conn.setClientInfo("OCSID.ACTION", "OrderDetail");                         // V$SESSION.ACTION
}

-- 주문 상세 화면의 SQL : 값이 바뀌지 않는 고정 주석은 괜찮다 (문장은 하나로 유지된다)
SELECT /* OrderDetailDao.find */ o.ORD_SEQ, o.ORD_DT, o.ORD_ST, o.ORD_AMT, d.ITM_ID, d.ORD_QTY, d.UNT_PRC
  FROM T_ORD o, T_ORD_DET d
 WHERE o.ORD_SEQ = :1
   AND d.ORD_SEQ = o.ORD_SEQ

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

xplan

[고친 뒤 같은 시간대 한 시간 (학습용 예시)]
  parse count (hard)               9,600
  parse time cpu (cs)              2,050
  CPU used by this session (cs)  167,900    (CPU 사용률 41% → 12%)
  V$SQL                          주문 상세 문장 부모 1 · 실행 약 21만
  V$SESSION.CLIENT_IDENTIFIER    요청마다 추적 번호가 보인다 (ASH와 10046 트레이스에도 남는다)

모범 답안 서술

오라클은 SQL 텍스트로 같은 문장인지 가리는데, 주석도 텍스트의 일부다. 인터셉터가 요청마다 다른 trace_id를 주석으로 앞에 붙였으므로, 문장 본문과 바인드 변수는 그대로여도 실행할 때마다 처음 보는 문장(다른 SQL_ID)이 됐다. V$SQL에 주석만 다른 부모가 실행 1번씩 줄지어 있고, parse count (hard)가 9,800 → 3,566,200으로 실행 수(약 360만)와 거의 같아졌다. 실행계획과 일량(한 번 7블록)은 그대로이고, 늘어난 CPU(168,400 → 593,600cs)의 대부분은 parse time cpu(2,100 → 428,500cs)다. 바인드 변수를 써도 텍스트가 다르면 공유되지 않는다. 추적 번호는 SQL 텍스트 밖으로 뺀다. JDBC setClientInfo("OCSID.CLIENTID", …)로 넘기면 V$SESSION.CLIENT_IDENTIFIER에 보이고 ASH와 10046 트레이스에도 남으므로, 요청과 SQL을 그대로 이어 볼 수 있다. 화면 이름처럼 값이 바뀌지 않는 고정 주석은 남겨도 된다. 문장 텍스트가 하나로 유지되기 때문이다. 고친 뒤 하드 파싱은 시간당 약 9,600번으로, CPU 사용률은 41% → 12%로 돌아간다.

해설

주석도 텍스트다. 공백, 대소문자, 주석, 리터럴 중 하나만 달라도 다른 부모 커서가 된다(교재 11화 §4). 교재 실습은 이 성질을 거꾸로 이용해 측정마다 새 문장을 만들었다.
같은 함정은 힌트에도 있다. 요청마다 다른 값을 넣어 힌트를 만들면(/*+ QB_NAME(q_4bf9…) */ 같은 식) 똑같이 문장이 갈라진다.
세션 속성(MODULE, ACTION, CLIENT_IDENTIFIER)은 AWR과 ASH에서 SQL을 화면 이름으로 묶어 볼 때도 쓴다(교재 16화). 다만 커서에 남는 MODULE과 ACTION은 그 커서가 처음 파싱될 때의 값이다.
CURSOR_SHARING = FORCE는 리터럴만 바인드 자리로 바꿀 뿐 주석은 그대로 두므로 이 문제를 고치지 못한다.

상황 ​

테이블과 인덱스 ​

원본 SQL ​

실행계획 학습용 예시 ​

문제 ​

모범 답안 SQL ​

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

모범 답안 서술 ​

해설 ​

관련 교재 ​

상황