Increasing the JDBC connection pool size
In the event of performing load and stress tests on OpenIAM with OpenIAM API /idp/rest/api/auth/public/login, you might run into an error indicating the pool size for connector is too small.
Problem
For instance, you use 4 rProxys that balance their respective openiam-uis and connect to 3 OpenIAM (backends) machines. When using the JMeter tool pointing to the F5 that balances the 4 rProxys. When carrying about 5000 requests/second, several database errors might occur and cause connections to fail giving the following error.
Unable to acquire JDBC Connection
javax.xml.ws.soap.SOAPFaultException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connectionat org.apache.cxf.jaxws.JaxWsClientProxy.mapException(JaxWsClientProxy.java:195) ~[cxf-rt-frontend-jaxws-3.3.6.jar:3.3.6]at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy. java:145) ~[cxf-rt-frontend-jaxws-3.3.6.jar:3.3.6]at com.sun.proxy.$Proxy244.getLoginByManagedSys(Unknown Source) ~[?:?]at org.openiam.ui.rest.api.mvc.AuthenticationRestController.loginPost(AuthenticationRestController. java:332) ~[classes/:?]at org.openiam.ui.rest.api.mvc.AuthenticationRestController$$$FastClassBySpringCGLIB$$1e6d3f3d.invoke(<generated>) ~[classes/:?]at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy. java:218) ~[spring-core-5.3.18.jar:5.3.18]at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) ~[spring-aop-5.3.18.jar:5.3.18]at org.springframework.aop.framework. ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.18.jar:5.3.18]at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.18. jar:5.3.18]at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89) ~[spring-aop-5.3.18.jar:5.3.18]at org.openiam.ui.audit.AuditPointcut.processAuditLog(AuditPointcut. java:86) ~[openiam-ui-intf-4.2.1.13.jar:?]at jdk.internal.reflect.GeneratedMethodAccessor990.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method. invoke(Method.java:566) ~[?:?]at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634) ~[spring-aop-5.3.18.jar:5.3.18]
Solution:
The problem may occur since the default property value is org.openiam.jdbc.connection.pool.size.max=20.
To resolve it, increase the value calculating based on following formula:
Concurrent users: XTPS per user: 1.5Avg query time: 0.5 secondsPool Size = (X * 1.5 * 0.5) * 1.2
Once you calculated proper max pool size, override this property for openiam-esb, openiam-auth, and workflow services - as these services use DB connection.
How to override default max pool size, which is 20 by default:
- Add into services/start_esb.sh along with existing -D properties add one more -Dspring.config.location=$HOME_DIR/conf/application.esb.properties,
- create file with following content:
org.openiam.jdbc.connection.pool.size.max=25
- restart service, make sure that old process is stopped and new is the only one running
- additionally you can add line into the file logging.level.com.zaxxer.hikari=DEBUG as it will help to monitor connections
Once you restart service you should see following logs:
2024-01-19 06:21:58.841 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : Driver class com.mysql.cj.jdbc.Driver found in Thread context class loader org.springframework.boot.loader.LaunchedURLClassLoader@4c70fda82024-01-19 06:21:58.863 WARN 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - idleTimeout has been set but has no effect because the pool is operating as a fixed size pool.2024-01-19 06:21:58.863 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - configuration:2024-01-19 06:21:58.866 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : allowPoolSuspension.............false2024-01-19 06:21:58.867 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : autoCommit......................true2024-01-19 06:21:58.867 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : catalog.........................none2024-01-19 06:21:58.868 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : connectionInitSql...............none2024-01-19 06:21:58.868 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : connectionTestQuery.............none2024-01-19 06:21:58.868 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : connectionTimeout...............300002024-01-19 06:21:58.869 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : dataSource......................none2024-01-19 06:21:58.869 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : dataSourceClassName.............none2024-01-19 06:21:58.869 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : dataSourceJNDI..................none2024-01-19 06:21:58.870 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : dataSourceProperties............{password=<masked>, prepStmtCacheSqlLimit=2048, cachePrepStmts=true, prepStmtCacheSize=250}2024-01-19 06:21:58.871 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : driverClassName................."com.mysql.cj.jdbc.Driver"2024-01-19 06:21:58.871 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : exceptionOverrideClassName......none2024-01-19 06:21:58.871 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : healthCheckProperties...........{}2024-01-19 06:21:58.872 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : healthCheckRegistry.............none2024-01-19 06:21:58.872 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : idleTimeout.....................3000002024-01-19 06:21:58.873 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : initializationFailTimeout.......12024-01-19 06:21:58.873 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : isolateInternalQueries..........false2024-01-19 06:21:58.874 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : jdbcUrl.........................jdbc:mysql://localhost:3306/activiti?autoReconnect=true&useUnicode=true&characterEncoding=utf8&connectionCollation=utf8_general_ci&serverTimezone=UTC2024-01-19 06:21:58.874 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : leakDetectionThreshold..........02024-01-19 06:21:58.874 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : maxLifetime.....................6000002024-01-19 06:21:58.874 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : maximumPoolSize.................252024-01-19 06:21:58.875 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : metricRegistry..................none2024-01-19 06:21:58.875 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : metricsTrackerFactory...........none2024-01-19 06:21:58.875 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : minimumIdle.....................252024-01-19 06:21:58.875 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : password........................<masked>2024-01-19 06:21:58.876 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : poolName........................"HikariPool-1"2024-01-19 06:21:58.876 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : readOnly........................false2024-01-19 06:21:58.876 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : registerMbeans..................false2024-01-19 06:21:58.876 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : scheduledExecutor...............none2024-01-19 06:21:58.877 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : schema..........................none2024-01-19 06:21:58.877 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : threadFactory...................internal2024-01-19 06:21:58.877 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : transactionIsolation............default2024-01-19 06:21:58.877 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : username........................"activiti"2024-01-19 06:21:58.878 DEBUG 2662251 --- [ main] com.zaxxer.hikari.HikariConfig : validationTimeout...............50002024-01-19 06:21:58.880 INFO 2662251 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...2024-01-19 06:21:59.452 DEBUG 2662251 --- [ main] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@29a1505c2024-01-19 06:21:59.456 INFO 2662251 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.2024-01-19 06:21:59.556 DEBUG 2662251 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=1, active=0, idle=1, waiting=0)