SQLServer JDBC의 이상한 동작

2017-04-24

DB -> HDFS 작업 관련 삽질 중인데 SQLServer의 JDBC 드라이버 동작이 생각과 다르게 동작하는 부분이 있어 공유해보려고 합니다. 공유의 목적은 이런 사항이 있으니 DB 선정 시 신중해야 할 것 같다는 것과 제가 잘못 사용하고 있는 부분이 있는지 원래 그런 것인지 독자들의 의견을 들어 보려는 것입니다.

참고로 SQLServer는 거의 사용해보지 않았고 지금도 사용하지는 않지만 HDFS로 저장해야 하는 데이터 중 SQLServer에 저장된 데이터가 있어 어쩔수 없이 보고 있습니다. 즉, SQLServer에 대해서는 하나도 모르는 상황입니다.

SQLServer JDBC의 이상한 동작

다음과 같은 코드를 이용하여 SQLServer의 데이터를 가져오려고 하였습니다. (sqljdbc4-4.0.jar 사용)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
Connection conn = DriverManager.getConnection("jdbc:sqlserver://localhost:1433;databaseName=TEST", "", "");
// created_at 컬럼에는 index 가 없음
String sql = "select * from test_table where created_at between '2017-04-01 00:00:00.000' and 2017-04-01 23:59:59.999";
Statement stmt = conn.createStatement();
LOG.info("01. Start run query");
ResultSet rs = stmt.executeQuery(sql);
LOG.info("02. Finish run query");
int count = 0;
while (true) {
 long time1 = System.currentTimeMillis();
 boolean hasNext = rs.next();
 long time2 = System.currentTimeMillis();
 if (!hasNext) {
   break;
 }
 count++;
 if (count % 1000 == 0) {
   LOG.info(count + " fetched");
 }
 if (time2 - time1 > 1000) {
   LOG.info("rs.next() is too slow: " + (time2 - time1)/1000 + " seconds. " + count + " rows fetched");
 }
}
LOG.info("03.Completed: " + count + " fetched.");

필자가 예상한 시나리오는 created_at 컬럼에 index가 없기 때문에 stmt.executeQuery(sql) 이 문장 실행 시 오래 걸리고 일단 "02.Finish run query" 메시지가 나온 다음에는 빠르게 처리할 것을 예상했습니다. MySQL로 비슷한 질의를 수행하면 이렇게 동작합니다.

하지만 SQLServer에 위 프로그램을 실행하면 다음과 같은 형태로 처리합니다.

stmt.executeQuery(sql) 수행에 수분 소요
일정 갯수의 row를 처리한 다음 rs.next()에서 수분 소요

위 프로그램의 로그는 다음과 같이 나타납니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17/04/23 17:17:41 INFO: 01. Start run query
17/04/23 17:18:51 INFO: 02. Finish run query
17/04/23 17:19:02 INFO: rs.next() is too slow: 11 seconds. 16 rows fetched
17/04/23 17:19:44 INFO: rs.next() is too slow: 41 seconds. 62 rows fetched
17/04/23 17:19:48 INFO: rs.next() is too slow: 4 seconds. 85 rows fetched
17/04/23 17:19:57 INFO: rs.next() is too slow: 8 seconds. 108 rows fetched
17/04/23 17:19:59 INFO: rs.next() is too slow: 2 seconds. 131 rows fetched
17/04/23 17:20:01 INFO: rs.next() is too slow: 1 seconds. 178 rows fetched
17/04/23 17:20:12 INFO: rs.next() is too slow: 11 seconds. 201 rows fetched
17/04/23 17:20:14 INFO: rs.next() is too slow: 1 seconds. 268 rows fetched
17/04/23 17:20:38 INFO: rs.next() is too slow: 24 seconds. 290 rows fetched
17/04/23 17:20:57 INFO: rs.next() is too slow: 19 seconds. 313 rows fetched
17/04/23 17:21:06 INFO: rs.next() is too slow: 7 seconds. 382 rows fetched
17/04/23 17:21:08 INFO: rs.next() is too slow: 2 seconds. 405 rows fetched
17/04/23 17:21:14 INFO: rs.next() is too slow: 5 seconds. 497 rows fetched
17/04/23 17:21:36 INFO: rs.next() is too slow: 21 seconds. 542 rows fetched

이런 패턴으로 동작하는데 이를 통해 유추해보면 SQLServer는 질의 실행 시 전체 결과 Set을 서버에 가지고 있지 않고 어느 정도의 Row 갯수만 가지고 있고 클라이언트가 이를 모두 fetch 하면 다시 질의가 실행되는 이런 방식으로 동작하는 것 같다는 느낌을 받았습니다.

SQLServer 공식 사이트에서의 가이드

구글링을 해보아도 비슷한 증상에 대한 질문만 있고 뚜렷한 답변이 없어 SQLServer 공식 사이트의 가이드를 확인해보았습니다.

SQLServer JDBC 성능 관련 사이트: https://docs.microsoft.com/en-us/sql/connect/jdbc/working-with-statements-and-result-sets

문서 내용 중에 다음 내용을 찾았는데 default 값이라고 되어 있습니다.

If you must deal with large result sets, consider using an adaptive response buffering by setting the connection string property responseBuffering=adaptive, which is the default mode.

아래 코드로 "adaptive" 라는 것을 확인했습니다.

1
2
SQLServerStatement stmt = (SQLServerStatement)conn.createStatement();
LOG.info("ResponseBuffering: " + stmt.getResponseBuffering());

다시 다음 링크에서 ResponseBuffering 이라는 것에 대해 확인해보았습니다.

ResponseBuffering: https://docs.microsoft.com/en-us/sql/connect/jdbc/using-adaptive-buffering

글 내용 중에 ResultSet의 Cursor 타입을 적절하게 잘 사용해야 한다는 문구가 있어 Forward Only, Read Only 로 설정해 보았습니다. TYPE_SS_SERVER_CURSOR_FORWARD_ONLY, TYPE_SS_DIRECT_FORWARD_ONLY 두가지 옵션이 있는데 TYPE_SS_DIRECT_FORWARD_ONLY 옵션의 경우 위와 동일하게 동작하는 반면 TYPE_SS_SERVER_CURSOR_FORWARD_ONLY 를 사용하면 "ResultSet rs = stmt.executeQuery(sql);" 이 부분은 빠르게 실행됩니다. 즉 이 명령에 의해서는 실제 서버에서는 SQL이 실행되지 않고 준비만 하는 것 같습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17/04/23 17:39:26 INFO: ResponseBuffering: adaptive
17/04/23 17:39:26 INFO: Start run query
17/04/23 17:39:26 INFO: Finish run query
17/04/23 17:39:45 INFO: rs.next() is too slow: 18 seconds. 1 rows fetched
17/04/23 17:39:48 INFO: rs.next() is too slow: 3 seconds. 129 rows fetched
17/04/23 17:39:57 INFO: rs.next() is too slow: 8 seconds. 257 rows fetched
17/04/23 17:40:01 INFO: rs.next() is too slow: 3 seconds. 385 rows fetched
17/04/23 17:40:24 INFO: rs.next() is too slow: 22 seconds. 513 rows fetched
17/04/23 17:41:35 INFO: rs.next() is too slow: 71 seconds. 641 rows fetched
17/04/23 17:41:51 INFO: rs.next() is too slow: 15 seconds. 769 rows fetched
17/04/23 17:41:53 INFO: rs.next() is too slow: 2 seconds. 897 rows fetched
17/04/23 17:41:53 INFO: 1000 fetched
17/04/23 17:41:55 INFO: rs.next() is too slow: 1 seconds. 1025 rows fetched
17/04/23 17:41:57 INFO: rs.next() is too slow: 2 seconds. 1153 rows fetched
17/04/23 17:41:59 INFO: rs.next() is too slow: 2 seconds. 1281 rows fetched
17/04/23 17:42:12 INFO: rs.next() is too slow: 12 seconds. 1409 rows fetched

위 결과에서 fetched 갯수를 보면 128 이라는 일정한 규칙이 나타납니다. SQLServerResultSet 클래스를 디컴파일해보니 다음과 같이 되어 있습니다.

this.nFetchSize = 1009 == this.resultSetConcurrency?8:128;

resultSetConcurrency는 무슨 값인지는 모르겠지만 Fetch Size의 기본 값이 128 로 설정되는 부분이 있습니다. 이것을 보고 setFetchSize를 통해 한번에 가져오는 Row의 갯수를 지정해보았습니다.

rs.setFetchSize(1000);

결과는 다음과 같습니다.

1
2
3
4
5
6
7
17/04/23 17:44:13 INFO: ResponseBuffering: adaptive
17/04/23 17:44:13 INFO: Start run query
17/04/23 17:44:13 INFO: Finish run query
17/04/23 17:46:44 INFO: rs.next() is too slow: 151 seconds. 1 rows fetched
17/04/23 17:46:44 INFO: 1000 fetched
17/04/23 17:48:19 INFO: rs.next() is too slow: 94 seconds. 1001 rows fetched
17/04/23 17:48:19 INFO: 2000 fetched

보시면 실제 executeStatement() 부분은 빨리 실행하고, 1000 건 단위로 fetch 작업 시 오랜 시간에 걸려 데이터를 가져오는 것을 볼 수 있습니다.

정말로 느린 것일까?

여기까지 테스트를 진행하고 이런 의문점이 들었습니다. SQLServer가 이렇게 동작하는 것이 이상한 것이 아니라 전체 질의 수행 시간은 동일하지 않을까? 예를 들어

MySQL의 경우라면 executeStatement()에 100초가 소요되었고 fetch에는 시간이 소요되지 않은 반면
SQLServer는 executeStatement()에는 시간이 소요되지 않는 반면 fetch의 총합이 100초가 되지 않을까?

이런 가정이라면 사용자 입장에서는 나쁘지 않은 구성입니다. 아직 이 비교는 해보지 못했습니다. 두 데이터베이스의 성능이 다르고 구성이 다르기때문에 BMT 환경이 아닌 실제 운영 환경에서는 비교하기 어렵습니다.

Update: 아래 페이스북 댓글로 @이수열님이 답변을 주셨습니다.

JDBC 문제는 아니구요 Oracle 이나 MSSQL에는 DBMS 자체에 '부분범위처리','전체범위처리' 라는 메카니즘이 있어요. 부분범위처리는 데이타를 끝까지 뒤져서 반환하지 않고 일단 일정량만 검색해서 돌려주고 next 요청이 있을때 그 다음부터 검색해 돌려주는 방식인데, 쿼리문 분석에 따라 반드시 끝까지 뒤져봐야만 할 상황이 아니라면 부분범위처리로 작동합니다. 부분범위처리나 전체범위처리나 끝까지 처리하는 시간은 같다고 보시면 됩니다 ^^

마치며

이글의 앞부분에서도 언급했는데 이 글의 목적이 다르게 동작한다는 것과, 증상을 설명하고, 여러분들의 의견을 듣고자 하는 것이라서 SQLServer가 느리다, 아니면 SQLServer의 JDBC가 느리다 라는 결론은 아닙니다. 이 부분에 대해 명쾌하게 설명해주실 있는 분이나 SQLServer 관계자가 보시면 답변 부탁드립니다.

다음 maven dependency를 사용해도 동일하게 나타남 <dependency> <groupId>com.microsoft.sqlserver</groupId> <artifactId>mssql-jdbc</artifactId> <version>6.1.0.jre8</version> </dependency>

Popit은 페이스북 댓글만 사용하고 있습니다. 페이스북 로그인 후 글을 보시면 댓글이 나타납니다.

SQLServer JDBC의 이상한 동작

SQLServer JDBC의 이상한 동작

SQLServer 공식 사이트에서의 가이드

정말로 느린 것일까?

마치며

김 형준 님의 다른 글

더 보기