Derby
  1. Derby
  2. DERBY-5617

Improve process handling in SpawnedProcess

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.9.1.0
    • Fix Version/s: 10.8.3.0, 10.9.1.0
    • Component/s: Test
    • Labels:
      None

      Description

      SpawnedProcess wraps a java.lang.Process and performs various tasks related to process handling. Using external processes from Java is somewhat tricky, in part because of sub-optimal behavior in the methods provided by Process.

      I plan to implement the following improvements:
      a) Kill the process after a timeout (the clock starts ticking when you create the SpawnedProcess instance).
      b) Don't let interrupts stop SpawnedProcess from waiting for / terminating the process.
      c) Clean up the Process properly.

      1. derby-5617-1a-spawnedprocess_improvements.diff
        21 kB
        Kristian Waagan
      2. derby-5617-2a-join_destroy_ordering.diff
        2 kB
        Kristian Waagan
      3. derby-5617-3a-timer_as_daemon_thread.diff
        0.8 kB
        Kristian Waagan

        Activity

        Hide
        Kristian Waagan added a comment -

        Closing issue.

        Show
        Kristian Waagan added a comment - Closing issue.
        Hide
        Kristian Waagan added a comment -

        Backported to 10.8, together with DERBY-5608, with revision 1327102.
        Resolving issue.

        Show
        Kristian Waagan added a comment - Backported to 10.8, together with DERBY-5608 , with revision 1327102. Resolving issue.
        Hide
        Kristian Waagan added a comment -

        The next step for this issue is backporting it (required by DERBY-5608). I'll wait for a little while longer to allow people to analyze their test results first, reducing the chance of backporting something that causes trouble.

        Show
        Kristian Waagan added a comment - The next step for this issue is backporting it (required by DERBY-5608 ). I'll wait for a little while longer to allow people to analyze their test results first, reducing the chance of backporting something that causes trouble.
        Hide
        Kristian Waagan added a comment -

        Attached patch 3a, committed to trunk with revision 1294592.

        The patch addresses the fact that I have forgotten to make the timer run as a daemon. This may cause the VM to stay alive for up to 45 minutes longer than it should have to.

        Show
        Kristian Waagan added a comment - Attached patch 3a, committed to trunk with revision 1294592. The patch addresses the fact that I have forgotten to make the timer run as a daemon. This may cause the VM to stay alive for up to 45 minutes longer than it should have to.
        Hide
        Kristian Waagan added a comment -

        Attaching patch 2a.

        Thanks, Myrna.
        I have messed up the order in which the process is cleaned up, which includes closing the streams assoicated with the process, and waiting for the output drainer streams to terminate. On some machines this causes truncated output (scheduler/timing/performance issue), and in any case the ordering is incorrect.

        Fixed with patch 2a, which also takes care of a few typos. Committed to trunk with revision 1291631.

        Show
        Kristian Waagan added a comment - Attaching patch 2a. Thanks, Myrna. I have messed up the order in which the process is cleaned up, which includes closing the streams assoicated with the process, and waiting for the output drainer streams to terminate. On some machines this causes truncated output (scheduler/timing/performance issue), and in any case the ordering is incorrect. Fixed with patch 2a, which also takes care of a few typos. Committed to trunk with revision 1291631.
        Hide
        Myrna van Lunteren added a comment -

        I think perhaps there might have been some fall out of this check-in on Feb 16, with ibm 1.5.
        See: http://people.apache.org/~myrnavl/derby_test_results/main/linux/testSummary-1245297.html
        http://people.apache.org/~myrnavl/derby_test_results/main/linux/testlog/ibm15/1245297-suites.All_diff.txt
        There are 3 failures (the fourth is DERBY-5377) that look related and there are some additional similar failures...
        ------------------------------
        1) test_05_MaxThreads_Neg1(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)junit.framework.AssertionFailedError: Could not find expectedString:Max threads changed to 0. in output:<STDOUT> <END STDOUT>
        <STDERR><END STDERR>

        at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:520)
        at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_05_MaxThreads_Neg1(NetworkServerControlApiTest.java:361)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        2) test_09_MaxThreads_Invalid(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)junit.framework.AssertionFailedError: Could not find expectedString:Max threads changed to 10000. in output:<STDOUT> <END STDOUT>
        <STDERR><END STDERR>

        at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:520)
        at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_09_MaxThreads_Invalid(NetworkServerControlApiTest.java:422)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        3) test_20_TimeSlice_a(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)junit.framework.AssertionFailedError: Could not find expectedString:Time slice changed to 8000. in output:<STDOUT> <END STDOUT>
        <STDERR><END STDERR>

        at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:520)
        at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_20_TimeSlice_a(NetworkServerControlApiTest.java:559)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        -----------------------

        Show
        Myrna van Lunteren added a comment - I think perhaps there might have been some fall out of this check-in on Feb 16, with ibm 1.5. See: http://people.apache.org/~myrnavl/derby_test_results/main/linux/testSummary-1245297.html http://people.apache.org/~myrnavl/derby_test_results/main/linux/testlog/ibm15/1245297-suites.All_diff.txt There are 3 failures (the fourth is DERBY-5377 ) that look related and there are some additional similar failures... ------------------------------ 1) test_05_MaxThreads_Neg1(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)junit.framework.AssertionFailedError: Could not find expectedString:Max threads changed to 0. in output:<STDOUT> <END STDOUT> <STDERR><END STDERR> at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:520) at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_05_MaxThreads_Neg1(NetworkServerControlApiTest.java:361) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) 2) test_09_MaxThreads_Invalid(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)junit.framework.AssertionFailedError: Could not find expectedString:Max threads changed to 10000. in output:<STDOUT> <END STDOUT> <STDERR><END STDERR> at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:520) at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_09_MaxThreads_Invalid(NetworkServerControlApiTest.java:422) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) 3) test_20_TimeSlice_a(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)junit.framework.AssertionFailedError: Could not find expectedString:Time slice changed to 8000. in output:<STDOUT> <END STDOUT> <STDERR><END STDERR> at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:520) at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_20_TimeSlice_a(NetworkServerControlApiTest.java:559) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) -----------------------
        Hide
        Kristian Waagan added a comment -

        A few things to consider:
        o Is the outer timeout too high?
        It is set to 45 minutes, and the clock starts ticking when you create the SpawnedProcess instance. This mechanism protects against inter-process communications hangs/bugs, for instance when a bug in the DRDA flow causes both sides to wait for more data. It must be high enough to avoid killing running test suites. This has been made configurable in case someone are running on painfully slow machines, or want to kill tests sooner.
        o Should there be a default timeout also for complete(), or is it okay to rely on the timeout above?
        o It may be useful to review the usages of complete(), and consider if a timeout value should be specified explicitly. This would be context-/test-dependent.

        I don't plan any further work on this issue, but won't close it yet in case there are problems to fix with the new code.

        Show
        Kristian Waagan added a comment - A few things to consider: o Is the outer timeout too high? It is set to 45 minutes, and the clock starts ticking when you create the SpawnedProcess instance. This mechanism protects against inter-process communications hangs/bugs, for instance when a bug in the DRDA flow causes both sides to wait for more data. It must be high enough to avoid killing running test suites. This has been made configurable in case someone are running on painfully slow machines, or want to kill tests sooner. o Should there be a default timeout also for complete(), or is it okay to rely on the timeout above? o It may be useful to review the usages of complete(), and consider if a timeout value should be specified explicitly. This would be context-/test-dependent. I don't plan any further work on this issue, but won't close it yet in case there are problems to fix with the new code.
        Hide
        Kristian Waagan added a comment -

        Attaching patch 1a, implementing the items a-c.

        This patch has been tested by Myrna (see DERBY-5601), and seems to be ready for commit.

        Committed the patch to trunk with revision 1244444.

        Show
        Kristian Waagan added a comment - Attaching patch 1a, implementing the items a-c. This patch has been tested by Myrna (see DERBY-5601 ), and seems to be ready for commit. Committed the patch to trunk with revision 1244444.

          People

          • Assignee:
            Kristian Waagan
            Reporter:
            Kristian Waagan
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development