When querying SQL Server database from Spring Boot JPA using a native query it takes longer than expected. On trace level it's visible that it's stuck when parsing a single row. Jump in time is visible after 14:20:16.436. Result set is ~500 records only. I don't see any GC pauses or anything else in logs.
2024-07-15 14:20:16.436 TRACE 927222 --- [nio-8083-exec-2] o.h.o.r.loading : StandardRowReader#readRow
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (0 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@77b7ad5a
2024-07-15 14:20:16.436 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (1:VARCHAR) -> [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [0] - [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (1 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@1c7ee7bb
2024-07-15 14:20:16.436 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (2:VARCHAR) -> [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [1] - [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (2 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@2f252c36
2024-07-15 14:20:16.436 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (3:VARCHAR) -> [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [2] - [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (3 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@6926f901
2024-07-15 14:20:16.436 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (4:VARCHAR) -> [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [3] - [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (4 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@23315402
2024-07-15 14:20:16.436 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (5:VARCHAR) -> [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [4] - [XXX]
2024-07-15 14:20:16.436 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (5 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@48993ce0
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (6:VARCHAR) -> [XXX]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [5] - [XXX]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (6 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@4e5bed59
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (7:TIMESTAMP) -> [2024-07-14 01:21:00.202]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [6] - [2024-07-14 01:21:00.202]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (7 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@10ebeb62
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (8:INTEGER) -> [9]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [7] - [9]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (8 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@39532c39
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (9:VARCHAR) -> [XXX]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [8] - [XXX]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (9 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@38ac79cf
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (10:TIMESTAMP) -> [2024-07-29 19:00:00.0]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [9] - [2024-07-29 19:00:00.0]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (10 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@298c6aa6
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (11:TIMESTAMP) -> [2024-07-29 20:00:00.0]
2024-07-15 14:20:25.673 DEBUG 927222 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [10] - [2024-07-29 20:00:00.0]
2024-07-15 14:20:25.673 TRACE 927222 --- [nio-8083-exec-2] o.h.o.r.loading : StandardRowReader#afterRow
Detailed TRACE level logs for the stuck record after 16:15:12.718:
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY 5
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.SQLServerResultSet : SQLServerResultSet:26 Getting Column:5
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114945
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114945 Reading 5 from stream offset 0 payload length 5
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114945Enter Closing SimpleInputStream.
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114945 Skipping :0
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114945Exit Closing SimpleInputStream.
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : RETURN XXXX1
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY
2024-07-15 16:15:12.717 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : RETURN false
2024-07-15 16:15:12.718 TRACE 936022 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (5:VARCHAR) -> [XXXX1]
2024-07-15 16:15:12.718 DEBUG 936022 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [4] - [XXXX1]
2024-07-15 16:15:12.718 DEBUG 936022 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (5 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@44693000
2024-07-15 16:15:12.718 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY 6
2024-07-15 16:15:12.718 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.SQLServerResultSet : SQLServerResultSet:26 Getting Column:6
2024-07-15 16:15:12.718 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114946
2024-07-15 16:15:12.718 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114946 Reading 4 from stream offset 0 payload length 4
2024-07-15 16:15:21.560 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114946Enter Closing SimpleInputStream.
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114946 Skipping :0
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.InputStream : com.microsoft.sqlserver.jdbc.SimpleInputStreamID:114946Exit Closing SimpleInputStream.
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : RETURN XXXX
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : RETURN false
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (6:VARCHAR) -> [XXXX]
2024-07-15 16:15:21.561 DEBUG 936022 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [5] - [XXXX]
2024-07-15 16:15:21.561 DEBUG 936022 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (6 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@2e8ced69
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY 7
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.i.SQLServerResultSet : SQLServerResultSet:26 Getting Column:7
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : RETURN 7/14/24, 1:20 AM
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : RETURN false
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] o.h.o.j.extract : extracted value (7:TIMESTAMP) -> [2024-07-14 01:20:59.964]
2024-07-15 16:15:21.561 DEBUG 936022 --- [nio-8083-exec-2] o.h.o.results : Extracted JDBC value [6] - [2024-07-14 01:20:59.964]
2024-07-15 16:15:21.561 DEBUG 936022 --- [nio-8083-exec-2] o.h.o.r.loading : Calling top-level assembler (7 / 11) : org.hibernate.sql.results.graph.basic.BasicResultAssembler@4d015504
2024-07-15 16:15:21.561 TRACE 936022 --- [nio-8083-exec-2] c.m.s.j.ResultSet : ENTRY 8
I've tried profiling, debugging, increasing heap size.
This is stacktrace from the widest column in flamechart for this request starting with repository proxy call:
jdk.proxy2.$Proxy246.findAllByXXX()
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:220)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.data.repository.core.support.MethodInvocationValidator.invoke(MethodInvocationValidator.java:95)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:135)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:392)
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:70)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:143)
org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:164)
org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:158)
org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:170)
org.springframework.data.repository.core.support.RepositoryMethodInvoker$RepositoryQueryMethodInvoker$$Lambda$2486/0x00007f94bd267258.invoke()
org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:137)
org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:149)
org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:92)
org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:129)
org.hibernate.query.Query.getResultList(Query.java:120)
org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:427)
org.hibernate.query.sql.internal.NativeQueryImpl.doList(NativeQueryImpl.java:621)
org.hibernate.query.sql.internal.NativeSelectQueryPlanImpl.performList(NativeSelectQueryPlanImpl.java:138)
org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:65)
org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:76)
org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:83)
org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:209)
org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:203)
org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:93)
org.hibernate.sql.results.graph.basic.BasicResultAssembler.assemble(BasicResultAssembler.java:59)
org.hibernate.sql.results.graph.basic.BasicResultAssembler.extractRawValue(BasicResultAssembler.java:52)
org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.getJdbcValue(RowProcessingStateStandardImpl.java:119)
org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.getCurrentRowValue(JdbcValuesResultSetImpl.java:302)
org.hibernate.type.descriptor.jdbc.BasicExtractor.extract(BasicExtractor.java:44)
org.hibernate.type.descriptor.jdbc.VarcharJdbcType$2.doExtract(VarcharJdbcType.java:118)
com.zaxxer.hikari.pool.HikariProxyResultSet.getString(HikariProxyResultSet.java)
com.microsoft.sqlserver.jdbc.SQLServerResultSet.getString(SQLServerResultSet.java:2568)
com.microsoft.sqlserver.jdbc.SQLServerResultSet.getValue(SQLServerResultSet.java:2091)
com.microsoft.sqlserver.jdbc.SQLServerResultSet.getValue(SQLServerResultSet.java:2105)
com.microsoft.sqlserver.jdbc.Column.getValue(Column.java:190)
com.microsoft.sqlserver.jdbc.DTV.getValue(dtv.java:248)
com.microsoft.sqlserver.jdbc.ServerDTVImpl.getValue(dtv.java:3751)
com.microsoft.sqlserver.jdbc.DDC.convertStreamToObject(DDC.java:801)
com.microsoft.sqlserver.jdbc.SimpleInputStream.getBytes(SimpleInputStream.java:356)
com.microsoft.sqlserver.jdbc.SimpleInputStream.read(SimpleInputStream.java:268)
com.microsoft.sqlserver.jdbc.SimpleInputStream.read(SimpleInputStream.java:307)
com.microsoft.sqlserver.jdbc.TDSReader.readBytes(IOBuffer.java:7078)
com.microsoft.sqlserver.jdbc.TDSReader.ensurePayload(IOBuffer.java:6760)
com.microsoft.sqlserver.jdbc.TDSReader.nextPacket(IOBuffer.java:6788)
com.microsoft.sqlserver.jdbc.TDSReader.readPacket(IOBuffer.java:6840)
com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:2151)
com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.read(IOBuffer.java:1179)
com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.readInternal(IOBuffer.java:1193)
sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1069)
sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1465)
sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:478)
sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:484)
com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.read(IOBuffer.java:1179)
com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.readInternal(IOBuffer.java:1193)
com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.read(IOBuffer.java:1179)
com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.readInternal(IOBuffer.java:1193)
java.net.Socket$SocketInputStream.read(Socket.java:966)
sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:808)
sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:355)
sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:319)
sun.nio.ch.NioSocketImpl.park(NioSocketImpl.java:195)
sun.nio.ch.NioSocketImpl.park(NioSocketImpl.java:186)
sun.nio.ch.Net.poll(Native Method)
Query:
select erfl.xxx1 as xxx1,
erfl.xxx2 as xxx2,
erfl.xxx3 as xxx3,
erfl.xxx4 as xxx4,
erfl.xxx5 as xxx5,
erfl.xxx6 as xxx6,
erfl.last_change_date as lastChangeDate,
erfl.units as units,
erfl.source as source,
vsp.eta as eta,
vsp.etd as etd
from table1 erfl
join table2 vsp on erfl.xxx1 = vsp.xxx1 and erfl.xxx2 = vsp.xxx2 and erfl.xxx3 = vsp.xxx3 and erfl.xxx4 = vsp.xxx4
where erfl.xxx4 in :xxx4
and erfl.xxx5 in :xxx5
and vsp.etd > :cutOffDate
and vsp.xxx6 in :xxx6
Table1:
create table table1
(
id bigint identity
constraint PK_empty_release_full_loading
primary key,
xxx1 varchar(5),
xxx2 varchar(10) not null,
xxx3 varchar(5) not null,
xxx4 varchar(5) not null,
xxx5 varchar(5) not null,
xxx6 varchar(4) not null,
last_change_date datetime2(6) not null,
units int not null,
source varchar(50) not null,
created_timestamp datetime2(6) not null
)
Table2:
create table table2
(
id bigint identity
constraint PK_vessel_schedule_port
primary key,
xxx2 varchar(10) not null,
xxx3 varchar(5) not null,
xxx4 varchar(5) not null,
xxx5 varchar(5) not null,
xxx1 varchar(5) not null,
eta datetime2(6) not null,
etd datetime2(6) not null,
vvl varchar(20) not null,
created_timestamp datetime2(6) not null
)
But my problem is not average, but being stuck on a single one out of few hundreds.