생략한 타입 선언은 행마다 쿼리 한 번으로 청구된다

출처: 토스 기술블로그 — Spring JDBC 성능 문제, 네트워크 분석으로 파악하기

정산 배치의 bulk insert가 100만 건에 18분 걸렸다. 애플리케이션 로그에는 insert 말고 아무것도 찍히지 않았다. TCP 패킷을 뜯어보고서야 정체 모를 select가 계속 나가는 게 보였다. 원문을 읽고 정리한 내용과 내 생각을 함께 적는다.

문제

토스페이먼츠 정산 플랫폼은 스프링 배치와 JDBC로 가맹점의 정산 거래 건을 처리한다. 대량 insert는 NamedParameterJdbcTemplate.batchUpdate()로 짰다.

@Component
class SettlementStepRepository(
    @Qualifier("settlementJdbcTemplate")
    private val jdbc: NamedParameterJdbcTemplate,
) {
    @Transactional
    fun insertAll(steps: List<SettlementStep>) {
        val namedParameters = steps.map { it.toSqlParam() }
        jdbc.batchUpdate(
            """
            INSERT INTO SETTLEMENT_STEP
            (....)
            VALUES
            (....)
            """.trimIndent(),
            namedParameters.toTypedArray(),
        )
    }
}

원문의 표현대로 “정말 흔하게 볼 수 있는” 구현이다. 이 리포지터리를 쓰는 ItemWriter가 5,000개 객체를 넣는 데 1분 넘게 걸렸다. 100만 건짜리 배치는 18분이었다.

코드에 이상한 곳이 없다는 게 이 사건의 출발점이다. 조회도 계산도 외부 호출도 없이 넣는 일만 하는 Writer 단계다. 로그 레벨을 올려 JDBC가 실행하는 쿼리를 전부 찍어봐도 insert 외에는 나오지 않았다. 볼 수 있는 것을 다 봤는데 느린 이유가 안 보이는 상태였다.

분석

저자는 데이터베이스와의 통신 중에 뭔가 막히고 있다고 보고 WireShark로 로컬 데이터베이스 호스트의 TCP 패킷을 잡았다. bulk insert가 나가기 전에 같은 테이블에 대한 select가 다량으로 계속해서 실행되고 있었다.

경로는 NamedParameterJdbcTemplate.batchUpdate()에서 시작해 JdbcTemplate.batchUpdate(), PreparedStatementCreatorFactory.setValues(), StatementCreatorUtils.setParameterValue()를 거쳐 setParameterValueInternal()로 내려간다. 마지막 함수의 끝은 두 갈래다. 값이 null이면 setNull(), 아니면 setValue().

문제는 setNull() 안에 있다.

private static void setNull(PreparedStatement ps, int paramIndex, int sqlType, @Nullable String typeName)
        throws SQLException {

    if (sqlType == SqlTypeValue.TYPE_UNKNOWN || (sqlType == Types.OTHER && typeName == null)) {
        boolean callGetParameterType = false;
        boolean useSetObject = false;
        Integer sqlTypeToUse = null;
        ...
        if (callGetParameterType) {
            try {
                sqlTypeToUse = ps.getParameterMetaData().getParameterType(paramIndex);
            }
            catch (SQLException ex) { ... }
        }
        ...
    }
    else if (typeName != null) {
        ps.setNull(paramIndex, sqlType, typeName);
    }
    else {
        ps.setNull(paramIndex, sqlType);  // 실제로는 예외 폴백을 감싼 try 블록 안에 있다
    }
}

첫 줄의 조건을 그대로 읽으면 이 함수가 무엇을 묻는지가 보인다. TYPE_UNKNOWN은 파라미터에 SQL 타입이 선언되지 않았다는 표시다. 비싼 경로로 들어가는 조건은 값이 null이라는 게 아니라 타입을 안 적었다는 것이다. 타입이 선언돼 있으면 맨 아래 else에서 ps.setNull(paramIndex, sqlType)을 바로 부르고 끝난다. 데이터베이스에 물어볼 일이 없다.

타입을 모르면 물어봐야 한다. 그래서 ps.getParameterMetaData().getParameterType(paramIndex)를 부르는데, 이 호출의 비용은 드라이버가 정한다. 저자가 쓰던 Oracle 드라이버의 OracleParameterMetaData.getParameterMetaData()는 파라미터 메타데이터를 알아낼 SQL을 그 자리에서 만들어 var1.prepareStatement(var7)로 실행한다. 패킷에 찍히던 select가 이것이다.

// OracleParameterMetaData.class
try {
    var7 = var6.getParameterMetaDataSql();  // metadata를 가져오기 위한 sql 생성
}
catch (Exception var14) {
    var7 = null;
}
...
var8 = var1.prepareStatement(var7);  // 쿼리 실행

왜 로그에는 안 찍혔나

이 select는 애플리케이션이 만든 쿼리가 아니다. 드라이버가 자기 안에서 만들어 자기가 실행한 쿼리다. Spring의 JDBC 로깅은 JdbcTemplate이 실행하는 문장을 찍는 물건이라 그 아래 층에서 생긴 문장을 볼 수 없다. 로그 레벨을 아무리 올려도 나오지 않았던 이유다.

다만 패킷 캡처가 유일한 길이었던 건 아니다. 데이터베이스 쪽에서 봤다면 — Oracle이라면 v$sql 같은 것 — 이 메타데이터 쿼리는 그대로 잡혔을 것이다. 원문은 “네트워크 분석”을 방법론으로 내세우지만 실제로 통한 건 패킷 그 자체가 아니라 경계 반대편에서 봤다는 사실이다. 자기 코드가 만든 것만 보여주는 도구는 그 바깥에서 생긴 비용을 못 본다.

명세는 비용을 말하지 않는다

getParameterMetaData()는 이름이 getter다. getter는 싸다는 게 자바를 쓰는 사람들의 관습이다. JDBC 명세는 그 관습을 보증하지 않는다. Spring은 행마다 도는 루프 안에서 이걸 부른다. MySQL 드라이버에서는 실제로 싸고 Oracle 드라이버에서는 쿼리 한 번이다. 어느 쪽도 명세를 위반하지 않았다.

원문이 MySQL과 비교한 대목이 이 차이를 보여준다. ClientPreparedStatement.getParameterMetaData()는 this.parameterMetaData가 null일 때만 객체를 만들고 그다음부터는 만들어둔 것을 돌려준다. Oracle의 OraclePreparedStatement.getParameterMetaData()는 메타데이터를 소유하지 않고 매번 OracleParameterMetaData.getParameterMetaData(this.sqlObject, this.connection, this)를 새로 부른다. 같은 인터페이스인데 한쪽은 필드 읽기고 한쪽은 왕복이다.

화이트리스트에 Oracle은 없다

이건 2024년 글이지만 지금 Spring에서도 사정이 같다. Spring 6.1부터 shouldIgnoreGetParameterType이 boolean에서 @Nullable Boolean으로 바뀌어 세 가지 상태를 갖는다. 플래그가 아예 설정돼 있지 않으면 드라이버 이름을 보고 갈라진다.

if (shouldIgnoreGetParameterType != null) {
    callGetParameterType = !shouldIgnoreGetParameterType;
}
else {
    String jdbcDriverName = ps.getConnection().getMetaData().getDriverName();
    if (jdbcDriverName.startsWith("PostgreSQL")) {
        sqlTypeToUse = Types.NULL;
    }
    else if (jdbcDriverName.startsWith("Microsoft") && jdbcDriverName.contains("SQL Server")) {
        sqlTypeToUse = Types.NULL;
        useSetObject = true;
    }
    else {
        callGetParameterType = true;
    }
}

PostgreSQL과 SQL Server는 이름으로 특수 취급해서 getParameterType 호출을 건너뛴다. 프레임워크가 드라이버 이름 문자열 비교로 비용을 우회하는 셈인데, 그 목록에 Oracle은 없다. else로 떨어져 예전과 똑같이 물어보러 간다. 원문의 문제는 최신 버전에서도 그대로 유효하다.

해결

원문이 추린 처방은 둘이다. spring.jdbc.getParameterType.ignore를 true로 두어 메타데이터 조회를 아예 끄거나, 파라미터를 넘길 때 SqlType을 적어주거나. 저자는 두 번째를 골랐다. 전체 시스템에 영향을 줄 수 있는 Spring 설정 변경이 내키지 않았다. 값이 null이 되는 경우가 제한적이고 예외적이라 타입 명시로 충분하다고 판단했다.

return MapSqlParameterSource()
    .addValue("originId", internalOriginId)
    .addValue("authDate", authDate)
    .addValue("cancelDate", cancelDate, Types.NULL)

두 처방이 실제로 무엇을 하는지 소스로 따라가 보면 조금 다른 그림이 나온다. ignore=true면 callGetParameterType이 false가 되어 sqlTypeToUse가 null로 남는다. 그러면 그 아래 “database-specific checks” 블록이 sqlTypeToUse = Types.NULL로 채운다. Oracle은 Informix, DB2, jConnect, SQLServer, Derby 어느 분기에도 걸리지 않으니 최종 호출은 ps.setNull(paramIndex, Types.NULL)이다. 저자가 Types.NULL을 선언해서 도달하는 곳과 정확히 같은 호출이다.

두 처방은 Oracle에서 같은 JDBC 호출로 수렴한다. 차이는 무엇을 호출하느냐가 아니라 적용 범위에 있다. 설정은 JVM 전체에 걸리고 타입 선언은 그 파라미터 하나에 걸린다. 덧붙이면 ignore=true 경로는 그 과정에서 ps.getConnection().getMetaData()를 두 번 부른다. 로컬 호출이라 싸지만 공짜는 아니다. 저자의 선택은 옳았다. 다만 옳은 이유는 저자가 댄 이유와 다르다. 두 처방의 효과는 같고 범위만 다르기 때문이다.

그 설정은 application.yml 키가 아니다

원문은 “Spring 내에서 spring.jdbc.getParameterType.ignore를 true로 설정해서 적용할 수 있어요”라고만 적는다. Spring Boot를 쓰는 사람이 이 문장을 읽으면 application.yml에 적는다. 아무 일도 일어나지 않는다.

이 값은 SpringProperties가 읽는다. SpringProperties는 클래스패스 루트의 spring.properties 파일과 System.getProperty()만 본다. Boot의 Environment와는 별개의 물건이라 application.yml이나 application.properties에 쓴 키는 여기에 닿지 않는다. 실제로 넣으려면 JVM 인자로 주거나,

java -Dspring.jdbc.getParameterType.ignore=true -jar app.jar

클래스패스 루트에 spring.properties를 두거나,

spring.jdbc.getParameterType.ignore=true

코드에서 SpringProperties.setFlag(...)를 부르는 방법이 있다. 게다가 StatementCreatorUtils는 이 값을 static 초기화 블록에서 한 번만 읽으니 그 클래스가 로딩되기 전에 설정이 끝나 있어야 한다. 잘못 넣으면 예외도 경고도 없다. 그냥 조용히 아무 효과가 없다.

Types.NULL은 올바른 타입이 아니다

여기서부터는 원문에 없는 이야기다.

MapSqlParameterSource.addValue(name, value, sqlType)로 붙인 타입은 그 파라미터의 선언 타입이 된다. 값이 null인 행에서는 의도대로 동작한다. 문제는 값이 null이 아닌 행이다. 그때는 setNull()이 아니라 setValue()로 간다. Types.NULL은 상수값이 0이라 VARCHAR, NVARCHAR, CLOB, DECIMAL, BOOLEAN, DATE, TIME, TIMESTAMP 어느 분기에도 걸리지 않고 TYPE_UNKNOWN도 아니다. 마지막 else로 떨어진다.

else {
    // Fall back to generic setObject call.
    try {
        // Try generic setObject call with SQL type specified.
        ps.setObject(paramIndex, inValue, sqlType);
    }
    catch (SQLFeatureNotSupportedException ex) {
        ps.setObject(paramIndex, inValue);
    }
}

cancelDate는 취소된 거래에서는 값이 있는 컬럼이다. 그 행에서는 실제 날짜 값이 “SQL NULL 타입”으로 선언된 채 드라이버에 넘어간다. 드라이버가 이걸 어떻게 받아주는지는 확인해보지 않았다. 예외를 내는지, 조용히 형변환하는지, SQLFeatureNotSupportedException으로 fallback을 타는지 모른다.

실제 컬럼 타입을 적으면 양쪽이 다 맞는다. Types.TIMESTAMP를 선언하면 값이 null일 때는 ps.setNull(i, Types.TIMESTAMP)로, 값이 있을 때는 setTimestamp 분기로 간다. Types.NULL은 메타데이터 조회 분기를 피하는 아무 값으로서 동작한 것이지 올바른 타입이라서 동작한 게 아니다.

타입을 정하는 건 0번 행이다

NamedParameterJdbcTemplate.batchUpdate()를 다시 보면 눈에 걸리는 줄이 있다.

ParsedSql parsedSql = getParsedSql(sql);
PreparedStatementCreatorFactory pscf = getPreparedStatementCreatorFactory(parsedSql, batchArgs[0]);

getPreparedStatementCreatorFactory는 NamedParameterUtils.buildSqlParameterList(parsedSql, paramSource)로 선언 파라미터 목록을 만든다. 넘어간 paramSource는 batchArgs[0]이다. 5,000행짜리 배치의 타입 선언을 0번 행 하나가 정한다. 나머지 4,999행은 값만 제공하고 타입에는 관여하지 않는다.

이게 함정이 되는 경우가 있다. 값이 null일 때만 타입을 붙이는 매퍼는 자연스러워 보인다.

val params = MapSqlParameterSource()
    .addValue("originId", internalOriginId)
    .addValue("authDate", authDate)

if (cancelDate == null) params.addValue("cancelDate", null, Types.TIMESTAMP)
else params.addValue("cancelDate", cancelDate)

0번 행의 cancelDate가 우연히 null이 아닌 배치에서는 이 파라미터에 타입이 선언되지 않는다. 나머지 4,999행에 들어 있는 null이 전부 메타데이터 왕복을 낸다. 0번 행이 null인 배치에서는 아무 일도 없다. 같은 코드가 데이터 순서에 따라 빠르거나 느리다. 값과 무관하게 무조건 타입을 붙여야 한다.

결과

파라미터 타입을 명시한 뒤 100만 건 내외의 거래 데이터를 넣는 배치가 18분에서 2분으로 줄었다. 원문이 내놓은 수치는 이것뿐이다.

여기서 왕복 하나의 값을 역산해볼 수 있다. 사라진 시간이 16분이고 대상이 100만 행이다. null 파라미터가 행당 하나였다고 가정하면 왕복 하나가 대략 1밀리초다. 1밀리초에 100만을 곱하면 1,000초, 약 16.7분이니 자릿수는 맞아떨어진다. 원문이 밝히지 않은 값을 결과에서 거꾸로 뽑은 추정이라 그대로 믿을 값은 아니다. null 파라미터가 여러 개였다면 왕복당 시간은 그만큼 짧아진다.

가정을 세워야 했던 건 원문이 밝히지 않은 게 많아서다. cancelDate가 null인 행의 비율이 얼마였는지, 파라미터 중 몇 개가 nullable이었는지, 같은 배치를 MySQL에서 돌리면 어땠는지가 없다. 마지막 항목이 특히 아쉽다. MySQL 드라이버가 메타데이터를 재사용한다는 것까지 소스로 확인해놓고 실측은 하지 않았다. 그 수치가 있었다면 Oracle 드라이버가 원인이라는 진단이 코드 읽기가 아니라 측정으로 뒷받침됐을 것이다.

그럼에도 이 글의 값어치는 수치에 있지 않다. 흔한 batchUpdate 한 줄에서 드라이버 내부의 prepareStatement까지 이어지는 경로를 끊기지 않게 그려낸 데 있다. 경로를 한번 보고 나면 비율이나 임계값 없이도 판단이 선다. 비용의 단위가 배치가 아니라 행 곱하기 null 파라미터라는 것만 알면 나머지는 자기 데이터에 대입하면 된다.

인상 깊었던 점

이 블로그에 @Transactional을 쓸 상황을 최대한 줄이자와 캐시를 비우는 비용은 캐시 크기가 아니라 Redis 전체 크기다를 쓴 적이 있다. 앞은 @Transactional(readOnly = true) 하나가 부수 쿼리 여섯 개를 만드는 이야기고 뒤는 allEntries = true 하나가 전체 키스페이스 스캔을 만드는 이야기다.

셋 다 작은 표기가 큰 비용으로 이어지는 사건이지만 이 글은 자리가 다르다. 앞의 둘은 적은 것의 비용이 감춰진 사례다. allEntries = true는 최소한 코드에 보이는 토큰이다. 리뷰에서 “이거 전체 무효화인데 괜찮나요”라고 물으려면 그 자리에 손가락을 얹으면 된다. 여기서 비싼 것은 안 적은 것이다. .addValue("cancelDate", cancelDate)에는 지적할 대상이 없다. 리뷰어가 무언가를 짚으려면 없는 것을 알아채야 한다.

없는 것을 알아채기 어려운 이유는 그 정보가 원래 있었기 때문이기도 하다. Kotlin에서 cancelDate는 타입이 선언된 필드다. MapSqlParameterSource에 담기면서 Object가 된다. 값이 null이면 클래스조차 남지 않는다. StatementCreatorUtils에는 javaTypeToSqlTypeMap이 있어서 값이 있으면 자바 타입에서 SQL 타입을 유도하지만 null에는 유도할 자바 타입이 없다. 컴파일 타임에 확정돼 있던 정보를 Map 경계에서 버리고 런타임에 네트워크 왕복으로 되사는 구조다. Types.NULL을 적는 해결책은 버린 정보를 손으로 다시 적어주는 것이다.

그러니 이 문제를 예방하는 방법은 타입을 잘 적자는 다짐이 아니라 타입이 지나가는 경계를 줄이는 쪽에 있다. 정적 타입 언어를 쓰면서 Map<String, Object>로 값을 옮기는 자리가 있으면 거기서 타입은 사라진다. 사라진 자리를 프레임워크가 어떻게 메우는지, 그 비용이 얼마인지는 문서에도 시그니처에도 적혀 있지 않다. 이번 사건에서는 그게 행마다 쿼리 한 번이었다.