Menu ▾ ▴

#102 Worker stays active even though timeout has expired

closed
Philip Aston
Core engine (63)
5
2012-09-29
2007-02-14
MattyM76
No

From the Console - Running multiple processes running multiple threads with a duration set for the process.

I have noticed that most of the time at least one of the processes will continue running the script even though the console reports that all are finished.

Stopping the agent via the console does stop both the process and the agent.

I have not yet tried it with setting the console use to false.

Thanks,

Matt

Discussion

  • Philip Aston

    Philip Aston - 2007-02-24

    Logged In: YES
    user_id=2117
    Originator: NO

    I'd like you to take a thread dump of the worker process.

    If you are using a UNIX-like operating system, taking the thread dump is simple. Just use ps to identify the process id, then issue a kill -3 <pid> to send the process a SIGQUIT signal. You will find the thread dump in the terminal window that the agent was started with, its probably best to redirect the process output to a file (java net.grinder.Grinder > foo.txt) rather than cutting and pasting from the terminal.

    If you are on Windows, things are a little more involved. This is because worker processes are children of agent processes, and Java does not pass on Ctrl-Break signals to child processes. In this case, I would like you to run The Grinder under the SUN Java 6 JVM, and use the jstack command.

    Once you have a thread dump, please attach it to this bug.

    Thanks,

    • Phil
     

  • Nobody/Anonymous

    Nobody/Anonymous - 2007-03-06

    Logged In: NO

    Hi Philip,

    I did the test again and this time noticed with the ps -ef command that 3 processes out of the 10 were left running even though grinder.duration had elapsed.

    I did a kill -3 on one of the process id's and this is what I got:-

    [java] Full thread dump Java HotSpot(TM) Client VM (1.5.0_10-b03 mixed mode, sharing):

     [java] "SocketTimeout" daemon prio=1 tid=0x08434f10 nid=0x2273 waiting on condition [0xb131c000..0xb131c570]
 [java]     at java.lang.Thread.sleep(Native Method)
 [java]     at HTTPClient.SocketTimeout.run(StreamDemultiplexor.java:917)

 [java] "Grinder thread 4" daemon prio=1 tid=0x08648a48 nid=0x2271 in Object.wait() [0xb0c1a000..0xb0c1b4f0]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.doSleep (SleeperImplementation.java:191)
 [java]     - locked <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java :151)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java:135)
 [java]     at net.grinder.engine.process.ScriptContextImplementation.sleep(ScriptContextImplementation.java :99)
 [java]     at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
 [java]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 [java]     at java.lang.reflect.Method.invoke (Method.java:585)
 [java]     at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.__call_ _(PyObject.java)
 [java]     at org.python.core.PyInstance.invoke(PyInstance.java)
 [java]     at org.python.pycode._pyx0.__call__$4(./tests/dictionary_test.py:48)
 [java]     at org.python.pycode._pyx0.call_function (./tests/dictionary_test.py)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call (PyTableCode.java)
 [java]     at org.python.core.PyFunction.__call__(PyFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.invoke(PyObject.java )
 [java]     at org.python.core.PyInstance.__call__(PyInstance.java)
 [java]     at org.python.core.PyObject.__call__(PyObject.java)
 [java]     at net.grinder.engine.process.jython.JythonScriptEngine$JythonWorkerRunnable.run (JythonScriptEngine.java:343)
 [java]     at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:126)
 [java]     at java.lang.Thread.run(Thread.java:595)

 [java] "Grinder thread 3" daemon prio=1 tid=0x0837a670 nid=0x2270 in Object.wait() [0xb0c9b000..0xb0c9c470]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.doSleep (SleeperImplementation.java:191)
 [java]     - locked <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java :151)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java:135)
 [java]     at net.grinder.engine.process.ScriptContextImplementation.sleep(ScriptContextImplementation.java :99)
 [java]     at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
 [java]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 [java]     at java.lang.reflect.Method.invoke (Method.java:585)
 [java]     at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.__call_ _(PyObject.java)
 [java]     at org.python.core.PyInstance.invoke(PyInstance.java)
 [java]     at org.python.pycode._pyx0.__call__$4(./tests/dictionary_test.py:48)
 [java]     at org.python.pycode._pyx0.call_function (./tests/dictionary_test.py)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call (PyTableCode.java)
 [java]     at org.python.core.PyFunction.__call__(PyFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.invoke(PyObject.java )
 [java]     at org.python.core.PyInstance.__call__(PyInstance.java)
 [java]     at org.python.core.PyObject.__call__(PyObject.java)
 [java]     at net.grinder.engine.process.jython.JythonScriptEngine$JythonWorkerRunnable.run (JythonScriptEngine.java:343)
 [java]     at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:126)
 [java]     at java.lang.Thread.run(Thread.java:595)

 [java] "Grinder thread 2" daemon prio=1 tid=0x08379990 nid=0x226f in Object.wait() [0xb0d1d000..0xb0d1d7f0]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.doSleep (SleeperImplementation.java:191)
 [java]     - locked <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java :151)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java:135)
 [java]     at net.grinder.engine.process.ScriptContextImplementation.sleep(ScriptContextImplementation.java :99)
 [java]     at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
 [java]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 [java]     at java.lang.reflect.Method.invoke (Method.java:585)
 [java]     at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.__call_ _(PyObject.java)
 [java]     at org.python.core.PyInstance.invoke(PyInstance.java)
 [java]     at org.python.pycode._pyx0.__call__$4(./tests/dictionary_test.py:48)
 [java]     at org.python.pycode._pyx0.call_function (./tests/dictionary_test.py)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call (PyTableCode.java)
 [java]     at org.python.core.PyFunction.__call__(PyFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.invoke(PyObject.java )
 [java]     at org.python.core.PyInstance.__call__(PyInstance.java)
 [java]     at org.python.core.PyObject.__call__(PyObject.java)
 [java]     at net.grinder.engine.process.jython.JythonScriptEngine$JythonWorkerRunnable.run (JythonScriptEngine.java:343)
 [java]     at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:126)
 [java]     at java.lang.Thread.run(Thread.java:595)

 [java] "Grinder thread 1" daemon prio=1 tid=0x08378e38 nid=0x226e in Object.wait() [0xb0d9e000..0xb0d9e770]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.doSleep (SleeperImplementation.java:191)
 [java]     - locked <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java :151)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java:135)
 [java]     at net.grinder.engine.process.ScriptContextImplementation.sleep(ScriptContextImplementation.java :99)
 [java]     at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
 [java]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 [java]     at java.lang.reflect.Method.invoke (Method.java:585)
 [java]     at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.__call_ _(PyObject.java)
 [java]     at org.python.core.PyInstance.invoke(PyInstance.java)
 [java]     at org.python.pycode._pyx0.__call__$4(./tests/dictionary_test.py:48)
 [java]     at org.python.pycode._pyx0.call_function (./tests/dictionary_test.py)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call (PyTableCode.java)
 [java]     at org.python.core.PyFunction.__call__(PyFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.invoke(PyObject.java )
 [java]     at org.python.core.PyInstance.__call__(PyInstance.java)
 [java]     at org.python.core.PyObject.__call__(PyObject.java)
 [java]     at net.grinder.engine.process.jython.JythonScriptEngine$JythonWorkerRunnable.run (JythonScriptEngine.java:343)
 [java]     at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:126)
 [java]     at java.lang.Thread.run(Thread.java:595)

 [java] "Grinder thread 0" daemon prio=1 tid=0x083789d0 nid=0x226d in Object.wait() [0xb0e1e000..0xb0e1f6f0]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.doSleep (SleeperImplementation.java:191)
 [java]     - locked <0x88576b10> (a net.grinder.util.SleeperImplementation)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java :151)
 [java]     at net.grinder.util.SleeperImplementation.sleepNormal(SleeperImplementation.java:135)
 [java]     at net.grinder.engine.process.ScriptContextImplementation.sleep(ScriptContextImplementation.java :99)
 [java]     at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
 [java]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 [java]     at java.lang.reflect.Method.invoke (Method.java:585)
 [java]     at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.__call_ _(PyObject.java)
 [java]     at org.python.core.PyInstance.invoke(PyInstance.java)
 [java]     at org.python.pycode._pyx0.__call__$4(./tests/dictionary_test.py:48)
 [java]     at org.python.pycode._pyx0.call_function (./tests/dictionary_test.py)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call(PyTableCode.java)
 [java]     at org.python.core.PyTableCode.call (PyTableCode.java)
 [java]     at org.python.core.PyFunction.__call__(PyFunction.java)
 [java]     at org.python.core.PyMethod.__call__(PyMethod.java)
 [java]     at org.python.core.PyObject.invoke(PyObject.java )
 [java]     at org.python.core.PyInstance.__call__(PyInstance.java)
 [java]     at org.python.core.PyObject.__call__(PyObject.java)
 [java]     at net.grinder.engine.process.jython.JythonScriptEngine$JythonWorkerRunnable.run (JythonScriptEngine.java:343)
 [java]     at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:126)
 [java]     at java.lang.Thread.run(Thread.java:595)

 [java] "Message pump thread 0" daemon prio=1 tid=0x083848c0 nid=0x2256 runnable [0xb139d000..0xb139d5f0]
 [java]     at java.io.FileInputStream.readBytes(Native Method)
 [java]     at java.io.FileInputStream.read(FileInputStream.java:194)
 [java]     at java.io.BufferedInputStream.fill(BufferedInputStream.java :218)
 [java]     at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
 [java]     at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
 [java]     - locked <0x88532388> (a java.io.BufferedInputStream)
 [java]     at java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2213)
 [java]     at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java :2226)
 [java]     at java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:2694)
 [java]     at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:761)
 [java]     at java.io.ObjectInputStream.<init>(ObjectInputStream.java:277)
 [java]     at net.grinder.communication.StreamReceiver.waitForMessage(StreamReceiver.java:81)
 [java]     - locked <0x88532388> (a java.io.BufferedInputStream )
 [java]     at net.grinder.communication.MessagePump$MessagePumpRunnable.interruptibleRun(MessagePump.java:91)
 [java]     at net.grinder.util.thread.AbstractInterruptibleRunnable.run(AbstractInterruptibleRunnable.java :19)
 [java]     at java.lang.Thread.run(Thread.java:595)

 [java] "Low Memory Detector" daemon prio=1 tid=0x080a6338 nid=0x2253 runnable [0x00000000..0x00000000]

 [java] "CompilerThread0" daemon prio=1 tid=0x080a4dd0 nid=0x2252 waiting on condition [0x00000000..0xb17b0e58]

 [java] "Signal Dispatcher" daemon prio=1 tid=0x080a3e00 nid=0x2251 waiting on condition [0x00000000..0x00000000]

 [java] "Finalizer" daemon prio=1 tid=0x0809d0b8 nid=0x2250 in Object.wait () [0xb1ab4000..0xb1ab4770]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88532230> (a java.lang.ref.ReferenceQueue$Lock)
 [java]     at java.lang.ref.ReferenceQueue.remove (ReferenceQueue.java:116)
 [java]     - locked <0x88532230> (a java.lang.ref.ReferenceQueue$Lock)
 [java]     at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
 [java]     at java.lang.ref.Finalizer$FinalizerThread.run (Finalizer.java:159)

 [java] "Reference Handler" daemon prio=1 tid=0x0809c420 nid=0x224f in Object.wait() [0xb1b35000..0xb1b356f0]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x885322b0> (a java.lang.ref.Reference$Lock)
 [java]     at java.lang.Object.wait(Object.java:474)
 [java]     at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
 [java]     - locked <0x885322b0> (a java.lang.ref.Reference$Lock)

 [java] "main" prio=1 tid=0x0805d260 nid=0x224b in Object.wait() [0xbfffb000..0xbfffb8c8]
 [java]     at java.lang.Object.wait(Native Method)
 [java]     - waiting on <0x88536148> (a net.grinder.util.thread.Monitor)
 [java]     at java.lang.Object.wait(Object.java:474)
 [java]     at net.grinder.util.thread.Monitor.waitNoInterrruptException(Monitor.java:44)
 [java]     at net.grinder.engine.process.GrinderProcess.run (GrinderProcess.java:288)
 [java]     - locked <0x88536148> (a net.grinder.util.thread.Monitor)
 [java]     at net.grinder.engine.process.WorkerProcessEntryPoint.run(WorkerProcessEntryPoint.java:87)
 [java]     at net.grinder.engine.process.WorkerProcessEntryPoint.main(WorkerProcessEntryPoint.java:59)

 [java] "VM Thread" prio=1 tid=0x08099890 nid=0x224e runnable

 [java] "VM Periodic Task Thread" prio=1 tid=0x080a77e0 nid=0x2254 waiting on condition
     

  • Philip Aston

    Philip Aston - 2007-03-07

    Logged In: YES
    user_id=2117
    Originator: NO

    It looks like threads are hanging in SleeperImplementation.doSleep(), and that you are using beta 31. There was a change to the sleeper synchronisation in beta 32 which may well help, and a further change (fixing bug 1638659) coming up in beta 33. Can you try to reproduce with 32 please? (Or wait a few days until I have 33 out of the door and try with that).

    Thanks,

    • Phil
     

  • SourceForge Robot

    SourceForge Robot - 2007-03-27

    Logged In: YES
    user_id=1312539
    Originator: NO

    This Tracker item was closed automatically by the system. It was
    previously set to a Pending status, and the original submitter
    did not respond within 30 days (the time period specified by
    the administrator of this Tracker).

     

Log in to post a comment.