playframework / play1

Play framework
https://www.playframework.com/documentation/1.4.x/home
Other
1.58k stars 682 forks source link

play framework 1.4 hang during sending requests to oracle database #1044

Closed karolszk closed 7 years ago

karolszk commented 7 years ago

Hello,

I have an application which causes a lot of requests to work for oracle and hangs. I don't have any idea what was reason for such behavior. (When I'm not using the app automatically is unblocked after some period of time (15-20minutes) which is unacceptable to production use. Normally application is used by 50 users.

The problem is repeatable (there are easy steps to follow by one user and go into this hang) and changing from 1.4.2 to 1.4.3 do nothing. And adding -Dorg.jboss.netty.epollBugWorkaround=true also doesn't help.

and here jstack:

"New I/O boss #27" #63 prio=5 os_prio=0 tid=0x0000000035a22000 nid=0xe70 runnable [0x000000003cd0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #26" #61 daemon prio=5 os_prio=0 tid=0x0000000034d52000 nid=0xaa8 runnable [0x000000003cc0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #25" #60 daemon prio=5 os_prio=0 tid=0x0000000034d53800 nid=0xd78 runnable [0x000000003cb0f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #24" #59 daemon prio=5 os_prio=0 tid=0x0000000034d51800 nid=0xbb0 runnable [0x000000003ca0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #23" #58 daemon prio=5 os_prio=0 tid=0x0000000034d50800 nid=0x3e0 runnable [0x000000003c90f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #22" #57 daemon prio=5 os_prio=0 tid=0x0000000034d53000 nid=0xbb4 runnable [0x000000003c80e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #21" #56 daemon prio=5 os_prio=0 tid=0x0000000034d4d000 nid=0x13fc runnable [0x000000003c70f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #20" #55 daemon prio=5 os_prio=0 tid=0x0000000034d4e800 nid=0xfcc runnable [0x000000003c60e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #19" #54 daemon prio=5 os_prio=0 tid=0x0000000034d4d800 nid=0x1218 runnable [0x000000003c50e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"Hashed wheel timer #1" #53 prio=5 os_prio=0 tid=0x0000000034d50000 nid=0x718 waiting on condition [0x000000003c40e000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.jboss.netty.util.HashedWheelTimer$Worker.waitForNextTick(HashedWheelTimer.java:445) at org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:364) at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) at java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

"play-thread-1" #52 prio=5 os_prio=0 tid=0x0000000034d4f000 nid=0x4a8 runnable [0x000000003c10d000] 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:300) at oracle.net.ns.DataPacket.receive(DataPacket.java:106) at oracle.net.ano.CryptoDataPacket.receive(Unknown Source) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) at oracle.net.ns.NetInputStream.read(NetInputStream.java:260) at oracle.net.ns.NetInputStream.read(NetInputStream.java:185) at oracle.net.ns.NetInputStream.read(NetInputStream.java:102) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80) at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207) at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:884) at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1167) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1289) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3584) at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3628)

"DestroyJavaVM" #51 prio=5 os_prio=0 tid=0x0000000034d49000 nid=0xab4 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:

"New I/O server boss #18" #50 prio=5 os_prio=0 tid=0x0000000034d4c000 nid=0x1088 runnable [0x000000003be0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #17" #49 prio=5 os_prio=0 tid=0x0000000034d4b800 nid=0x1308 runnable [0x000000003bd0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #16" #48 prio=5 os_prio=0 tid=0x0000000034d48800 nid=0x1364 runnable [0x000000003bc0f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #15" #47 prio=5 os_prio=0 tid=0x0000000034d4a800 nid=0xdec runnable [0x000000003bb0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #14" #46 prio=5 os_prio=0 tid=0x0000000034d47800 nid=0xe8c runnable [0x000000003ba0f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #13" #45 prio=5 os_prio=0 tid=0x0000000034d47000 nid=0x1284 runnable [0x000000003b90e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #12" #44 prio=5 os_prio=0 tid=0x0000000034d4a000 nid=0x1294 runnable [0x000000003b80f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #11" #43 prio=5 os_prio=0 tid=0x0000000034d45800 nid=0x1068 runnable [0x000000003b70e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #10" #42 prio=5 os_prio=0 tid=0x0000000034d44800 nid=0x1164 runnable [0x000000003b60e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O server boss #9" #41 prio=5 os_prio=0 tid=0x0000000034d46000 nid=0xe00 runnable [0x000000003b50e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #8" #40 prio=5 os_prio=0 tid=0x000000003394d000 nid=0xe94 runnable [0x000000003b40f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #7" #39 prio=5 os_prio=0 tid=0x0000000030a53000 nid=0x944 runnable [0x000000003b30f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #6" #38 prio=5 os_prio=0 tid=0x0000000030a4f800 nid=0x670 runnable [0x000000003b20f000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #5" #37 prio=5 os_prio=0 tid=0x0000000030a52800 nid=0xf50 runnable [0x000000003b10e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #4" #36 prio=5 os_prio=0 tid=0x0000000030a51800 nid=0x126c runnable [0x000000003b00e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #3" #35 prio=5 os_prio=0 tid=0x0000000030a4e800 nid=0x7b0 runnable [0x000000003af0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #2" #34 prio=5 os_prio=0 tid=0x0000000030a51000 nid=0xbf8 runnable [0x000000003ae0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"New I/O worker #1" #33 prio=5 os_prio=0 tid=0x0000000030a50000 nid=0xf1c runnable [0x000000003ad0e000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

"jobs-thread-10" #32 prio=5 os_prio=0 tid=0x0000000030a4b000 nid=0x1098 waiting on condition [0x000000003ac0e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method)

Regards, Karol

asolntsev commented 7 years ago

Hi @karolszk

  1. You have a very unoptimized query from database: controllers.utilities.QueryByCriteriaSwitchOffFactory.getListAndSetCountPage(QueryByCriteriaSwitchOffFactory.java:202. You need to optimize it. Probably you should add an index to database. And probably cache the result.

  2. You have only one worker thread in Play pool: play-thread-1. Then this thread is busy with the slow DB query, Play cannot handle other requests. Try to increase play pool size by adding the following line in application.conf: play.pool=10

karolszk commented 7 years ago

Hi @asolntsev thanks for help :

ad. 1 - OK. I try to optimize it. ad. 2. I had play.pool=8

please look at the rest of the play-threads-* - I've added missing now:

"play-thread-8" #70 prio=5 os_prio=0 tid=0x0000000035a2a000 nid=0x6b4 waiting on condition [0x000000003d80e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method)

"play-thread-7" #69 prio=5 osprio=0 tid=0x0000000035a29800 nid=0x9e0 runnable [0x000000003d70d000] java.lang.Thread.State: RUNNABLE at org.hibernate.event.internal.AbstractVisitor.processValue(AbstractVisitor.java:119) at org.hibernate.event.internal.WrapVisitor.processValue(WrapVisitor.java:125) at org.hibernate.event.internal.AbstractVisitor.processEntityPropertyValues(AbstractVisitor.java:76) at org.hibernate.event.internal.DefaultFlushEntityEventListener.wrapCollections(DefaultFlushEntityEventListener.java:223) at org.hibernate.event.internal.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:162) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:251) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:100) at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:61) at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1166) at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1223) at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:268) at play.db.jpa.GenericModel$JPAQuery.fetch(GenericModel.java:406) at models.Work.getEffectTags(Work.java:196) at sun.reflect.GeneratedMethodAccessor398.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:196) at models.Work$$_jvstbd3.getEffectTags(Work$$_jvstb_d3.java) at services.damages.DamageService.setShowOnMapDto(DamageService.java:262) at services.damages.DamageService.addShowOnMapDetails(DamageService.java:249) at models.damages.Damage.getDamages(Damage.java:270) at models.damages.Damage.getAllDamages(Damage.java:244) at models.utilities.ExportData.DamagesToFrReport.(DamagesToFrReport.java:95) at controllers.Damages.export(Damages.java:322) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:544) at play.mvc.ActionInvoker.invoke(ActionInvoker.java:494) at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:489) at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:458) at play.mvc.ActionInvoker.invoke(ActionInvoker.java:162) at play.server.PlayHandler$NettyInvocation.execute(PlayHandler.java:326) at play.Invoker$Invocation$1.apply(Invoker.java:292) at play.Invoker$Invocation$1.apply(Invoker.java:288) at play.db.jpa.JPA.withTransaction(JPA.java:258) at play.db.jpa.JPA.withinFilter(JPA.java:217) at play.db.jpa.JPAPlugin$TransactionalFilter.withinFilter(JPAPlugin.java:298) at play.Invoker$Invocation.withinFilter(Invoker.java:271) at play.Invoker$Invocation.run(Invoker.java:288) at play.server.PlayHandler$NettyInvocation.run(PlayHandler.java:303) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

"play-thread-6" #68 prio=5 os_prio=0 tid=0x0000000035a25000 nid=0x1120 runnable [0x000000003d60d000] 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:300) at oracle.net.ns.DataPacket.receive(DataPacket.java:106) at oracle.net.ano.CryptoDataPacket.receive(Unknown Source) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) at oracle.net.ns.NetInputStream.read(NetInputStream.java:260) at oracle.net.ns.NetInputStream.read(NetInputStream.java:185) at oracle.net.ns.NetInputStream.read(NetInputStream.java:102) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80) at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207) at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:884) at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1167) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1289) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3584) at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3628)

"play-thread-5" #67 prio=5 os_prio=0 tid=0x0000000035a28000 nid=0xc1c runnable [0x000000003d50d000] java.lang.Thread.State: RUNNABLE at java.lang.String.intern(Native Method) at java.lang.Class.searchMethods(Class.java:3003) at java.lang.Class.privateGetMethodRecursive(Class.java:3048) at java.lang.Class.getMethod0(Class.java:3018) at java.lang.Class.getMethod(Class.java:1784) at play.classloading.enhancers.PropertiesEnhancer$FieldAccessor.invokeReadProperty(PropertiesEnhancer.java:223) at services.zzzzzz.disconnectedLine.DisconnectedLineService.loadDisconnectedLine(DisconnectedLineService.java:129) at models.utilities.ExportData.outage.ReportsMergedOutageSimpleToFrReport.setTableBody(ReportsMergedOutageSimpleToFrReport.java:98) at models.utilities.ExportData.outage.ReportsMergedOutageSimpleToFrReport.(ReportsMergedOutageSimpleToFrReport.java:55) at controllers.Reports.exportOutageSimple(Reports.java:622) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:544) at play.mvc.ActionInvoker.invoke(ActionInvoker.java:494) at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:489) at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:458) at play.mvc.ActionInvoker.invoke(ActionInvoker.java:162) at play.server.PlayHandler$NettyInvocation.execute(PlayHandler.java:326) at play.Invoker$Invocation$1.apply(Invoker.java:292) at play.Invoker$Invocation$1.apply(Invoker.java:288) at play.db.jpa.JPA.withTransaction(JPA.java:258) at play.db.jpa.JPA.withinFilter(JPA.java:217) at play.db.jpa.JPAPlugin$TransactionalFilter.withinFilter(JPAPlugin.java:298) at play.Invoker$Invocation.withinFilter(Invoker.java:271) at play.Invoker$Invocation.run(Invoker.java:288) at play.server.PlayHandler$NettyInvocation.run(PlayHandler.java:303) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

"play-thread-4" #66 prio=5 os_prio=0 tid=0x0000000035a24000 nid=0x3d8 runnable [0x000000003d40c000] 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:300) at oracle.net.ns.DataPacket.receive(DataPacket.java:106) at oracle.net.ano.CryptoDataPacket.receive(Unknown Source) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) at oracle.net.ns.NetInputStream.read(NetInputStream.java:260) at oracle.net.ns.NetInputStream.read(NetInputStream.java:185) at oracle.net.ns.NetInputStream.read(NetInputStream.java:102) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80) at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207) at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:884) at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1167) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1289) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3584) at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3628)

"play-thread-3" #65 prio=5 os_prio=0 tid=0x0000000035a27000 nid=0x940 runnable [0x000000003d30d000] java.lang.Thread.State: RUNNABLE at org.hibernate.event.internal.AbstractVisitor.processValue(AbstractVisitor.java:123) at org.hibernate.event.internal.WrapVisitor.processValue(WrapVisitor.java:125) at org.hibernate.event.internal.AbstractVisitor.processEntityPropertyValues(AbstractVisitor.java:76) at org.hibernate.event.internal.DefaultFlushEntityEventListener.wrapCollections(DefaultFlushEntityEventListener.java:223) at org.hibernate.event.internal.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:162) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:251) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:100) at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:61) at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1166) at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1223) at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:268) at dao.netEvents.NetEventDao.findByDamageId(NetEventDao.java:102) at services.netEvents.NetEventService.getByDamageId(NetEventService.java:124) at models.damages.DamageBase.getLowVoltageCircuitByWork(DamageBase.java:251) at models.damages.DamageBase.getSubstationAndObjectName(DamageBase.java:348) at models.utilities.ExportData.DamagesToFrReport.getObjectName(DamagesToFrReport.java:372) at models.utilities.ExportData.DamagesToFrReport.prepareReport(DamagesToFrReport.java:301) at models.utilities.ExportData.DamagesToFrReport.(DamagesToFrReport.java:115) at controllers.Damages.export(Damages.java:322) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:544) at play.mvc.ActionInvoker.invoke(ActionInvoker.java:494) at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:489) at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:458) at play.mvc.ActionInvoker.invoke(ActionInvoker.java:162) at play.server.PlayHandler$NettyInvocation.execute(PlayHandler.java:326) at play.Invoker$Invocation$1.apply(Invoker.java:292) at play.Invoker$Invocation$1.apply(Invoker.java:288) at play.db.jpa.JPA.withTransaction(JPA.java:258) at play.db.jpa.JPA.withinFilter(JPA.java:217) at play.db.jpa.JPAPlugin$TransactionalFilter.withinFilter(JPAPlugin.java:298) at play.Invoker$Invocation.withinFilter(Invoker.java:271) at play.Invoker$Invocation.run(Invoker.java:288) at play.server.PlayHandler$NettyInvocation.run(PlayHandler.java:303) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

"play-thread-2" #64 prio=5 os_prio=0 tid=0x0000000035a23800 nid=0x694 runnable [0x000000003d20d000] 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:300) at oracle.net.ns.DataPacket.receive(DataPacket.java:106) at oracle.net.ano.CryptoDataPacket.receive(Unknown Source) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) at oracle.net.ns.NetInputStream.read(NetInputStream.java:260) at oracle.net.ns.NetInputStream.read(NetInputStream.java:185) at oracle.net.ns.NetInputStream.read(NetInputStream.java:102) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80) at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207) at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:884) at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1167) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1289) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3584) at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3628)

karolszk commented 7 years ago

Hi again, @asolntsev "Try to increase play pool size by adding the following line in application.conf: play.pool=10" how big may be this value? From doc number_of_processors+1 but ts it possible to increase to 50? :) Regards, Karol

asolntsev commented 7 years ago

Hi @karolszk ! Most of your "play-thread-*" threads are busy with database operations. So, I repeat: you need to analyze your selects and probably add some indexes to database.

I think that recommendation "doc number_of_processors+1" is only valid for applications that use asynchronous operations everywhere (like Rest services calls). In other words, threads "play-thread-*" never wait for anything in such applications.

Oracle jdbc driver is not asynochronous, meaning that your threads do wait for database response. In this case I recommend setting `play.pool=database pool + N".