본사 주문 조회는 한 쪽에 20건인데, 쪽을 넘길 때마다 2.7초가 걸리고 WAS가 GC로 멈칫한다

중급SELECT버거587 / 700

상황

버거 본사 운영팀의 「주문 조회」 화면은 기간(최대 31일)을 넣으면 최근 주문부터 한 쪽에 20건씩 보여 주고, 목록 위에 「총 n건」을 띄운다. 2016년에 만든 화면으로, 쪽 번호를 누를 때마다 DAO가 다시 불린다. 지난달 운영팀이 40명으로 늘자 쪽을 넘길 때마다 2~3초가 걸리고 화면 서버(WAS)가 Full GC로 멈칫한다는 신고가 잦아졌다. DBA는 "그 SQL은 인덱스를 잘 타고 실행당 DB 시간이 0.2초예요. WAS 쪽 문제 아닌가요?"라고 한다.

테이블과 인덱스

ORD 주문: 1,000,000행 · 22,422블록 · ORD_NO · ORD_DT VARCHAR2(8) · ORD_HMS VARCHAR2(6) · SHOP_NO · 날짜순 적재 · 2013년 11월 41,666건(테이블 약 934블록)
인덱스 ORD_PK (ORD_NO) · ORD_X01 (ORD_DT, ORD_HMS): BLEVEL 2 · 리프 약 3,570블록(11월은 약 149블록) · CF 22,223 · 통계 최신
WAS와 DB는 같은 IDC에 있다(왕복 약 0.45ms). JDBC fetch size는 드라이버 기본값 10이다.

원본 SQL

sql

// OrderSearchDao.java (2016) : 쪽 번호를 받아 그 쪽의 20건과 총건수를 함께 돌려준다
public Page<OrderRow> search(String from, String to, int page) throws SQLException {
    String sql = "SELECT ORD_NO, ORD_DT, ORD_HMS, SHOP_NO FROM ORD "
               + "WHERE ORD_DT BETWEEN ? AND ? "
               + "ORDER BY ORD_DT DESC, ORD_HMS DESC";
    try (PreparedStatement ps = conn.prepareStatement(sql,
             ResultSet.TYPE_SCROLL_INSENSITIVE, ResultSet.CONCUR_READ_ONLY)) {
        ps.setString(1, from);
        ps.setString(2, to);
        ResultSet rs = ps.executeQuery();
        rs.last();                                  // 맨 끝 행으로 가서
        int total = rs.getRow();                    // 그 행 번호가 총건수
        List<OrderRow> rows = new ArrayList<>();
        if (rs.absolute((page - 1) * 20 + 1)) {     // 그 쪽의 첫 행으로 돌아와 20건
            do { rows.add(map(rs)); } while (rows.size() < 20 && rs.next());
        }
        return new Page<>(rows, total);
    }
}

실행계획 학습용 예시

xplan

[1쪽 한 번 · 2013-11-01 ~ 2013-11-30 · 세션 통계 증가분 (V$SESSTAT)]
  화면 응답 (APM)                           2.71 초
  execute count                                1
  SQL*Net roundtrips to/from client        4,169
  bytes sent via SQL*Net to client          2.9 MB
  session logical reads                    9,425
  DB time                                   0.21 초
  SQL*Net message from client              4,168번 · 1.88 초 (평균 0.45 ms)

[V$SQL · 같은 실행]  EXECUTIONS 1 · FETCHES 4,167 · ROWS_PROCESSED 41,666 · BUFFER_GETS 9,419
[이어서 37쪽을 누른 실행]  위와 같다 (ROWS_PROCESSED 41,666 · roundtrips 4,169 · 2.69 초)

[WAS · 지난달 대비 · 운영팀 40명]
  힙 사용량 1.2 GB → 3.4 GB · Full GC 시간당 2번 → 31번 (한 번에 1~2초 멈춤)
  힙 덤프 상위 : JDBC 드라이버가 ResultSet마다 쌓아 둔 행 캐시 (요청 하나에 41,666행, 약 9 MB)

[DISPLAY_CURSOR · 같은 실행 (모든 페치를 합친 값)]
-----------------------------------------------------------------------------------------------
| Id  | Operation                      | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |         |      1 |        |  41666 |00:00:00.19 |    9419 |
|*  1 |  FILTER                        |         |      1 |        |  41666 |00:00:00.19 |    9419 |
|   2 |   TABLE ACCESS BY INDEX ROWID  | ORD     |      1 |  41100 |  41666 |00:00:00.18 |    9419 |
|*  3 |    INDEX RANGE SCAN DESCENDING | ORD_X01 |      1 |  41100 |  41666 |00:00:00.03 |    4318 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:1<=:2)
   3 - access("ORD_DT">=:1 AND "ORD_DT"<=:2)

문제

화면은 20건만 그리는데 한 번에 41,666행과 왕복 4,169번이 오가는 이유를 위 코드와 숫자로 설명하시오. WAS 힙이 차오르는 이유도 쓰시오.
화면(그 쪽의 20건과 총건수)이 바뀌지 않게 DAO와 SQL을 고치고, 고친 뒤의 왕복 수와 블록 수를 쓰시오. 총건수를 어떻게 셀지와 그 대가도 쓰시오.

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

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

모범답안

모범 답안 SQL

sql

// OrderSearchDao.java : 앞으로만 읽는 ResultSet(기본값) · 그 쪽의 20건만 묻는다 · 총건수는 따로 센다
private static final String PAGE_SQL =
      "SELECT ORD_NO, ORD_DT, ORD_HMS, SHOP_NO FROM ("
    + "  SELECT ROWNUM AS RN, x.* FROM ("
    + "    SELECT ORD_NO, ORD_DT, ORD_HMS, SHOP_NO FROM ORD"
    + "     WHERE ORD_DT BETWEEN ? AND ?"
    + "     ORDER BY ORD_DT DESC, ORD_HMS DESC) x"
    + "   WHERE ROWNUM <= ?)"
    + " WHERE RN > ?";

private static final String COUNT_SQL =
      "SELECT COUNT(*) FROM ORD WHERE ORD_DT BETWEEN ? AND ?";

public List<OrderRow> page(String from, String to, int page) throws SQLException {
    try (PreparedStatement ps = conn.prepareStatement(PAGE_SQL)) {
        ps.setFetchSize(21);                     // 20행과 '끝'을 첫 왕복에 함께 받는다
        ps.setString(1, from);
        ps.setString(2, to);
        ps.setInt(3, page * 20);
        ps.setInt(4, (page - 1) * 20);
        try (ResultSet rs = ps.executeQuery()) {
            List<OrderRow> rows = new ArrayList<>(20);
            while (rs.next()) rows.add(map(rs));
            return rows;
        }
    }
}

// 검색 버튼을 눌렀을 때만 부른다 · 쪽을 넘길 때는 화면이 받아 둔 총건수를 다시 쓴다
public int count(String from, String to) throws SQLException {
    try (PreparedStatement ps = conn.prepareStatement(COUNT_SQL)) {
        ps.setString(1, from);
        ps.setString(2, to);
        try (ResultSet rs = ps.executeQuery()) {
            rs.next();
            return rs.getInt(1);
        }
    }
}

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

xplan

[그 쪽의 20건 · 1쪽 (ROWNUM <= 20, RN > 0)]
------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |         |      1 |        |     20 |00:00:00.01 |       5 |
|*  1 |  VIEW                             |         |      1 |     20 |     20 |00:00:00.01 |       5 |
|*  2 |   COUNT STOPKEY                   |         |      1 |        |     20 |00:00:00.01 |       5 |
|   3 |    VIEW                           |         |      1 |     20 |     20 |00:00:00.01 |       5 |
|*  4 |     FILTER                        |         |      1 |        |     20 |00:00:00.01 |       5 |
|   5 |      TABLE ACCESS BY INDEX ROWID  | ORD     |      1 |  41100 |     20 |00:00:00.01 |       5 |
|*  6 |       INDEX RANGE SCAN DESCENDING | ORD_X01 |      1 |     20 |     20 |00:00:00.01 |       3 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN">:4)
   2 - filter(ROWNUM<=:3)
   4 - filter(:1<=:2)
   6 - access("ORD_DT">=:1 AND "ORD_DT"<=:2)

[총건수 · 검색할 때 한 번 · ORD_X01만 읽는다]
------------------------------------------------------------------------------------
| Id  | Operation          | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |         |      1 |        |      1 |00:00:00.01 |     152 |
|   1 |  SORT AGGREGATE    |         |      1 |      1 |      1 |00:00:00.01 |     152 |
|*  2 |   FILTER           |         |      1 |        |  41666 |00:00:00.01 |     152 |
|*  3 |    INDEX RANGE SCAN| ORD_X01 |      1 |  41100 |  41666 |00:00:00.01 |     152 |
------------------------------------------------------------------------------------

[고친 뒤 · 세션 통계 (학습용 예시)]
                        SQL*Net roundtrips   session logical reads   받은 행   화면 응답
  검색 (1쪽 + 총건수)                    2                     157        21   0.02 초
  쪽 넘기기 (37쪽)                       1                      22        20   0.01 초
  WAS 힙 3.4 GB → 1.2 GB 언저리 · Full GC 시간당 31번 → 2번

모범 답안 서술

오라클 서버의 커서는 앞으로만 읽는다. TYPE_SCROLL_INSENSITIVE로 연 ResultSet에서 뒤로 돌아가거나 건너뛰는 일은 JDBC 드라이버가 받은 행을 WAS 메모리에 캐시해 두고 그 안에서 해 준다. 그래서 rs.last()로 맨 끝 행에 가려면 드라이버가 41,666행을 모두 받아 캐시에 쌓아야 한다. fetch size가 기본값 10이라 페치가 4,167번, 왕복이 4,169번이다(V$SQL의 FETCHES 4,167, ROWS_PROCESSED 41,666). 화면은 그중 20행만 그리고, 나머지는 총건수 하나를 얻으려고 받은 셈이다. 쪽을 넘길 때마다 DAO가 다시 불리므로 37쪽을 눌러도 같은 일이 되풀이된다. DBA 말대로 SQL의 계획은 나쁘지 않다. ORD_X01을 거꾸로 읽어 정렬도 없고 DB 시간은 0.21초다. 나머지 시간은 DB가 다음 페치를 기다린 왕복 대기(SQL*Net message from client 4,168번, 1.88초)와 드라이버가 행을 쌓는 시간이다. 정렬이 없는 계획이라 페치마다 읽던 블록을 다시 잡아서, 인덱스 149블록과 테이블 934블록이면 될 일이 Buffers 9,419가 됐다. 힙이 차오르는 이유도 같다. 요청 하나가 41,666행(약 9MB)을 ResultSet이 닫힐 때까지 힙에 들고 있다. 운영팀 40명이 쪽을 넘길 때마다 이만큼씩 쌓였다 버려지니 힙이 1.2GB에서 3.4GB로 늘고 Full GC가 시간당 31번이 됐다. 고친 판은 기본값인 앞으로만 읽는 ResultSet으로 열고, 그 쪽의 20건만 묻는 Top-N 문장(ROWNUM <= 쪽 × 20, RN > (쪽 - 1) × 20)으로 바꾼다. 정렬 순서와 같은 ORD_X01을 거꾸로 읽다가 COUNT STOPKEY에서 멈추므로 1쪽은 5블록이다. fetch size를 21로 주면 20행과 끝 표시가 첫 왕복에 함께 온다. 총건수는 SELECT COUNT(*) 문장을 따로 두고 검색할 때 한 번만 센다. ORD_X01만 읽어 152블록이고, 쪽을 넘길 때는 화면이 받아 둔 값을 다시 쓴다. 검색 한 번은 왕복 4,169 → 2번, Buffers 9,419 → 157, 응답 2.71 → 0.02초가 되고, 쪽 넘기기는 왕복 1번에 22블록이다. 대가도 있다. 총건수는 검색한 순간의 값이라 쪽을 넘기는 사이에 들어온 주문은 반영되지 않는다. COUNT의 일은 건수에 비례하므로 기간 상한(31일)을 풀면 상한까지만 세는 방법(ROWNUM <= 10001로 세고 "1만 건 이상"으로 표시)으로 바꾼다. ROWNUM 페이징은 뒤 쪽으로 갈수록 앞의 행을 읽고 버리지만(37쪽은 740행), 운영팀이 수백 쪽을 넘기는 일은 드물어 받아들인다.

해설

오라클 JDBC 드라이버는 스크롤 가능한 ResultSet을 클라이언트 쪽 캐시로 구현한다. 서버 커서는 앞으로만 가기 때문이다. TYPE_SCROLL_SENSITIVE는 여기에 행을 다시 읽어 오는 일까지 더한다. 목록 화면에서 스크롤 ResultSet을 쓸 이유는 거의 없다.
총건수를 얻으려고 끝까지 받는 모양은 rs.last()만이 아니다. while (rs.next()) cnt++나 ORM의 list.size()도 같은 양을 받는다. 앞으로만 읽어도 받는 행 수는 같다.
COUNT(*) OVER ()를 쪽 문장에 넣으면 문장은 하나로 줄지만, 41,666건을 다 읽어야 총건수가 나오므로 COUNT STOPKEY가 사라진다. 쪽을 넘길 때마다 건수를 다시 세는 셈이다.
총건수를 어디까지 정확히 보여 줄지는 화면 주인과 정할 일이다. 상한까지만 세기, 통계의 행수, 다음 쪽이 있는지만 보여 주기의 비용은 교재 09화 §10에 있다(SORT-001).
ORD_DT, ORD_HMS는 유일하지 않아 같은 초에 들어온 주문이 쪽 경계에서 겹치거나 빠질 수 있다. 정확히 하려면 정렬 끝에 ORD_NO를 더하고 인덱스도 (ORD_DT, ORD_HMS, ORD_NO)로 맞춘다(교재 09화 §7).

상황 ​

테이블과 인덱스 ​

원본 SQL ​

실행계획 학습용 예시 ​

문제 ​

모범 답안 SQL ​

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

모범 답안 서술 ​

해설 ​

관련 교재 ​

상황