Server stops

udrescu_bogdan · November 22, 2011, 12:45pm

The production server is running since yesterday on java7, so it’s too early to say that it crashed with OutOfMemory error.

Right now it has this memory:

System Information
Heap memory: allocated=494972K, used=358109K, max=506816K
None Heap memory: allocated=91008K, used=90399K, max=180224K

and it’s running 9 WebClients, 2 HeadlessClients and 4 WebClients with login solution.

About how java manages the memory, the testing server that I was talking earlier, indeed uses less memory now:

 System Information
Heap memory: allocated=364992K, used=95561K, max=932096K
None Heap memory: allocated=48320K, used=47639K, max=180224K

But, yes, while running with java6u26 I wrote here a lot that I had OutOfMemory almost each day. And we tested this java version on 2 different Linux 32 and 64 bit, and the behavior was almost the same.

udrescu_bogdan · November 22, 2011, 1:26pm

Still, one thing about the memory release, I had those 100 additional MB for more then 10 minutes after I upload the solution, at least this time I spent to watch if it will decrease. I can’t say what java does inside, but normally, the GC should clear the unused objects, which in this case, after lot of calls to GC, the memory was not released, meaning that the references to the objects were not released from usage. That extra memory was in the end clear, but in my opinion, it took lot of time.

And one more thing. On the same java6u26 that seems to couse lot of OutOfMemory errors, I have another java app running, that didn’t had any problem with the memory. In fact this one is running for months without any restart.

java6u26:

root      7870 16.0  7.0 674204 149424 pts/1   Sl   14:10   0:03 java -Xmx512m -Xms128m -cp noaa_server.zip server.WebServer
Memory: total: 228589568, free: 219063904, maximum: 477233152

java7:

root      7792 19.6  7.9 673396 168672 pts/1   Sl   14:08   0:03 ./../servoy_aeroplus/application_server/jre1.7.0_01/bin/java -Xmx512m -Xms128m -cp noaa_server.zip server.WebServer
Memory: total: 262668288, free: 251391688, maximum: 477233152

jcompagner · November 22, 2011, 2:48pm

really, just looking at the runtime memory information doesn’t tell you anything, java doesn’t have to do any GC when it is just sitting idle, at least not a full gc cleaning everything up

If you really have out of memories where you should have enough memory for the load you get then the only thing to do is analyze the memory dump…
Looking at the values you do doesn’t make much sense.

udrescu_bogdan · November 25, 2011, 7:36am

Hi Johan,

Can you please tell me if Servoy or any plugin that you know is using only the java api and other java libraries or is also calling some native / jni code?

Thanks!

jcompagner · November 25, 2011, 9:11am

servoy ships with java only plugins
But there are plugins that have native integration like browser_suite

udrescu_bogdan · December 6, 2011, 7:37am

Hi again,

We notice other problems with Servoy after switching to java7!

First of all, the processor usage goes to 100% after few days of running. I thought it’s a bug in my code, an endless loop, but after closing all clients, which closed correctly, the processor was still to 100%.

This morning the processor went to 100% again after 7 days of uptime and the server crashed again with this error:

Exception in thread "ModificationWatcher Task" java.lang.OutOfMemoryError: Java heap space
       at java.util.Arrays.copyOf(Unknown Source)
       at java.lang.AbstractStringBuilder.expandCapacity(Unknown Source)
       at java.lang.AbstractStringBuilder.ensureCapacityInternal(Unknown Source)
       at java.lang.AbstractStringBuilder.append(Unknown Source)
       at java.lang.StringBuilder.append(Unknown Source)
       at java.lang.StackTraceElement.toString(Unknown Source)
       at java.lang.String.valueOf(Unknown Source)
       at java.lang.StringBuilder.append(Unknown Source)
       at java.lang.Throwable.printStackTrace(Throwable.java:657)
       at java.lang.Throwable.printStackTrace(Throwable.java:720)
       at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:59)
       at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:342)
       at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:304)
       at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:236)
       at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
       at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
       at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
       at org.apache.log4j.Category.callAppenders(Category.java:203)
       at org.apache.log4j.Category.forcedLog(Category.java:388)
       at org.apache.log4j.Category.log(Category.java:853)
       at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:485)
       at org.apache.wicket.util.thread.Task$1.run(Task.java:135)
       at java.lang.Thread.run(Unknown Source)
Dec 06, 2011 8:00:47 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet servoy_webclient threw exception
java.lang.OutOfMemoryError: Java heap space

Thanks!

jcompagner · December 6, 2011, 8:24am

how much memory do you give your server?
what does the admin page mem status say when the cpu usage is high?

It seems that or you just have to little memory assigned or there is somewhere a leak eating a way memory.

udrescu_bogdan · December 6, 2011, 8:55am

The -xmx is 512.

While the processor is 100%, the allocated heap in the admin page is at maximum 506816K, but the used memory varies between 300+MB and 400+MB. Clients can connect. Is not always slow. Actually it becomes slow just before it crash, even with one day as we noticed.

First time (two weeks ago) it was fine for 2 days, then the processor went to 100% and it stood alive for about 3 days with 100% processor. From the clients point or view it was running fine, then suddenly after 3 days it went slow and it crashed.
Then, after restarting it again it was fine for one day, then the processor went up again to 100%. At that time we test by closing all clients and they closed correctly, but the processor was still 100%. This was last monday.
Then we start it again and the processor was fine. Since then it was running fine for 7 days. Yesterday users noticed that the server is slow. And this morning it crashed.

Please let me know if this is helpful information.

jcompagner · December 6, 2011, 9:00am

give it first more memory, besides that if it is 100% you could dump the stack a few times, lets say 5 times 10 seconds apart from the admin pages.
Then we can try to see what the cpu is really doing, also you could connect to the server process with jvisualvm (its in the jdk 6/7 bin dir) and there you should be able to see where it spends it time (look also at the GC times)

udrescu_bogdan · December 6, 2011, 9:07am

OK, I’ll do that and let you know after few days or more, depending on the behavior. Thanks a lot!

udrescu_bogdan · December 27, 2011, 1:01pm

Hello, I think I found a cause for the processor problem. I am doing lots of processing in a headless client, some of them with thousands of inserts in the database. I’ve add these inserts into a transaction and for 5 days the server is running fine without any processor overheat.

udrescu_bogdan · December 29, 2011, 7:22am

I think I enjoyed it too soon. That process that now use transactions is blocked now again…

udrescu_bogdan · January 2, 2012, 8:03am

Hi Johan,

I have the server using 100% again. So far I didn’t manage to connect using jvisualvm. Do you know what ports needs to be open on the remote server so that I can connect with the process there. Is it 3333? Anyway it’s a day off now, so I won’t bother the guys that manages the servers to open any ports for me now, but next days I can try again.

I can show you now the stack. Maybe you can get a picture from it with what’s happening.

Current time: Mon Jan 02 09:00:32 CET 2012

Server Information
Servoy version 5.2.9 -build 1020
Port used by RMI Registry: 1089
Repository version 38

Current time: Mon Jan 02 09:00:32 CET 2012

Uptime:  6 days 18 hours 30 minutes 43 seconds

JDK Information
java.vm.name=Java HotSpot(TM) Server VM
java.version=1.7.0_01
java.vm.info=mixed mode
java.vm.vendor=Oracle Corporation

Operating System Information
os.name=Linux
os.version=2.6.29-xs5.5.0.17
os.arch=i386

System Information
Heap memory: allocated=241472K, used=156741K, max=932096K
None Heap memory: allocated=40448K, used=40014K, max=180224K

Thread: pool-4-thread-194, state: WAITING, total cpu time: 0.113763ms, total user time: 0.0ms, blocked by: pool-4-thread-192 on java.util.concurrent.locks.ReentrantLock$NonfairSync@c23824
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Unknown Source)
  java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(Unknown Source)
  java.util.concurrent.locks.ReentrantLock.lock(Unknown Source)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeAndWait(SessionClient.java:1167)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeLater(SessionClient.java:1160)
  com.servoy.j2db.plugins.ClientPluginAccessProvider$1.run(ClientPluginAccessProvider.java:439)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: pool-4-thread-193, state: WAITING, total cpu time: 0.11438ms, total user time: 0.0ms, blocked by: pool-4-thread-192 on java.util.concurrent.locks.ReentrantLock$NonfairSync@c23824
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Unknown Source)
  java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(Unknown Source)
  java.util.concurrent.locks.ReentrantLock.lock(Unknown Source)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeAndWait(SessionClient.java:1167)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeLater(SessionClient.java:1160)
  com.servoy.j2db.plugins.ClientPluginAccessProvider$1.run(ClientPluginAccessProvider.java:439)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: pool-4-thread-192, state: RUNNABLE, total cpu time: 3.76318827734018E8ms, total user time: 3.7632202E8ms
  org.mozilla.javascript.IdScriptableObject.get(IdScriptableObject.java:405)
  org.mozilla.javascript.ScriptableObject.getProperty(ScriptableObject.java:1641)
  org.mozilla.javascript.ScriptableObject.getDefaultValue(ScriptableObject.java:772)
  org.mozilla.javascript.ScriptableObject.getDefaultValue(ScriptableObject.java:708)
  org.mozilla.javascript.ScriptRuntime.toString(ScriptRuntime.java:762)
  org.mozilla.javascript.NativeString.execIdCall(NativeString.java:310)
  org.mozilla.javascript.IdFunctionObject.call(IdFunctionObject.java:127)
  org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:3666)
  org.mozilla.javascript.Interpreter.interpret(Interpreter.java:2680)
  org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:166)
  org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:387)
  org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3135)
  org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:165)
  com.servoy.j2db.scripting.ScriptEngine.executeFunction(ScriptEngine.java:476)
  com.servoy.j2db.plugins.ClientPluginAccessProvider$MethodExecutor.run(ClientPluginAccessProvider.java:511)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeAndWait(SessionClient.java:1170)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeLater(SessionClient.java:1160)
  com.servoy.j2db.plugins.ClientPluginAccessProvider$1.run(ClientPluginAccessProvider.java:439)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: pool-4-thread-184, state: WAITING, total cpu time: 15416.342455ms, total user time: 13580.0ms, blocked by: pool-4-thread-192 on java.util.concurrent.locks.ReentrantLock$NonfairSync@c23824
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Unknown Source)
  java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(Unknown Source)
  java.util.concurrent.locks.ReentrantLock.lock(Unknown Source)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeAndWait(SessionClient.java:1167)
  com.servoy.j2db.server.headlessclient.SessionClient.invokeLater(SessionClient.java:1160)
  com.servoy.j2db.plugins.ClientPluginAccessProvider$1.run(ClientPluginAccessProvider.java:439)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: http-213.154.228.156-80-6, state: WAITING, total cpu time: 9.957176ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:423)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:449)
  java.lang.Thread.run(Unknown Source)

Thread: http-213.154.228.156-80-5, state: WAITING, total cpu time: 9.547616ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:423)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:449)
  java.lang.Thread.run(Unknown Source)

Thread: http-213.154.228.156-80-4, state: WAITING, total cpu time: 7.552196ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:423)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:449)
  java.lang.Thread.run(Unknown Source)

Thread: http-213.154.228.156-80-3, state: WAITING, total cpu time: 6.61974ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:423)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:449)
  java.lang.Thread.run(Unknown Source)

Thread: Java2D Disposer, state: WAITING, total cpu time: 0.098487ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.lang.ref.ReferenceQueue.remove(Unknown Source)
  java.lang.ref.ReferenceQueue.remove(Unknown Source)
  sun.java2d.Disposer.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: http-213.154.228.156-80-2, state: RUNNABLE, total cpu time: 572.425229ms, total user time: 520.0ms
  sun.management.ThreadImpl.getThreadInfo1(Native Method)
  sun.management.ThreadImpl.getThreadInfo(Unknown Source)
  sun.management.ThreadImpl.getThreadInfo(Unknown Source)
  com.servoy.j2db.server.servlets.ConfigServlet.Zt(ConfigServlet.java:2457)
  com.servoy.j2db.server.servlets.ConfigServlet.service(ConfigServlet.java:3632)
  javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
  org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
  org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
  org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
  org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
  org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
  org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
  org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:567)
  org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
  org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
  org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
  org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
  java.lang.Thread.run(Unknown Source)

Thread: http-213.154.228.156-80-1, state: WAITING, total cpu time: 1126.472537ms, total user time: 1040.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:423)
  org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:449)
  java.lang.Thread.run(Unknown Source)

Thread: pool-1-thread-3, state: WAITING, total cpu time: 6417.052129ms, total user time: 3960.0ms
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: pool-1-thread-2, state: WAITING, total cpu time: 6468.795245ms, total user time: 3600.0ms
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: TaskExecuter[0], state: WAITING, total cpu time: 87.777992ms, total user time: 40.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  com.servoy.j2db.util.TaskExecuter.run(TaskExecuter.java:70)
  java.lang.Thread.run(Unknown Source)

Thread: DestroyJavaVM, state: RUNNABLE, total cpu time: 6407.56199ms, total user time: 5760.0ms

Thread: Timer-0, state: TIMED_WAITING, total cpu time: 4.495197ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.util.TimerThread.mainLoop(Unknown Source)
  java.util.TimerThread.run(Unknown Source)

Thread: scheduler_QuartzSchedulerThread, state: TIMED_WAITING, total cpu time: 4108.557865ms, total user time: 3660.0ms
  java.lang.Object.wait(Native Method)
  org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:411)

Thread: http-213.154.228.156-80-Acceptor-0, state: RUNNABLE, total cpu time: 8.690544ms, total user time: 0.0ms
  java.net.PlainSocketImpl.socketAccept(Native Method)
  java.net.AbstractPlainSocketImpl.accept(Unknown Source)
  java.net.ServerSocket.implAccept(Unknown Source)
  java.net.ServerSocket.accept(Unknown Source)
  org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61)
  org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:317)
  java.lang.Thread.run(Unknown Source)

Thread: ContainerBackgroundProcessor[StandardEngine[Catalina]], state: TIMED_WAITING, total cpu time: 18121.52997ms, total user time: 10200.0ms
  java.lang.Thread.sleep(Native Method)
  org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579)
  java.lang.Thread.run(Unknown Source)

Thread: scheduler_Worker-1, state: TIMED_WAITING, total cpu time: 34895.039274ms, total user time: 27040.0ms
  java.lang.Object.wait(Native Method)
  org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:543)

Thread: ModificationWatcher Task, state: TIMED_WAITING, total cpu time: 60482.257847ms, total user time: 46270.0ms
  java.lang.Thread.sleep(Native Method)
  org.apache.wicket.util.time.Duration.sleep(Duration.java:445)
  org.apache.wicket.util.thread.Task$1.run(Task.java:130)
  java.lang.Thread.run(Unknown Source)

Thread: pool-3-thread-1, state: TIMED_WAITING, total cpu time: 17.78065ms, total user time: 0.0ms
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: GC Daemon, state: TIMED_WAITING, total cpu time: 20.486772ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  sun.misc.GC$Daemon.run(Unknown Source)

Thread: RMI Reaper, state: WAITING, total cpu time: 0.141728ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  java.lang.ref.ReferenceQueue.remove(Unknown Source)
  java.lang.ref.ReferenceQueue.remove(Unknown Source)
  sun.rmi.transport.ObjectTable$Reaper.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: pool-1-thread-1, state: WAITING, total cpu time: 6937.569694ms, total user time: 4180.0ms
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: RMI TCP Accept-1089, state: WAITING, total cpu time: 0.139001ms, total user time: 0.0ms
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
  java.util.concurrent.ArrayBlockingQueue.take(Unknown Source)
  com.servoy.j2db.rmi.ServerTwoWaySocketFactory$TwoWayServerSocket.accept(ServerTwoWaySocketFactory.java:578)
  sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(Unknown Source)
  sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: 2 way Server Acceptor, state: RUNNABLE, total cpu time: 2.007958ms, total user time: 0.0ms
  java.net.PlainSocketImpl.socketAccept(Native Method)
  java.net.AbstractPlainSocketImpl.accept(Unknown Source)
  java.net.ServerSocket.implAccept(Unknown Source)
  sun.security.ssl.SSLServerSocketImpl.accept(Unknown Source)
  com.servoy.j2db.rmi.ServerTwoWaySocketFactory$TwoWayServerSocket.run(ServerTwoWaySocketFactory.java:596)
  java.lang.Thread.run(Unknown Source)

Thread: pool-2-thread-1, state: TIMED_WAITING, total cpu time: 216.642289ms, total user time: 120.0ms
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: PingScanner, state: TIMED_WAITING, total cpu time: 223.6945ms, total user time: 80.0ms
  java.lang.Object.wait(Native Method)
  com.servoy.j2db.dataprocessing.Zn.run(Zn.java:38)
  java.lang.Thread.run(Unknown Source)

Thread: MessageScheduler, state: TIMED_WAITING, total cpu time: 95.007722ms, total user time: 60.0ms
  java.lang.Object.wait(Native Method)
  com.servoy.j2db.dataprocessing.Zp.run(Zp.java:10)
  java.lang.Thread.run(Unknown Source)

Thread: MessagePreHandler, state: WAITING, total cpu time: 88.872503ms, total user time: 60.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  com.servoy.j2db.dataprocessing.ClientMessagePreQueueHandler.run(ClientMessagePreQueueHandler.java:48)
  java.lang.Thread.run(Unknown Source)

Thread: Keep-Alive-SocketCleaner, state: WAITING, total cpu time: 2.447938ms, total user time: 0.0ms
  java.lang.Object.wait(Native Method)
  sun.net.www.http.KeepAliveStreamCleaner.run(Unknown Source)
  java.lang.Thread.run(Unknown Source)

Thread: Signal Dispatcher, state: RUNNABLE, total cpu time: 0.162151ms, total user time: 0.0ms

Thread: Finalizer, state: WAITING, total cpu time: 4318.224897ms, total user time: 3700.0ms
  java.lang.Object.wait(Native Method)
  java.lang.ref.ReferenceQueue.remove(Unknown Source)
  java.lang.ref.ReferenceQueue.remove(Unknown Source)
  java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

Thread: Reference Handler, state: WAITING, total cpu time: 2533.647582ms, total user time: 1340.0ms
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:503)
  java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)

Thanks!

jcompagner · January 2, 2012, 11:24am

i think you just have a runaway script:

  Thread: pool-4-thread-192, state: RUNNABLE, total cpu time: 3.76318827734018E8ms, total user time: 3.7632202E8ms
      org.mozilla.javascript.IdScriptableObject.get(IdScriptableObject.java:405)
      org.mozilla.javascript.ScriptableObject.getProperty(ScriptableObject.java:1641)
      org.mozilla.javascript.ScriptableObject.getDefaultValue(ScriptableObject.java:772)
      org.mozilla.javascript.ScriptableObject.getDefaultValue(ScriptableObject.java:708)
      org.mozilla.javascript.ScriptRuntime.toString(ScriptRuntime.java:762)
      org.mozilla.javascript.NativeString.execIdCall(NativeString.java:310)
      org.mozilla.javascript.IdFunctionObject.call(IdFunctionObject.java:127)
      org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:3666)
      org.mozilla.javascript.Interpreter.interpret(Interpreter.java:2680)
      org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:166)
      org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:387)
      org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3135)
      org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:165)
      com.servoy.j2db.scripting.ScriptEngine.executeFunction(ScriptEngine.java:476)
      com.servoy.j2db.plugins.ClientPluginAccessProvider$MethodExecutor.run(ClientPluginAccessProvider.java:511)
      com.servoy.j2db.server.headlessclient.SessionClient.invokeAndWait(SessionClient.java:1170)
      com.servoy.j2db.server.headlessclient.SessionClient.invokeLater(SessionClient.java:1160)
      com.servoy.j2db.plugins.ClientPluginAccessProvider$1.run(ClientPluginAccessProvider.java:439)
      java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
      java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
      java.lang.Thread.run(Unknown Source)

thats a lot of time if i see that correctly…
That script seems to be called from a plugin (scheduler) or something, I don’t know much more, but it seems to me that that script just runs for ever (something like a never ending loop)

udrescu_bogdan · January 2, 2012, 11:56am

Yes, I also thought it’s a never ending loop, but I reviewed several times all loops from that client and they all should close fine. I have cron methods initiated from scheduler. I can’t reproduce this with a single shoot. It takes about 6 days to enter in a never ending state. I even increased the performance after I used transactions. Before that the processor went to 100 in less then 6 days.
Another point is that it happened before with other processes as well, that I had to remove, although we need the functionality. Running the process once and trying to debug went fine. Let it run on the server, after a while it would block all server.

jcompagner · January 2, 2012, 2:40pm

i don’t know what to tell you then,
it is or an script that is constantly running because of some state, or it is script that is constantly called because it is constantly scheduled

In your stack dump for example there is already an other thread waiting for the next script to execute…
So even if this one would finish, another is also executing right away.

So you really should look at your solution what you are exactly executing, and maybe add some tracing so that you can see what is running at what time and how long…

udrescu_bogdan · January 2, 2012, 3:11pm

How does the scheduler plugin works? Does it executes the cron methods concurrent, each one on its own thread, or it execute only one at a time, all of them on a single thread?

And one more thing. I’m almost sure the scheduler blocks into one method because the “Client idle since” time is not changing. Normally it should change from 5 to 5 minutes, but when it happens it remain block with the same time forever. If I’m trying to close it from the Clients section, it will not work. If I stop it from the Batch Processors it work. I’m not sure but I think this is the moment when the processor goes to 100, at least this is what I noticed last time (It was morning, on 29 last month, the process was idle since 00:00 in the night, I stopped it and looked on a snapshoot with the processor usage, which increased around the time I closed the batch client).
I run methods at 5 minutes interval, 15 minutes, few hours and one day. Right now there are 6 cron methods running, though they should be at least 2 more.

jcompagner · January 2, 2012, 3:29pm

for the same client they wait on each other:

Thread: pool-4-thread-192, state: RUNNABLE, total cpu time: 3.76318827734018E8ms, total user time: 3.7632202E8ms
org.mozilla.javascript.IdScriptableObject.get(IdScriptableObject.java:405)

thats the thread that is currently executing
this i the thread that is currently waiting: (see blocked by: xxx)

Thread: pool-4-thread-184, state: WAITING, total cpu time: 15416.342455ms, total user time: 13580.0ms, blocked by: pool-4-thread-192 on java.util.concurrent.locks.ReentrantLock$NonfairSync@c23824
sun.misc.Unsafe.park(Native Method)

looking at the cpu time of that thread:

376318827ms → thats a bit more then 4 days!!

udrescu_bogdan · January 2, 2012, 3:34pm

OK. I see. Thanks a lot!

udrescu_bogdan · January 16, 2012, 7:37am

Can you please answer me to my previous post. Are both of those threads created by the scheduler plugin?

udrescu_bogdan:
How does the scheduler plugin works? Does it executes the cron methods concurrent, each one on its own thread, or it execute only one at a time, all of them on a single thread?

And one more thing. I’m almost sure the scheduler blocks into one method because the “Client idle since” time is not changing. Normally it should change from 5 to 5 minutes, but when it happens it remain block with the same time forever. If I’m trying to close it from the Clients section, it will not work. If I stop it from the Batch Processors it work. I’m not sure but I think this is the moment when the processor goes to 100, at least this is what I noticed last time (It was morning, on 29 last month, the process was idle since 00:00 in the night, I stopped it and looked on a snapshoot with the processor usage, which increased around the time I closed the batch client).
I run methods at 5 minutes interval, 15 minutes, few hours and one day. Right now there are 6 cron methods running, though they should be at least 2 more.

Topic		Replies	Views
CPU Utilization Classic Servoy	7	4237	January 11, 2013
Servoy server blocks Classic Servoy	47	32802	August 17, 2011
Servoy memory usage question Classic Servoy	22	21410	November 14, 2012
Help with Java crashes Classic Servoy	2	2470	June 11, 2012
Server STOPS RESPONDING. Classic Servoy	8	5691	August 2, 2004

Server stops

Related topics