Mysql SlowQuery GC overhead limit exceeded error

Submitted by mzhu on Mon, 05/15/2023 - 17:40
1
0
-1

Hi,

We are currently experiencing issues with a process that allows users to register multiple data of a complex type. Occasionally, this process encounters errors, especially when there are more than 200 items involved.

We have identified the following errors in our logs:

2023-05-15 09:01:15.601 -0500 INFO (http-nio-8080-exec-10) org.hibernate.SQL_SLOW SlowQuery: 23567 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@2c35f9f8: select count(distinct sprocessde0_.id) as col_0_0_ from process_definition sprocessde0_ cross join process_instance sprocessin1_ cross join flownode_instance shumantask2_ where sprocessde0_.tenantid = 1 and sprocessin1_.tenantid = 1 and shumantask2_.tenantid = 1 and shumantask2_.kind in ('manual', 'user') and sprocessde0_.processId=sprocessin1_.processDefinitionId and sprocessin1_.id=shumantask2_.logicalGroup2 and shumantask2_.stable=1 and shumantask2_.state_executing=0 and shumantask2_.terminal=0 and (shumantask2_.assigneeId=104 or shumantask2_.assigneeId=0 and (exists (select spendingac3_.id from pending_mapping spendingac3_ where spendingac3_.tenantid = 1 and spendingac3_.activityId=shumantask2_.id and (spendingac3_.userId=104 or exists (select sactor4_.id from actor sactor4_ cross join actormember sactormemb5_ where sactor4_.tenantid = 1 and sactormemb5_.tenantid = 1 and spendingac3_.actorId=sactor4_.id and sactor4_.id=sactormemb5_.actorId and (sactormemb5_.userId=104 or exists (select susermembe6_.id from user_membership susermembe6_ where susermembe6_.tenantid = 1 and susermembe6_.userId=104 and (sactormemb5_.groupId=susermembe6_.groupId and sactormemb5_.roleId=-1 or sactormemb5_.roleId=susermembe6_.roleId and sactormemb5_.groupId=-1 or sactormemb5_.groupId=susermembe6_.groupId and sactormemb5_.roleId=susermembe6_.roleId)))))))) limit 2147483647'
2023-05-15 09:01:15.604 -0500 INFO (http-nio-8080-exec-8) org.hibernate.SQL_SLOW SlowQuery: 23570 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@2e92f1fc: select stenant0_.id as id1_58_0_, stenant0_.created as created2_58_0_, stenant0_.createdBy as createdB3_58_0_, stenant0_.defaultTenant as defaultT4_58_0_, stenant0_.description as descript5_58_0_, stenant0_.iconName as iconName6_58_0_, stenant0_.iconPath as iconPath7_58_0_, stenant0_.name as name8_58_0_, stenant0_.status as status9_58_0_ from tenant stenant0_ where stenant0_.id=1'
2023-05-15 09:01:26.292 -0500 INFO (http-nio-8080-exec-10) org.hibernate.SQL_SLOW SlowQuery: 10683 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@5631dfba: select distinct sprocessde0_.id as id1_47_, sprocessde0_.tenantid as tenantid2_47_, sprocessde0_.activationState as activati3_47_, sprocessde0_.configurationState as configur4_47_, sprocessde0_.deployedBy as deployed5_47_, sprocessde0_.deploymentDate as deployme6_47_, sprocessde0_.description as descript7_47_, sprocessde0_.content_id as content15_47_, sprocessde0_.content_tenantid as content16_47_, sprocessde0_.displayDescription as displayD8_47_, sprocessde0_.displayName as displayN9_47_, sprocessde0_.iconPath as iconPat10_47_, sprocessde0_.lastUpdateDate as lastUpd11_47_, sprocessde0_.name as name12_47_, sprocessde0_.processId as process13_47_, sprocessde0_.version as version14_47_ from process_definition sprocessde0_ cross join process_instance sprocessin1_ cross join flownode_instance shumantask2_ where sprocessde0_.tenantid = 1 and sprocessin1_.tenantid = 1 and shumantask2_.tenantid = 1 and shumantask2_.kind in ('manual', 'user') and sprocessde0_.processId=sprocessin1_.processDefinitionId and sprocessin1_.id=shumantask2_.logicalGroup2 and shumantask2_.stable=1 and shumantask2_.state_executing=0 and shumantask2_.terminal=0 and (shumantask2_.assigneeId=104 or shumantask2_.assigneeId=0 and (exists (select spendingac3_.id from pending_mapping spendingac3_ where spendingac3_.tenantid = 1 and spendingac3_.activityId=shumantask2_.id and (spendingac3_.userId=104 or exists (select sactor4_.id from actor sactor4_ cross join actormember sactormemb5_ where sactor4_.tenantid = 1 and sactormemb5_.tenantid = 1 and spendingac3_.actorId=sactor4_.id and sactor4_.id=sactormemb5_.actorId and (sactormemb5_.userId=104 or exists (select susermembe6_.id from user_membership susermembe6_ where susermembe6_.tenantid = 1 and susermembe6_.userId=104 and (sactormemb5_.groupId=susermembe6_.groupId and sactormemb5_.roleId=-1 or sactormemb5_.roleId=susermembe6_.roleId and sactormemb5_.groupId=-1 or sactormemb5_.groupId=susermembe6_.groupId and sactormemb5_.roleId=susermembe6_.roleId)))))))) order by sprocessde0_.name ASC, sprocessde0_.id ASC limit 2147483646'
2023-05-15 09:01:35.053 -0500 INFO (http-nio-8080-exec-1) org.hibernate.SQL_SLOW SlowQuery: 8745 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@55bc5c35: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:01:35.054 -0500 INFO (http-nio-8080-exec-10) org.hibernate.SQL_SLOW SlowQuery: 8746 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@330c6255: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=401 and sprocessde0_.tenantid=1'
2023-05-15 09:01:35.054 -0500 INFO (http-nio-8080-exec-3) org.hibernate.SQL_SLOW SlowQuery: 8746 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@77a6a923: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:01:35.053 -0500 INFO (http-nio-8080-exec-9) org.hibernate.SQL_SLOW SlowQuery: 8744 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@2609fd5e: select sprocessde0_.id as id1_47_, sprocessde0_.tenantid as tenantid2_47_, sprocessde0_.activationState as activati3_47_, sprocessde0_.configurationState as configur4_47_, sprocessde0_.deployedBy as deployed5_47_, sprocessde0_.deploymentDate as deployme6_47_, sprocessde0_.description as descript7_47_, sprocessde0_.content_id as content15_47_, sprocessde0_.content_tenantid as content16_47_, sprocessde0_.displayDescription as displayD8_47_, sprocessde0_.displayName as displayN9_47_, sprocessde0_.iconPath as iconPat10_47_, sprocessde0_.lastUpdateDate as lastUpd11_47_, sprocessde0_.name as name12_47_, sprocessde0_.processId as process13_47_, sprocessde0_.version as version14_47_ from process_definition sprocessde0_ where sprocessde0_.tenantid = 1 and sprocessde0_.processId=6505946291067187573 limit 1'
2023-05-15 09:01:43.608 -0500 INFO (http-nio-8080-exec-10) org.hibernate.SQL_SLOW SlowQuery: 8550 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@249c9a44: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=701 and sprocessde0_.tenantid=1'
2023-05-15 09:01:43.614 -0500 INFO (http-nio-8080-exec-9) org.hibernate.SQL_SLOW SlowQuery: 8551 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@54eae250: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:01:52.241 -0500 INFO (http-nio-8080-exec-10) org.hibernate.SQL_SLOW SlowQuery: 8627 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@41564d0a: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:02:00.119 -0500 INFO (http-nio-8080-exec-3) org.hibernate.SQL_SLOW SlowQuery: 7871 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@4769581d: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:02:00.121 -0500 INFO (http-nio-8080-exec-9) org.hibernate.SQL_SLOW SlowQuery: 7873 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@1bff59d1: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:02:00.122 -0500 INFO (http-nio-8080-exec-1) org.hibernate.SQL_SLOW SlowQuery: 7875 milliseconds. SQL: 'com.mysql.cj.jdbc.PreparedStatementWrapper@7640bb1d: select sprocessde0_.id as id1_46_0_, sprocessde0_.tenantid as tenantid2_46_0_, sprocessde0_.content as content3_46_0_ from process_content sprocessde0_ where sprocessde0_.id=801 and sprocessde0_.tenantid=1'
2023-05-15 09:09:55.172 -0500 WARN (Bonita-Worker-1-09) org.hibernate.engine.jdbc.spi.SqlExceptionHelper SQL Error: 0, SQLState: S1000
2023-05-15 09:09:55.173 -0500 ERROR (Bonita-Worker-1-09) org.hibernate.engine.jdbc.spi.SqlExceptionHelper GC overhead limit exceeded2023-05-15 09:09:55.190 -0500 SEVERE (http-nio-8080-exec-9) org.bonitasoft.web.toolkit.server.servlet.ToolkitHttpServlet org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=username| java.lang.OutOfMemoryError: GC overhead limit exceeded
org.bonitasoft.web.toolkit.client.common.exception.api.APIException: org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=edhernandez | java.lang.OutOfMemoryError: GC overhead limit exceeded
        at org.bonitasoft.web.rest.server.datastore.bpm.cases.CaseDatastore.get(CaseDatastore.java:146)
        at org.bonitasoft.web.rest.server.api.bpm.flownode.AbstractAPIFlowNode.fillDeploys(AbstractAPIFlowNode.java:144)
        at org.bonitasoft.web.rest.server.api.bpm.flownode.AbstractAPIFlowNode.fillDeploys(AbstractAPIFlowNode.java:57)
        at org.bonitasoft.web.rest.server.framework.API.runSearch(API.java:243)
        at org.bonitasoft.web.rest.server.framework.APIServletCall.doGet(APIServletCall.java:172)
        at org.bonitasoft.web.toolkit.server.servlet.ToolkitHttpServlet.doGet(ToolkitHttpServlet.java:208)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
        at org.bonitasoft.web.toolkit.server.servlet.ToolkitHttpServlet.service(ToolkitHttpServlet.java:76)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
        at org.bonitasoft.web.toolkit.server.servlet.ToolkitHttpServlet.service(ToolkitHttpServlet.java:251)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.bonitasoft.console.common.server.login.filter.AbstractAuthorizationFilter.doFilter(AbstractAuthorizationFilter.java:61)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.bonitasoft.console.common.server.filter.NoCacheFilter.doFilter(NoCacheFilter.java:51)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:713)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:462)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:387)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:315)
        at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.bonitasoft.console.common.server.login.filter.AbstractAuthorizationFilter.doFilter(AbstractAuthorizationFilter.java:61)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.bonitasoft.console.common.server.login.filter.AbstractAuthorizationFilter.doFilter(AbstractAuthorizationFilter.java:61)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.bonitasoft.console.common.server.filter.NoCacheFilter.doFilter(NoCacheFilter.java:51)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:544)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:818)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1626)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:750)
Caused by: org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=edhernandez | java.lang.OutOfMemoryError: GC overhead limit exceeded
        at org.bonitasoft.engine.api.impl.ServerAPIImpl.wrapThrowable(ServerAPIImpl.java:143)
        at org.bonitasoft.engine.api.impl.ServerAPIImpl.invokeMethod(ServerAPIImpl.java:131)
        at org.bonitasoft.engine.api.impl.ClientInterceptor.invoke(ClientInterceptor.java:79)
        at com.sun.proxy.$Proxy129.getProcessInstance(Unknown Source)
        at org.bonitasoft.web.rest.server.datastore.bpm.cases.CaseDatastore.get(CaseDatastore.java:142)
        ... 62 more
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded

After that, the portal become unresponsive and we begin to get the following error:

2023-05-15 09:09:55.206 -0500 WARN (Bonita-Worker-1-09) com.arjuna.ats.jta ARJUNA016129: Could not end XA resource com.mysql.cj.jdbc.MysqlXAConnection@707f9c90
com.mysql.cj.jdbc.MysqlXAException: Undetermined error occurred in the underlying Connection - check your data for consistency
        at com.mysql.cj.jdbc.MysqlXAConnection.mapXAExceptionFromSQLException(MysqlXAConnection.java:347)
        at com.mysql.cj.jdbc.MysqlXAConnection.dispatchCommand(MysqlXAConnection.java:329)
        at com.mysql.cj.jdbc.MysqlXAConnection.end(MysqlXAConnection.java:267)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1088)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1059)
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1286)
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:313)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
        at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1370)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:143)
        at org.bonitasoft.engine.transaction.JTATransactionServiceImpl.complete(JTATransactionServiceImpl.java:180)
        at org.bonitasoft.engine.transaction.JTATransactionServiceImpl.executeInTransaction(JTATransactionServiceImpl.java:296)
        at org.bonitasoft.engine.execution.work.TxBonitaWork.work(TxBonitaWork.java:41)
        at org.bonitasoft.engine.execution.work.LockProcessInstanceWork.work(LockProcessInstanceWork.java:68)
        at org.bonitasoft.engine.execution.work.failurewrapping.TxInHandleFailureWrappingWork.work(TxInHandleFailureWrappingWork.java:40)
        at org.bonitasoft.engine.execution.work.failurewrapping.TxInHandleFailureWrappingWork.work(TxInHandleFailureWrappingWork.java:40)
        at org.bonitasoft.engine.execution.work.failurewrapping.TxInHandleFailureWrappingWork.work(TxInHandleFailureWrappingWork.java:40)
        at org.bonitasoft.engine.execution.work.InSessionBonitaWork.work(InSessionBonitaWork.java:60)
        at org.bonitasoft.engine.work.BonitaThreadPoolExecutor.lambda$submit$1(BonitaThreadPoolExecutor.java:131)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:750)
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

This are the steps we have taken so far:

Regrettably, none of these actions worked and the problem still persists.

Thank you for any advice,

mysql
Slow query
GC overhead
No answers yet.
Notifications