fetch() - 1 : ResultSetType 분석

목차

1. fetch()란?
2. fetch()를 뜯어보자
3. rs.next()를 뜯어보자
4. ResultSet의 타입을 뜯어보자
5. 로컬에서 로그를 남겨보자
6. 로그가 포착됐다

1. fetch()란?

QueryDSL을 사용하면서 아래와 같은 fetch()는 흔하게 본다.

    public List<Member> findActiveMembers() {
        return jpaQueryFactory
                .selectFrom(m)
                .where(m.active.isTrue())
                .orderBy(m.id.asc())
                .fetch(); 
    }

코드를 보면 짐작이 가겠지만 fetch()는 List로 결과를 반환할 때 사용된다.
fetch()와 파생된 메서드는 다양하게 있다. 예시로 단건 조회시 fetchOne(), 최초 1건만 조회시 fetchFirst(), 개수 조회시 fetchCount() 등이 있다.

여기까지만 보면 누구든 흔하게 사용할 수 있는 메서드다.
이제 fetch()를 뜯어보자.

2. fetch()를 뜯어보자

AbstractSQLQuery에 선언된 fetch()를 뜯어보면 다음과 같다.

    @SuppressWarnings("unchecked")
    @Override
    public List<T> fetch() {
        // 변수 선언문은 생략...

        try {
            listeners.preRender(context);
            SQLSerializer serializer = serialize(false);
            queryString = serializer.toString();
            logQuery(queryString, serializer.getConstants());
            context.addSQL(getSQL(serializer));
            listeners.rendered(context);

            listeners.notifyQuery(queryMixin.getMetadata());
            constants = serializer.getConstants();

            listeners.prePrepare(context);
            try (PreparedStatement stmt = getPreparedStatement(queryString)) {
                setParameters(stmt, constants, serializer.getConstantPaths(), queryMixin.getMetadata().getParams());
                context.addPreparedStatement(stmt);
                listeners.prepared(context);

                listeners.preExecute(context);
                try (ResultSet rs = stmt.executeQuery()) {
                    listeners.executed(context);
                    lastCell = null;
                    final List<T> rv = new ArrayList<T>();
                    if (expr instanceof FactoryExpression) {
                        FactoryExpression<T> fe = (FactoryExpression<T>) expr;
                        while (rs.next()) {
                            if (getLastCell) {
                                lastCell = rs.getObject(fe.getArgs().size() + 1);
                                getLastCell = false;
                            }
                            rv.add(newInstance(fe, rs, 0));
                        }
                    } else if (expr.equals(Wildcard.all)) {
                        while (rs.next()) {
                            Object[] row = new Object[rs.getMetaData().getColumnCount()];
                            if (getLastCell) {
                                lastCell = rs.getObject(row.length);
                                getLastCell = false;
                            }
                            for (int i = 0; i < row.length; i++) {
                                row[i] = rs.getObject(i + 1);
                            }
                            rv.add((T) row);
                        }
                    } else {
                        while (rs.next()) {
                            if (getLastCell) {
                                lastCell = rs.getObject(2);
                                getLastCell = false;
                            }
                            rv.add(get(rs, expr, 1, expr.getType()));
                        }
                    }
                    return rv;
                } 
            // 하위 내용은 생략...

여기서 눈여겨 볼 포인트는 ResultSet과 rs.next()이다.
ResultSet은 DB 쿼리 결과 집합을 가리키는 커서(cursor) 객체다.
이 커서는 행 단위로 이동하면서 데이터를 읽어오고, rs.next()를 호출할 때마다 커서가 다음 행으로 이동 -> 이동이 성공하면 true, 마지막을 지나면 false를 반환한다.

커서(cursor)라는 개념에 집중해보니, 어드민 개발 시절 숱하게 작성했던 Native Query가 생각난다.

--- 커서(>)를 사용하여 다음 10개의 레코드를 가져오는 쿼리 (마지막 ID를 기준으로)
SELECT * FROM users WHERE id > 10 ORDER BY id LIMIT 10;

커서 방식의 페이지네이션은 커서의 범위에 따라 시간복잡도가 O(1) 또는 O(limit)으로 극단적으로도 갈릴 수 있다.
이렇듯 범위가 주는 영향력이 중요한데, fetch() 메서드는 커서의 범위를 어떻게 설정하는걸까?

한번 rs.next()를 파헤쳐보자.

3. rs.next()를 뜯어보자

next()의 공식 javadoc

rs.next()를 파고들어가면 다음 설명이 나온다. 편의상 인상깊은 부분만 한국어로 해석했다.

1. 커서 이동
커서를 현재 위치에서 한 행 앞으로 이동시킵니다.
ResultSet 커서는 처음에 첫 번째 행 이전에 위치합니다.
따라서 next()를 처음 호출하면 커서가 첫 번째 행으로 이동하고,
두 번째 호출하면 두 번째 행으로 이동하는 식으로 진행됩니다.

2. 마지막 행 뒤로 이동
next() 호출 결과가 false를 반환하면,
커서는 마지막 행 뒤(after last row)에 위치하게 됩니다.
이 상태에서 "현재 행"을 필요로 하는 메서드를 호출하면 SQLException이 발생합니다.

3. TYPE_FORWARD_ONLY 타입인 경우
ResultSet의 타입이 TYPE_FORWARD_ONLY라면,
마지막 행 뒤에서 다시 next()를 호출했을 때
JDBC 드라이버 구현에 따라 false를 반환할 수도 있고
SQLException을 던질 수도 있습니다. (→ 벤더별 동작 차이 존재)

4. 입력 스트림 처리
현재 행에 대해 열려 있는 입력 스트림(InputStream)이 있다면,
next() 호출 시 자동으로 닫힙니다.

눈여겨 볼 포인트는 3번의 TYPE_FORWARD_ONLY이다.
나는 fetch()를 사용할때 커서와 관련된 타입을 지정해 준 적이 없다.
그런데 공식문서에서는 ResultSet의 타입이 TYPE_FORWARD_ONLY인 경우에 대해 설명하고 있으며, 벤더별 동작 차이가 존재한다고도 언급한다.

어떤 종류들이 있는걸까? 한번 파헤쳐보자.

4. ResultSet의 타입을 뜯어보자

먼저 Oracle Java의 공식문서 (Click)를 확인해보자.

아래와 같이 ResultType의 기본값을 명시해주고 있다.

The default ResultSet type is TYPE_FORWARD_ONLY.

실제로 테스트 용 로그를 통해 ResultSet의 getType()을 출력해본 결과, 아래와 같이 나온다.

========== RESULTSET TYPE : 1003 // 1003 -> TYPE_FORWARD_ONLY

TYPE_FORWARD_ONLY가 어떤 속성을 갖고있는지 알아야한다.

친절하게도 해당 문서에는 TYPE_FORWARD_ONLY가 어떤 속성을 갖고있는지 설명해주고 있다.
편의상 한국어로 번역한 내용은 다음과 같다.

📌 TYPE_FORWARD_ONLY
결과 집합은 스크롤할 수 없습니다.
커서는 첫 번째 행 이전에서 시작해서 마지막 행 뒤까지 오직 앞으로만 이동할 수 있습니다.
결과 집합에 포함되는 행들은 쿼리가 실행될 당시 또는 행이 검색될 때 기준으로, 조건을 만족하는 데이터가 채워집니다.

📌 TYPE_SCROLL_INSENSITIVE
결과 집합은 스크롤할 수 있습니다.
커서는 현재 위치 기준으로 앞/뒤로 이동할 수 있고, 특정 절대 위치(absolute position)로도 이동할 수 있습니다.
결과 집합은 열려 있는 동안 기본 데이터 소스에 가해진 변경 사항에는 영향을 받지 않습니다.
따라서 쿼리 실행 시점(또는 검색 시점)에 조건을 만족하는 행들이 고정됩니다.

📌 TYPE_SCROLL_SENSITIVE
결과 집합은 스크롤할 수 있습니다.
커서는 현재 위치 기준으로 앞/뒤 이동과 절대 위치 이동이 모두 가능합니다.
결과 집합은 열려 있는 동안 기본 데이터 소스에 가해진 변경 사항을 반영합니다.
즉, DB에서 데이터가 바뀌면 ResultSet에도 그 변화가 나타납니다.

그렇다면 내 코드는 Default로 TYPE_FORWARD_ONLY가 실행되는걸까?

 at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:734)
        at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:439)
        at com.zaxxer.hikari.pool.HikariProxyResultSet.next(HikariProxyResultSet.java)
        at com.querydsl.sql.AbstractSQLQuery.fetch(AbstractSQLQuery.java:451)

덤프로 확인된 스택 트레이스를 분석해 본 결과, 내부적으로 TYPE_SCROLL_SENSITIVE가 채택된 것 같다.
왜 그런걸까? 로컬에서 한번 테스트를 해보자

5. 로컬에서 로그를 남겨보자

로컬에서 스택 트레이스를 분석하기 전에, 먼저 인라이닝을 막기 위해 JVM 설정을 변경했다.

-XX:-Inline
-XX:CompileCommand=dontinline,com/zaxxer/hikari/pool/HikariProxyResultSet::next
-XX:TieredStopAtLevel=1
-XX:-BackgroundCompilation

이렇게 하는 이유는 ？ (Click)

• XX:-Inline → JIT(Just In Time) 최적화로 유지되던 인라인을 끄기 위함
• XX:CompileCommand=dontinline,com/zaxxer/hikari/pool/HikariProxyResultSet::next → 원하는 로그가 남도록 안전벨트 역할을 수행하며, 없어도 무방함
• XX:TieredStopAtLevel=1 → 티어드 컴파일을 C1(저수준/경량 최적화) 수준에서 멈춤. 세이프 포인트 폴이 촘촘하다고 이해하면 됨
• XX:-BackgroundCompilation → 백그라운드 코드가 필요시 슬금슬금 C2 컴파일로 중간 프레임 모양을 자제시킴

사실 -XX:-Inline이 핵심이고, 나머지는 보조 역할을 한다.

이렇게 해서 2가지 목적을 달성시킨다.

1. 쿼리 시점을 기점으로 최대한 많은 stack trace를 남기기
   • 타겟 thread를 고주파로 샘플링 + 문제의 구간을 루프로 길게 유지
2. 원하는 로그 InsensitiveScrollableResultSet.next가 출력될때까지 호출 반복

물론 이렇게해도 API 호출의 A~Z까지의 로그를 확인할 수는 없지만, 부분 부분 파편화 된 로그를 반복적으로라도 확인할 수 있다.

public List<TestDto> getTests(String memId) {
    QTestBase test = new QTestBase("TEST_ENTITY");
    final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(getClass());

    final Thread target = Thread.currentThread();
    final java.util.concurrent.CountDownLatch firstTick = new java.util.concurrent.CountDownLatch(1);
    final java.util.concurrent.atomic.AtomicBoolean running = new java.util.concurrent.atomic.AtomicBoolean(true);
    final java.util.concurrent.atomic.AtomicBoolean hitInsensitive = new java.util.concurrent.atomic.AtomicBoolean(false);

    Thread sampler = new Thread(() -> {
        Thread.currentThread().setPriority(Math.min(Thread.NORM_PRIORITY + 1, Thread.MAX_PRIORITY));
        int maxFrames = 100000;

        while (running.get()) {
            if (firstTick.getCount() > 0) firstTick.countDown();

            StackTraceElement[] st = target.getStackTrace();
            StringBuilder sb = new StringBuilder(1024).append("=== STACK SAMPLE ===\n");
            for (int i = 0; i < Math.min(st.length, maxFrames); i++) {
                sb.append("  at ").append(st[i]).append('\n');
            }
            String stackStr = sb.toString();
            log.debug(stackStr);

            if (stackStr.contains("InsensitiveScrollableResultSet.next")) {
                log.warn(">>> Insensitive detected by sampler! Stopping...");
                hitInsensitive.set(true);
                running.set(false);
                break;
            }

            java.util.concurrent.locks.LockSupport.parkNanos(10_000L);
        }
    }, "stack-sampler");
    sampler.setDaemon(true);
    sampler.start();

    log.debug("=== STACK (start) ===\n{}", formatStack(Thread.currentThread().getStackTrace()));

    final long maxDurationNanos = java.util.concurrent.TimeUnit.SECONDS.toNanos(30);
    final int maxIterations = 100_000;
    final long start = System.nanoTime();

    List<TestDto> lastResult = java.util.Collections.emptyList();
    int it = 0;
    try {
        firstTick.await(50, java.util.concurrent.TimeUnit.MILLISECONDS);

        while (!hitInsensitive.get()) {
            it++;
            lastResult = getTestsQuery()
                .where(test.memId.eq(memId))
                .fetch();

            java.util.concurrent.locks.LockSupport.parkNanos(100_000L);

            if (System.nanoTime() - start > maxDurationNanos) {
                log.warn(">>> Stop due to maxDuration ({}s) reached. iterations={}",
                    java.util.concurrent.TimeUnit.NANOSECONDS.toSeconds(maxDurationNanos), it);
                break;
            }
            if (it >= maxIterations) {
                log.warn(">>> Stop due to maxIterations reached. iterations={}", it);
                break;
            }
            if (!running.get() && !hitInsensitive.get()) {
                log.warn(">>> Sampler stopped without Insensitive hit. iterations={}", it);
                break;
            }
        }

        if (hitInsensitive.get()) {
            log.warn(">>> Exiting loop because Insensitive was detected. iterations={}", it);
        }

        return lastResult;

    } catch (InterruptedException ie) {
        Thread.currentThread().interrupt();
        throw new RuntimeException(ie);
    } finally {
        log.debug("=== STACK (end) ===\n{}", formatStack(Thread.currentThread().getStackTrace()));
        running.set(false);
        java.util.concurrent.locks.LockSupport.unpark(sampler);
        try { sampler.join(200); } catch (InterruptedException ignored) { Thread.currentThread().interrupt(); }
    }
}

// 보조: 스택 포매터
private static String formatStack(StackTraceElement[] st) {
    StringBuilder sb = new StringBuilder(1024);
    int limit = Math.min(st.length, 80);
    for (int i = 0; i < limit; i++) sb.append("  at ").append(st[i]).append('\n');
    return sb.toString();
}

단지 로컬에서 원하는 횟수만큼 빠르게 호출하기 위해 GPT의 힘을 빌린 코드이니, 참고로만 활용하자.

6. 로그가 포착됐다

로컬에서 동일한 로그가 확인됐다.

 at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:734)
        at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:439)
        at com.zaxxer.hikari.pool.HikariProxyResultSet.next(HikariProxyResultSet.java)
        at com.querydsl.sql.AbstractSQLQuery.fetch(AbstractSQLQuery.java:451)

그러나 이상한 점은, next() 호출시에도 여전히 ForwardOnlyResultSet으로 wrapper 클래스가 적용됐다는 것이다.

심지어 디버깅 포인트를 ForwardOnlyResultSet <-> InsensitiveScrollableResultSet로 걸어둘 경우, 전자는 항상 디버깅이 걸리지만 후자는 절대 안걸린다.

대체 어디서 ForwardOnlyResultSet -> InsensitiveScrollableResultSet으로 전환이 되는걸까?
원인은 다름이 아닌 ForwardOnlyResultSet에 있었다.

보다시피 ForwardOnlyResultSet은 InsensitiveScrollableResultSet을 상속받는다.
그리고 우리가 사용중인 next() 메서드는 ForwardOnlyResultSet에는 존재하지 않는다.
InsensitiveScrollableResultSet에만 존재하므로, 거기에 선언된 next()를 호출하게 된다.

그래서 로그에서는 InsensitiveScrollableResultSet 로그가 계속해서 찍혔던 것이다.

어처구니 없는 포인트에서 원인이 발견됐지만, 해당 이슈를 분석했던 덕에 강제로 ResultSetType을 지정해 줄 필요는 없게됐다.