Поток в рабочем состоянии 900 секунд без причины

Question

У меня проблемы с приложением, развернутым на tomcat. На самом деле это веб-сервис SOAP на основе сервлетов.

Tomcat - это Apache Tomcat / 7.0.47, развернутый на Linux ОС, с Oracle DB (org. apache .tomcat.jdb c .pool.DataSource used).

Catalina OPTS: CATALINA_OPTS="-server -Xms8G -Xmx20G -XX:PermSize=512m -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:ParallelGCThreads=20 -XX:ConcGCThreads=5 -XX:InitiatingHeapOccupancyPercent=70"

В веб-сервисе используется пакет Spring и средство запуска задания пула потоков со следующими параметрами:

TE_CORE_POOL_SIZE=20
TE_MAX_POOL_SIZE=40
TE_QUEUE_CAPACITY=200

Пакетная версия Spring: 2.1.9.RELEASE

Spring: 3.1.3.RELEASE

Oracle: 11.1.0.6.0-Production +

Tomcat на сервере xml исполнитель определен как:

<Executor name="tomcatThreadPool" namePrefix="catalina-exec-" maxThreads="800" 
                acceptCount="140" minSpareThreads="80" maxSpareThreads="160"/>

Проблема:

Иногда потоки просто находятся в рабочем состоянии в течение 15 минут без причины . Например, в WS у меня весенний запуск задания:

I get log line:

2020-07-13 15:52:47.894/CEST DEBUG MdmWS - Time for process everything before launcher run 0h 0m 0s 15ms 188us 682ns

Now job should be started, and job is defined as tasklet, but actually it wait exactly 15 minutes before it starts as shown in spring batch log:

2020-07-13 16:08:16.390/CEST INFO SimpleJobLauncher - Job: [FlowJob: [name=wizard_du_generation_job]] launched with the following parameters ...

and as shown below: введите описание изображения здесь

2020-07-13 16: 08: 16.514 / CEST DEBUG RegularCalculation - Получение DU для сеанса cal c: 3058, 2/954 //,,, 1593554400000 2020-07 -13 16: 23: 45.316 / CEST DEBUG RegularCalculation - DU, полученные для сеанса calc: 3058

Как вы можете видеть здесь в журналах, на то, чтобы добраться до тасклета, потребовалось 15 минут, а затем 15 минут, чтобы получить результаты от фасада.

Я действительно не уверен, в чем может быть проблема, это не похоже на то, что у сервера или кота были проблемы с памятью в этот момент. Иногда это просто бывает. Может, в 1 из 10 раз, а иногда и хуже. Я не могу найти какой-либо параметр тайм-аута, установленный на 900 (секунды - 15 минут) или аналогичный, поэтому я действительно запутался здесь.

Я получил дамп потока и получил их, но все еще не уверен, в чем может быть проблема:

"threadPoolTaskExecutor-3" prio=10 tid=0x00007fe834001800 nid=0x3279 runnable [0x00007fe751eda000]
       java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:152)
        at java.net.SocketInputStream.read(SocketInputStream.java:122)
        at oracle.net.ns.Packet.receive(Packet.java:239)
        at oracle.net.ns.DataPacket.receive(DataPacket.java:92)
        at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:172)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:117)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:92)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:77)
        at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1023)
        at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:999)
        at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:584)
        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:183)
        at oracle.jdbc.driver.T4CStatement.executeForDescribe(T4CStatement.java:774)
        at oracle.jdbc.driver.T4CStatement.executeMaybeDescribe(T4CStatement.java:849)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1186)
        at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1770)
        at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1739)
        - locked <0x00000002e383bfa8> (a oracle.jdbc.driver.T4CConnection)
        at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:298)
        at org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:455)
        at org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:395)
        at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:777)
        at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:618)
        at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188)
        at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
        at ...core.common.dao.BaseDao.getConnection(BaseDao.java:224)
        at ...core.common.dao.BaseDao.query(BaseDao.java:72)
        at ...core.rr.dao.PrimaryRegDao.getUsagePointResources(PrimaryRegDao.java:219)
        at ...core.rr.dao.PrimaryRegDao$$FastClassByCGLIB$$28d69ecb.invoke(<generated>)
        at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        at ...core.rr.dao.PrimaryRegDao$$EnhancerByCGLIB$$5487459d.getUsagePointResources(<generated>)
        at ...core.rr.PrimaryRegFacadeImpl.getUsagePointResources(PrimaryRegFacadeImpl.java:47)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at com.sun.proxy.$Proxy96.getUsagePointResources(Unknown Source)
        at ...core.rr.validation.PrimaryRegRefDataCacheImpl.init(PrimaryRegRefDataCacheImpl.java:335)
        at ...core.rr.validation.PrimaryRegProcessor.init(PrimaryRegProcessor.java:166)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1581)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1522)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1452)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
        at org.springframework.beans.factory.support.AbstractBeanFactory$2.getObject(AbstractBeanFactory.java:332)
        at org.springframework.batch.core.scope.StepScope.get(StepScope.java:150)
        - locked <0x000000031c6949a8> (a java.lang.Object)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:328)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
        at org.springframework.aop.target.SimpleBeanTargetSource.getTarget(SimpleBeanTargetSource.java:33)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:182)
        at com.sun.proxy.$Proxy19.process(Unknown Source)
        at org.springframework.batch.core.step.item.SimpleChunkProcessor.doProcess(SimpleChunkProcessor.java:125)
        at org.springframework.batch.core.step.item.SimpleChunkProcessor.transform(SimpleChunkProcessor.java:291)
        at org.springframework.batch.core.step.item.SimpleChunkProcessor.process(SimpleChunkProcessor.java:190)
        at org.springframework.batch.core.step.item.ChunkOrientedTasklet.execute(ChunkOrientedTasklet.java:74)
        at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:386)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
        at org.springframework.batch.core.step.tasklet.TaskletStep$2.doInChunkContext(TaskletStep.java:264)
        at org.springframework.batch.core.scope.context.StepContextRepeatCallback.doInIteration(StepContextRepeatCallback.java:76)
        at org.springframework.batch.repeat.support.RepeatTemplate.getNextResult(RepeatTemplate.java:367)
        at org.springframework.batch.repeat.support.RepeatTemplate.executeInternal(RepeatTemplate.java:214)
        at org.springframework.batch.repeat.support.RepeatTemplate.iterate(RepeatTemplate.java:143)
        at org.springframework.batch.core.step.tasklet.TaskletStep.doExecute(TaskletStep.java:250)
        at org.springframework.batch.core.step.AbstractStep.execute(AbstractStep.java:195)
        at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:135)
        at org.springframework.batch.core.job.flow.JobFlowExecutor.executeStep(JobFlowExecutor.java:61)
        at org.springframework.batch.core.job.flow.support.state.StepState.handle(StepState.java:60)
        at org.springframework.batch.core.job.flow.support.SimpleFlow.resume(SimpleFlow.java:144)
        at org.springframework.batch.core.job.flow.support.SimpleFlow.start(SimpleFlow.java:124)
        at org.springframework.batch.core.job.flow.FlowJob.doExecute(FlowJob.java:135)
        at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:293)
        at org.springframework.batch.core.launch.support.SimpleJobLauncher$1.run(SimpleJobLauncher.java:120)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)

Вот так:

"catalina-exec-38" daemon prio=10 tid=0x00000000023ca800 nid=0x3291 runnable [0x00007fe751ad7000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:152)
    at java.net.SocketInputStream.read(SocketInputStream.java:122)
    at oracle.net.ns.Packet.receive(Packet.java:239)
    at oracle.net.ns.DataPacket.receive(DataPacket.java:92)
    at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:172)
    at oracle.net.ns.NetInputStream.read(NetInputStream.java:117)
    at oracle.net.ns.NetInputStream.read(NetInputStream.java:92)
    at oracle.net.ns.NetInputStream.read(NetInputStream.java:77)
    at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1023)
    at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:999)
    at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:584)
    at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:183)
    at oracle.jdbc.driver.T4CStatement.executeForDescribe(T4CStatement.java:774)
    at oracle.jdbc.driver.T4CStatement.executeMaybeDescribe(T4CStatement.java:849)
    at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1186)
    at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1770)
    at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1739)
    - locked <0x00000002e40f0978> (a oracle.jdbc.driver.T4CConnection)
    at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:298)
    at org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:455)
    at org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:395)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:777)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:618)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188)
    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:202)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:334)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:105)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
    at com.sun.proxy.$Proxy29.getLastJobExecution(Unknown Source)
    at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:94)
    at ...ws.MainProcessingWebService.executeJob(MainProcessingWebService.java:103)
    at sun.reflect.GeneratedMethodAccessor166.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at com.sun.xml.ws.api.server.InstanceResolver$1.invoke(InstanceResolver.java:250)
    at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:149)
    at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:88)
    at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1136)
    at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1050)
    at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:1019)
    at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:877)
    at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:420)
    at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:687)
    at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:266)
    at com.sun.xml.ws.transport.http.servlet.ServletAdapter.invokeAsync(ServletAdapter.java:225)
    at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServletDelegate.java:161)
    at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServletDelegate.java:197)
    at com.sun.xml.ws.transport.http.servlet.WSSpringServlet.doPost(WSSpringServlet.java:52)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:603)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
    - locked <0x00000002ea47d4a0> (a org.apache.tomcat.util.net.SocketWrapper)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)

It is strange problem, so I am not sure if description is enough, but any help is welcome.