Derby
  1. Derby
  2. DERBY-4709

Create test that parse client trace file to detect round-trips for Derby-4653

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 10.7.1.1
    • Fix Version/s: 10.7.1.1
    • Component/s: Test
    • Labels:
      None
    • Issue & fix info:
      Newcomer

      Description

      In DERBY-4653, Kristian suggested we have a test that parse the trace file to detect round-trip Connection.flowcommit() instead of calling getClientTransactionID() method. The existing test for DERBY-4653 is in J2EEDataSourceTest.testConnectionFlowCommit(). When this issue get fixed, the call for getClientTransactionID can be replace with trace file parsing.

      1. derby-4709-1a-alternative_test.diff
        11 kB
        Kristian Waagan
      2. derby-4709-1b-alternative_test.diff
        11 kB
        Kristian Waagan
      3. derby-4709-1c-alternative_test.diff
        11 kB
        Kristian Waagan

        Issue Links

          Activity

          Hide
          Lily Wei added a comment -

          Kristian suggests to parsing trace file mechanism to test

          Show
          Lily Wei added a comment - Kristian suggests to parsing trace file mechanism to test
          Hide
          Kristian Waagan added a comment -

          Attached a proposal (1a) for the alternative test.

          Patch ready for review.

          BTW, now that the other test is in use, I don't think it it necessary to remove it even if this issue is completed. At least it would be good to keep both around for some time to make sure the additional test is stable.

          Show
          Kristian Waagan added a comment - Attached a proposal (1a) for the alternative test. Patch ready for review. BTW, now that the other test is in use, I don't think it it necessary to remove it even if this issue is completed. At least it would be good to keep both around for some time to make sure the additional test is stable.
          Hide
          Lily Wei added a comment -

          Thanks Kristian for the alternative test. I think it is very promising. I just have two heads up.
          1. typo on invokations for testConnectionFlowCommitRollback. I am assuming it intent for invocation for comments and variable name
          2. When we check RDBCMM or RDBLLBCK, do care about when it was print to the trace file? I think it is also matter because it will show whether the Connection.commit() flow the commit or not and same goes to rollback.
          3. Do we care about how frequent the token is print to trace file? Will it be persistent throught out different releases? Does it depend on different department effort in turn of the trace message?

          Show
          Lily Wei added a comment - Thanks Kristian for the alternative test. I think it is very promising. I just have two heads up. 1. typo on invokations for testConnectionFlowCommitRollback. I am assuming it intent for invocation for comments and variable name 2. When we check RDBCMM or RDBLLBCK, do care about when it was print to the trace file? I think it is also matter because it will show whether the Connection.commit() flow the commit or not and same goes to rollback. 3. Do we care about how frequent the token is print to trace file? Will it be persistent throught out different releases? Does it depend on different department effort in turn of the trace message?
          Hide
          Kristian Waagan added a comment -

          Hi Lily,

          Thanks for looking at the patch. Below are my answers to your comments. When I say commit below, I mean both commit and rollback.

          1. That's a spelling error, yes. I'll correct it in an upcoming revision of the patch.

          2. I'm not sure I follow. Do you mean that we should correlate each commit flow to a JDBC call in the test?
          Since the only thing differing between the base end the extra run of the test sequence is the number of commits, my working theory has been that an increase in the number of commit flows must be caused by the redundant commits.

          3. No, we only care about the fact that invoking commit redundantly doesn't cause more commit commands to be flowed to the server.
          Without your fix for DERBY-4653, I think the base count was 13 and the extra count 339. The test only compares these two numbers, expecting them to be equal if the optimization is working. If an unrelated change causes Derby to flow two more commits for the test sequence, it doesn't matter as it will apply to both the base count and the extra count.
          The trace file is not part of our public API. However, the token I've used comes from the DRDA specification, and I don't see any reason why someone would change that. It has at least remained unchanged since the code was donated to Apache.

          If you enable the rollback-test and run the test you should hopefully see a reasonable failure message.

          Now, the most annoying issue I've found so far is the fact that the support files directories are deleted - which means that the trace file itself goes away...
          Has anyone solved this problem before?

          Show
          Kristian Waagan added a comment - Hi Lily, Thanks for looking at the patch. Below are my answers to your comments. When I say commit below, I mean both commit and rollback. 1. That's a spelling error, yes. I'll correct it in an upcoming revision of the patch. 2. I'm not sure I follow. Do you mean that we should correlate each commit flow to a JDBC call in the test? Since the only thing differing between the base end the extra run of the test sequence is the number of commits, my working theory has been that an increase in the number of commit flows must be caused by the redundant commits. 3. No, we only care about the fact that invoking commit redundantly doesn't cause more commit commands to be flowed to the server. Without your fix for DERBY-4653 , I think the base count was 13 and the extra count 339. The test only compares these two numbers, expecting them to be equal if the optimization is working. If an unrelated change causes Derby to flow two more commits for the test sequence, it doesn't matter as it will apply to both the base count and the extra count. The trace file is not part of our public API. However, the token I've used comes from the DRDA specification, and I don't see any reason why someone would change that. It has at least remained unchanged since the code was donated to Apache. If you enable the rollback-test and run the test you should hopefully see a reasonable failure message. Now, the most annoying issue I've found so far is the fact that the support files directories are deleted - which means that the trace file itself goes away... Has anyone solved this problem before?
          Hide
          Lily Wei added a comment -

          Thanks Kristian for the explanation and comments. I only want to bring to your attention in turn of the working theory. While it is true the increase in the number of commit flows caused by the redundant commits. The verification will be more accurate if we know the increase number between the base end and unconditional commit. The accurate number does not need to be exact. However, it will help if it is in a range.

          When I run J2EEDataSourceTest, I am also getting a failure due to the support files directories are deleted. It will be nice to know we had solved this problem before.

          Show
          Lily Wei added a comment - Thanks Kristian for the explanation and comments. I only want to bring to your attention in turn of the working theory. While it is true the increase in the number of commit flows caused by the redundant commits. The verification will be more accurate if we know the increase number between the base end and unconditional commit. The accurate number does not need to be exact. However, it will help if it is in a range. When I run J2EEDataSourceTest, I am also getting a failure due to the support files directories are deleted. It will be nice to know we had solved this problem before.
          Hide
          Kristian Waagan added a comment -

          Hi Lily,

          I'm sorry, I do not understand what you mean regarding a more accurate verification.
          With the exception of the extra commits, the exact same test sequence is run twice on a fresh connection. The test criteria may be expressed like:
          [common_work] = [common_work] + [unnecessary_commit_work]

          What number do you want to know the value of?

          Regarding the failure you are seeing, can you post the stack trace?
          Is the test itself failing, or is SupportFilesSetup.tearDown failing?

          Show
          Kristian Waagan added a comment - Hi Lily, I'm sorry, I do not understand what you mean regarding a more accurate verification. With the exception of the extra commits, the exact same test sequence is run twice on a fresh connection. The test criteria may be expressed like: [common_work] = [common_work] + [unnecessary_commit_work] What number do you want to know the value of? Regarding the failure you are seeing, can you post the stack trace? Is the test itself failing, or is SupportFilesSetup.tearDown failing?
          Hide
          Lily Wei added a comment -

          I want the number of RDBCMM or RDBRLLBCK right after [common_wok], then after [unnecessary_commit_work]. As I recall I was reading them from the trace number, the number is different. Is that true?

          This is the stack trace I am getting when applying your patch:
          $ java junit.textui.TestRunner org.apache.derbyTesting.functionTests.tests.jdbcap
          i.J2EEDataSourceTest
          .........................................
          ..........F.......
          Time: 36.77
          There was 1 failure:
          1) Client/Serverjunit.framework.AssertionFailedError: extinout\ds_cp_base_commit.trace
          at org.apache.derbyTesting.junit.DropDatabaseSetup.removeDir(DropDatabaseSetup.java:130)
          at org.apache.derbyTesting.junit.DropDatabaseSetup.access$000(DropDatabaseSetup.java:35)
          at org.apache.derbyTesting.junit.DropDatabaseSetup$1.run(DropDatabaseSetup.java:105)
          at java.security.AccessController.doPrivileged(Native Method)
          at org.apache.derbyTesting.junit.DropDatabaseSetup.removeDirectory(DropDatabaseSetup.java:10
          2)
          at org.apache.derbyTesting.junit.DropDatabaseSetup.removeDirectory(DropDatabaseSetup.java:98
          )
          at org.apache.derbyTesting.junit.SupportFilesSetup.tearDown(SupportFilesSetup.java:128)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:20)
          at junit.extensions.TestSetup.run(TestSetup.java:23)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
          at junit.extensions.TestSetup.run(TestSetup.java:23)
          at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

          FAILURES!!!
          Tests run: 58, Failures: 1, Errors: 0

          Do I miss something or is it something in my environment?

          Show
          Lily Wei added a comment - I want the number of RDBCMM or RDBRLLBCK right after [common_wok] , then after [unnecessary_commit_work] . As I recall I was reading them from the trace number, the number is different. Is that true? This is the stack trace I am getting when applying your patch: $ java junit.textui.TestRunner org.apache.derbyTesting.functionTests.tests.jdbcap i.J2EEDataSourceTest ......................................... ..........F....... Time: 36.77 There was 1 failure: 1) Client/Serverjunit.framework.AssertionFailedError: extinout\ds_cp_base_commit.trace at org.apache.derbyTesting.junit.DropDatabaseSetup.removeDir(DropDatabaseSetup.java:130) at org.apache.derbyTesting.junit.DropDatabaseSetup.access$000(DropDatabaseSetup.java:35) at org.apache.derbyTesting.junit.DropDatabaseSetup$1.run(DropDatabaseSetup.java:105) at java.security.AccessController.doPrivileged(Native Method) at org.apache.derbyTesting.junit.DropDatabaseSetup.removeDirectory(DropDatabaseSetup.java:10 2) at org.apache.derbyTesting.junit.DropDatabaseSetup.removeDirectory(DropDatabaseSetup.java:98 ) at org.apache.derbyTesting.junit.SupportFilesSetup.tearDown(SupportFilesSetup.java:128) at junit.extensions.TestSetup$1.protect(TestSetup.java:20) at junit.extensions.TestSetup.run(TestSetup.java:23) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) FAILURES!!! Tests run: 58, Failures: 1, Errors: 0 Do I miss something or is it something in my environment?
          Hide
          Kristian Waagan added a comment -

          Well, the first iteration of testConnectionFlowCommitRollback gives you the count after [common_work] (15 as the test stands now).
          The second iteration of testConnectionFlowCommitRollback gives you the count after ([common_work] + [unnecessary_commit_work]) (also 15 when the optimization works).
          If these two counts differ, the test fails. Note that [common_work] and [unnecessary_commit_work] are interspersed (in the second iteration of testConnectionFlowCommitRollback ), so there isn't really a notion of before and after.
          Before the fix for DERBY-4653, the second count was 340 (15+325).

          If I add another query to the test sequence, the numbers will change. Thats why I first run only [common_work] to obtain the base count, and then ([common_work] + [unnecessary_commit_work]). If I used a hard-coded number for the base run, the test would be more sensitive to changes in other areas of the code.
          You can easily obtain these counts from the trace file manually during debugging. The trace level can be changed from PROTOCOL to ALL (I'll do that in the next revision of the patch), then it will be a lot easier to assoicate a commit flow with a JDBC call.

          You are probably seeing the error because you are running on Windows. The behavior of the file operations are different there, specifically you aren't allowed to delete a file when it is open for reading.
          Looking at the test and client driver tracing code, the real reasons are:
          1) I forgot to close the pysical connection (i.e. getPooledConnection() and getXAConnection()).
          2) There's a bug in the client driver tracing code, where the stream to the trace file isn't closed.

          I'll address 1 in the next revision of the patch, and will do Jira search for issue 2. If I can't find that it has been logged, I will do so.

          Thanks,

          Show
          Kristian Waagan added a comment - Well, the first iteration of testConnectionFlowCommitRollback gives you the count after [common_work] (15 as the test stands now). The second iteration of testConnectionFlowCommitRollback gives you the count after ( [common_work] + [unnecessary_commit_work] ) (also 15 when the optimization works). If these two counts differ, the test fails. Note that [common_work] and [unnecessary_commit_work] are interspersed (in the second iteration of testConnectionFlowCommitRollback ), so there isn't really a notion of before and after. Before the fix for DERBY-4653 , the second count was 340 (15+325). If I add another query to the test sequence, the numbers will change. Thats why I first run only [common_work] to obtain the base count, and then ( [common_work] + [unnecessary_commit_work] ). If I used a hard-coded number for the base run, the test would be more sensitive to changes in other areas of the code. You can easily obtain these counts from the trace file manually during debugging. The trace level can be changed from PROTOCOL to ALL (I'll do that in the next revision of the patch), then it will be a lot easier to assoicate a commit flow with a JDBC call. You are probably seeing the error because you are running on Windows. The behavior of the file operations are different there, specifically you aren't allowed to delete a file when it is open for reading. Looking at the test and client driver tracing code, the real reasons are: 1) I forgot to close the pysical connection (i.e. getPooledConnection() and getXAConnection()). 2) There's a bug in the client driver tracing code, where the stream to the trace file isn't closed. I'll address 1 in the next revision of the patch, and will do Jira search for issue 2. If I can't find that it has been logged, I will do so. Thanks,
          Hide
          Kristian Waagan added a comment -

          Attached patch 1b, with the following changes:
          o changed trace level from TRACE_PROTOCOL_FLOW to TRACE_ALL
          o fixed typo
          o added logic for closing the underlying physical connection (i.e. for ConnectionPool and XA data sources)

          I also logged DERBY-4717 for the issue with the open trace files, which is blocking a successful run of the test on Windows.

          Show
          Kristian Waagan added a comment - Attached patch 1b, with the following changes: o changed trace level from TRACE_PROTOCOL_FLOW to TRACE_ALL o fixed typo o added logic for closing the underlying physical connection (i.e. for ConnectionPool and XA data sources) I also logged DERBY-4717 for the issue with the open trace files, which is blocking a successful run of the test on Windows.
          Hide
          Kristian Waagan added a comment -

          Attached patch 1c, and committed it to trunk with revision 963243.

          Besides from a comment change, it is just a refreshed version of 1b.

          Show
          Kristian Waagan added a comment - Attached patch 1c, and committed it to trunk with revision 963243. Besides from a comment change, it is just a refreshed version of 1b.
          Hide
          Kristian Waagan added a comment -

          Resolved issue, awaits confirmation.

          Show
          Kristian Waagan added a comment - Resolved issue, awaits confirmation.
          Hide
          Kristian Waagan added a comment -

          Lily, can this issue be closed?

          Show
          Kristian Waagan added a comment - Lily, can this issue be closed?
          Hide
          Lily Wei added a comment -

          Thanks Kristian. Yes, please close this issue. Great job. I really appreciated it.

          Show
          Lily Wei added a comment - Thanks Kristian. Yes, please close this issue. Great job. I really appreciated it.
          Hide
          Kristian Waagan added a comment -

          Thanks, Lily.

          I asked because you are listed as reporter. In general I prefer that the reporter closes the issue he/she filed, as the reporter is generally in a better position to tell if the issue has indeed been addressed or not.

          Show
          Kristian Waagan added a comment - Thanks, Lily. I asked because you are listed as reporter. In general I prefer that the reporter closes the issue he/she filed, as the reporter is generally in a better position to tell if the issue has indeed been addressed or not.
          Hide
          Lily Wei added a comment -

          Sorry about that. I did not realize that. Thanks Kristian. I will do that next time.

          Show
          Lily Wei added a comment - Sorry about that. I did not realize that. Thanks Kristian. I will do that next time.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development