BPMS / RHPAM server startup very slow due to query registration
Issue
After patching from 6.4.8 to 6.4.11 we are experiencing very slow startup times:
BEFORE PATCHING:
2019-07-31 02:35:09,774 INFO started in 42177ms
2019-08-01 02:38:05,137 INFO started in 43102ms
AFTER PATCHING:
2019-08-02 21:12:35,876 INFO started in 116657ms
2019-08-03 15:16:06,088 INFO started in 795473ms
Looking at the log files, it seems that the query registration times have increased:
02:10:25,882 start
02:10:39,155 Registered findTasksInWaitForUserProcessInstances query successfully
02:10:52,182 Registered activeTasksForGroupInputParamContentFiltered query successfully
02:10:53,592 Registered findTasksWithParameters query successfully
02:10:54,511 Registered notPotOwnedTasksForWorkedProcessInstance query successfully
02:10:54,737 Registered jbpmHumanTasksWithUser query successfully
02:10:55,007 Registered jbpmHumanTasksWithAdmin query successfully
02:10:56,026 Registered jbpmHumanTasksWithVariables query successfully
02:10:57,822 Registered tasksMonitoring query successfully
02:10:58,729 Registered getAllTaskInstancesWithCorrelationKey query successfully
02:15:19,640 Registered tasksByGroupsAndVariablesAndParams query successfully
02:19:25,291 Registered potOwnedTasksByVariablesAndParams query successfully
Before patching, the times were around just one sec:
02:15:00,907 start
02:15:01,626 Registered findProcessInstancesWithVariables query successfully
02:15:01,649 Registered findTasksInWaitForUserProcessInstances query successfully
02:15:01,662 Registered activeTasksForGroupInputParamContentFiltered query successfully
02:15:01,697 Registered findTasksWithParameters query successfully
02:15:01,723 Registered notPotOwnedTasksForWorkedProcessInstance query successfully
02:15:01,739 Registered tasksByVariablesAndParams query successfully
02:15:01,767 Registered tasksByNamesAndVariablesAndParams query successfully
02:15:01,776 Registered jbpmHumanTasksWithUser query successfully
02:15:01,803 Registered jbpmHumanTasksWithAdmin query successfully
02:15:01,820 Registered jbpmHumanTasksWithVariables query successfully
02:15:01,836 Registered tasksMonitoring query successfully
02:15:01,857 Registered jbpmProcessInstancesWithVariables query successfully
02:15:01,881 Registered getAllTaskInstancesWithCorrelationKey query successfully
02:15:01,912 Registered tasksByGroupsAndVariablesAndParams query successfully
02:15:01,929 Registered potOwnedTasksByVariablesAndParams query successfully
The thread dumps show the following activity during the query registration:
"ServerService Thread Pool -- 63" #153 prio=5 os_prio=0 tid=0x00007f1990754800 nid=0x1b2ca runnable [0x00007f196b5f4000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at oracle.net.ns.Packet.receive(Packet.java:311)
at oracle.net.ns.DataPacket.receive(DataPacket.java:105)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:249)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:171)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:89)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:123)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:79)
at oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:429)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:397)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:257)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:587)
at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:210)
at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:30)
at oracle.jdbc.driver.T4CStatement.executeForDescribe(T4CStatement.java:762)
at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:925)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1111)
at oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:1309)
- locked <0x000000077851cd10> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.OracleStatementWrapper.executeQuery(OracleStatementWrapper.java:422)
at org.jboss.jca.adapters.jdbc.WrappedStatement.executeQuery(WrappedStatement.java:344)
at org.dashbuilder.dataprovider.sql.JDBCUtils.executeQuery(JDBCUtils.java:76)
at org.dashbuilder.dataprovider.sql.model.Select.fetchCount(Select.java:177)
at org.dashbuilder.dataprovider.sql.SQLDataSetProvider._getRowCount(SQLDataSetProvider.java:434)
at org.dashbuilder.dataprovider.sql.SQLDataSetProvider._getDataSetMetadata(SQLDataSetProvider.java:380)
at org.dashbuilder.dataprovider.sql.SQLDataSetProvider.getDataSetMetadata(SQLDataSetProvider.java:259)
at org.dashbuilder.dataset.DataSetManagerImpl.getDataSetMetadata(DataSetManagerImpl.java:179)
at org.jbpm.kie.services.impl.query.QueryServiceImpl.replaceQuery(QueryServiceImpl.java:146)
at org.jbpm.kie.services.impl.query.QueryServiceImpl.registerQuery(QueryServiceImpl.java:127)
at org.jbpm.kie.services.impl.query.QueryServiceImpl.init(QueryServiceImpl.java:111)
at org.kie.server.services.jbpm.JbpmKieServerExtension.init(JbpmKieServerExtension.java:218)
at org.kie.server.services.impl.KieServerImpl. (KieServerImpl.java:111)
at org.kie.server.services.impl.KieServerImpl. (KieServerImpl.java:90)
at org.kie.server.services.impl.KieServerLocator. (KieServerLocator.java:20)
Environment
- Red Hat JBoss BPM Suite
- 6.4.9+
- Red Hat Process Automation Manager (RHPAM)
- 7.x
Subscriber exclusive content
A Red Hat subscription provides unlimited access to our knowledgebase, tools, and much more.