When using the wrapper, it seems that this is becoming a bottleneck for database interactions.
Version
main
Expected behavior
Performance should be similar to when not using the wrapper
Actual behavior
All threads block on a global lock in the wrapper.
"pool-11-thread-29" #207 prio=5 os_prio=0 cpu=24970.50ms elapsed=1270.97s tid=0x00007fe5e80293b0 nid=0x273 waiting on condition [0x00007fe42f8f6000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.10/Native Method)
- parking to wait for <0x000000075ba39bb0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.10/LockSupport.java:211)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.10/AbstractQueuedSynchronizer.java:715)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.10/AbstractQueuedSynchronizer.java:938)
at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@17.0.10/ReentrantLock.java:153)
at java.util.concurrent.locks.ReentrantLock.lock(java.base@17.0.10/ReentrantLock.java:322)
at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:236)
at software.amazon.jdbc.wrapper.ConnectionWrapper.prepareStatement(ConnectionWrapper.java:613)
at io.agroal.pool.wrapper.ConnectionWrapper.prepareStatement(ConnectionWrapper.java:658)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:153)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:183)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:155)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.lambda$scroll$1(JdbcSelectExecutor.java:102)
at org.hibernate.sql.exec.spi.JdbcSelectExecutor$$Lambda$2286/0x00007fe629f4b4e8.apply(Unknown Source)
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:231)
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:167)
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:218)
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:98)
at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19)
at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66)
at org.hibernate.internal.ScrollableResultsImpl.next(ScrollableResultsImpl.java:51)
at org.hibernate.query.internal.ScrollableResultsIterator.hasNext(ScrollableResultsIterator.java:33)
at java.util.Iterator.forEachRemaining(java.base@17.0.10/Iterator.java:132)
at java.util.Spliterators$IteratorSpliterator.forEachRemaining(java.base@17.0.10/Spliterators.java:1845)
at java.util.stream.AbstractPipeline.copyInto(java.base@17.0.10/AbstractPipeline.java:509)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@17.0.10/AbstractPipeline.java:499)
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(java.base@17.0.10/ReduceOps.java:921)
at java.util.stream.AbstractPipeline.evaluate(java.base@17.0.10/AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.collect(java.base@17.0.10/ReferencePipeline.java:682)
at org.keycloak.utils.ClosingStream.collect(ClosingStream.java:182)
at org.keycloak.models.jpa.JpaRealmProvider.getClientScopes(JpaRealmProvider.java:1106)
at org.keycloak.models.jpa.JpaRealmProvider.addClientScopes(JpaRealmProvider.java:1068)
at org.keycloak.storage.ClientStorageManager.addClientScopes(ClientStorageManager.java:265)
at org.keycloak.models.cache.infinispan.RealmCacheSession.addClientScopes(RealmCacheSession.java:1417)
at org.keycloak.models.jpa.ClientAdapter.addClientScopes(ClientAdapter.java:356)
at org.keycloak.protocol.AbstractLoginProtocolFactory.lambda$addDefaultClientScopes$2(AbstractLoginProtocolFactory.java:88)
at org.keycloak.protocol.AbstractLoginProtocolFactory$$Lambda$2448/0x00007fe629f8eb88.accept(Unknown Source)
at java.util.stream.Streams$StreamBuilderImpl.forEachRemaining(java.base@17.0.10/Streams.java:411)
at java.util.stream.ReferencePipeline$Head.forEach(java.base@17.0.10/ReferencePipeline.java:762)
at org.keycloak.protocol.AbstractLoginProtocolFactory.addDefaultClientScopes(AbstractLoginProtocolFactory.java:94)
at org.keycloak.protocol.AbstractLoginProtocolFactory.addDefaultClientScopes(AbstractLoginProtocolFactory.java:76)
at org.keycloak.protocol.AbstractLoginProtocolFactory$1.onEvent(AbstractLoginProtocolFactory.java:51)
at org.keycloak.services.DefaultKeycloakSessionFactory.publish(DefaultKeycloakSessionFactory.java:91)
at org.keycloak.models.jpa.ClientAdapter.setProtocol(ClientAdapter.java:266)
at org.keycloak.models.utils.RepresentationToModel.createClient(RepresentationToModel.java:354)
at org.keycloak.models.utils.RepresentationToModel.createClient(RepresentationToModel.java:313)
at org.keycloak.services.managers.ClientManager.createClient(ClientManager.java:82)
at org.keycloak.benchmark.dataset.DatasetResourceProvider.createClients(DatasetResourceProvider.java:983)
at org.keycloak.benchmark.dataset.DatasetResourceProvider.lambda$createClientsImpl$8(DatasetResourceProvider.java:313)
at org.keycloak.benchmark.dataset.DatasetResourceProvider$$Lambda$3376/0x00007fe62a2feb58.run(Unknown Source)
at org.keycloak.models.utils.KeycloakModelUtils.lambda$runJobInTransaction$1(KeycloakModelUtils.java:257)
at org.keycloak.models.utils.KeycloakModelUtils$$Lambda$2230/0x00007fe629ef8880.run(Unknown Source)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:379)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:256)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithTimeout(KeycloakModelUtils.java:398)
at org.keycloak.benchmark.dataset.ExecutorHelper.lambda$addTaskRunningInTransaction$0(ExecutorHelper.java:58)
at org.keycloak.benchmark.dataset.ExecutorHelper$$Lambda$3377/0x00007fe62a2fed80.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.10/Executors.java:539)
at java.util.concurrent.FutureTask.run(java.base@17.0.10/FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.10/ThreadPoolExecutor.java:1136)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.10/ThreadPoolExecutor.java:635)
at java.lang.Thread.run(java.base@17.0.10/Thread.java:840)
How to Reproduce?
In the preparation phase on the nightly run, create a thread dump for using kill -3 1 in the Pod.
Describe the bug
When using the wrapper, it seems that this is becoming a bottleneck for database interactions.
Version
main
Expected behavior
Performance should be similar to when not using the wrapper
Actual behavior
All threads block on a global lock in the wrapper.
How to Reproduce?
In the preparation phase on the nightly run, create a thread dump for using
kill -3 1in the Pod.Anything else?
See upstream issue https://github.com/awslabs/aws-advanced-jdbc-wrapper/issues/921