search

kruize / autotune-results

Recommendations and Results from Autotune
Apache License 2.0
3 stars 6 forks source link

Generate a throughput config with Autotune for TechEmpower results Round21 #28

Open kusumachalasani opened 2 years ago

kusumachalasani commented 2 years ago
kusumachalasani commented 2 years ago

Created a TFB image (kusumach/tfb-qrh:2.4.1.F) with Quarkus 2.4.1.F using the branch https://github.com/franz1981/FrameworkBenchmarks/tree/round21_2.4.1.Final to try some runs.

When the load is run with hyperfoil-0.16/wrk, I see following errors. But with Quarkus version 1.13.2.Final no errors are observed. @franz1981 @johnaohara Is there anything I need to enable to avoid the errors with Quarkus 2.4.1.F ?

2022-05-16 06:19:42,243 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-102) SQL Error: 0, SQLState: 53300
2022-05-16 06:19:42,243 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-102) FATAL: remaining connection slots are reserved for non-replication superuser connections
2022-05-16 06:19:42,229 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-30) HTTP Request to /db failed, error id: c5209e56-2d3e-4c6b-9558-4aa69028540d-11: org.jboss.resteasy.spi.UnhandledException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
        at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:106)
        at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:372)
        at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:218)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:519)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
        at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
        at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:135)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:90)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:198)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:162)
        at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:104)
        at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:285)
        at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:267)
        at org.hibernate.loader.entity.plan.PaddedBatchingEntityLoader.load(PaddedBatchingEntityLoader.java:86)
        at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:4521)
        at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4506)
        at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4497)
        at org.hibernate.internal.StatelessSessionImpl.get(StatelessSessionImpl.java:188)
        at org.hibernate.internal.StatelessSessionImpl.get(StatelessSessionImpl.java:180)
        at org.hibernate.internal.StatelessSessionImpl.get(StatelessSessionImpl.java:170)
        at io.quarkus.benchmark.repository.WorldRepository.singleStatelessWorldLoad(WorldRepository.java:74)
        at io.quarkus.benchmark.repository.WorldRepository.findSingleAndStateless(WorldRepository.java:46)
        at io.quarkus.benchmark.resource.DbResource.randomWorldForRead(DbResource.java:76)
        at io.quarkus.benchmark.resource.DbResource.db(DbResource.java:33)
        at io.quarkus.benchmark.resource.DbResource_Subclass.db$$superforward1(DbResource_Subclass.zig:194)
        at io.quarkus.benchmark.resource.DbResource_Subclass$$function$$1.apply(DbResource_Subclass$$function$$1.zig:24)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
        at io.quarkus.resteasy.runtime.QuarkusRestPathTemplateInterceptor.restMethodInvoke(QuarkusRestPathTemplateInterceptor.java:31)
        at io.quarkus.resteasy.runtime.QuarkusRestPathTemplateInterceptor_Bean.intercept(QuarkusRestPathTemplateInterceptor_Bean.zig:323)
        at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
        at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
        at io.quarkus.benchmark.resource.DbResource_Subclass.db(DbResource_Subclass.zig:294)
        at jdk.internal.reflect.GeneratedMethodAccessor43.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
        at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
        at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
        ... 15 more
Caused by: org.postgresql.util.PSQLException: FATAL: remaining connection slots are reserved for non-replication superuser connections
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2565)
        at org.postgresql.core.v3.QueryExecutorImpl.readStartupMessages(QueryExecutorImpl.java:2677)
        at org.postgresql.core.v3.QueryExecutorImpl.<init>(QueryExecutorImpl.java:147)
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:273)
        at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51)
        at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:225)
        at org.postgresql.Driver.makeConnection(Driver.java:465)
        at org.postgresql.Driver.connect(Driver.java:264)
        at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204)
        at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470)
        at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        ... 1 more
franz1981 commented 2 years ago

Probably need to increase the configured max_connections value of postgres (see https://github.com/TechEmpower/FrameworkBenchmarks/blob/1e45c83008a2b1b8d44556283dffa3d96de7e650/toolset/databases/postgres/postgresql.conf#L64)

I suggest to use https://github.com/franz1981/FrameworkBenchmarks/tree/round_21 in the last commit, that's getting rid of other errors and has applied the most recent patches, but beware: in order to make it works there are few JVM args that cannot be omitted ie -Dquarkus.http.accept-backlog=-1 (in frameworks/Java/quarkus/run_quarkus.sh)

johnaohara commented 2 years ago

As Franz said, the max number of connections have been opened, The default max is 100 iirc. If you have defined the upper bound on connection pool size to over 100, then this error is likely.

But another question is, if the max bounds are the same as previous runs, why do we now need to open more than 100 connections to perform the test?

franz1981 commented 2 years ago

if the max bounds are the same as previous runs, why do we now need to open more than 100 connections to perform the test?

Not sure It's like the previous one anymore, I remember Sanne changed them in https://github.com/franz1981/FrameworkBenchmarks/blob/3d273a8edfe9bb022784938f9286546cad42a226/frameworks/Java/quarkus/resteasy-hibernate/src/main/resources/application.properties#L13

johnaohara commented 2 years ago

quarkus.datasource.jdbc.max-size is a autotune tuneable: quarkus.datasource.jdbc.max-size,

Initial size of 512 would immediately cause the issue, if the pool is set to pre-fill

kusumachalasani commented 2 years ago

The run which throwed the above error doesn't use any tunables. Makes sense why it did throw this error. In the image I created previously with 1.13.2.F, I commented out those variables as it needs to be set through autotune. Will pick up the latest code suggested by @franz1981 and try it by commenting out tunables from application.properties.

Below are the quarkus tunables and their ranges which are in my list now.

Do I need to increase the upper bound quarkusdatasourcejdbcmaxsize to 512 by updating my postgres server ? Or can I continue with the ranges we are using for previous experiments ?

{"name": "quarkusthreadpoolcorethreads", "value_type": "integer", "upper_bound": 33, "lower_bound": 1, "step": 4},
{"name": "quarkusthreadpoolqueuesize", "value_type": "integer", "upper_bound": 10000, "lower_bound": 0, "step": 10}, 
{"name": "quarkusdatasourcejdbcminsize", "value_type": "integer", "upper_bound": 12, "lower_bound": 1, "step": 1},
{"name": "quarkusdatasourcejdbcmaxsize", "value_type": "integer", "upper_bound": 90, "lower_bound": 12, "step": 1},

Also, autotune tunables in this experiment will be Quarkus and JVM tunables. Will be keeping cpu and memory constant(requests and limits being set to 4c - 4GB). Is that okay ?