Derby
  1. Derby
  2. DERBY-3805

Create a simple Blob performance regression test

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.5.1.1
    • Fix Version/s: 10.5.1.1
    • Component/s: Test
    • Labels:
      None
    • Bug behavior facts:
      Performance

      Description

      A simple Blob performance regression test should exist to make it easier to detect performance degradations.
      The test should be reasonably quick to complete.

      My plan is to focus on embedded first, then continue and enable all tests for client/server if possible.
      Depending on the relative performance of embedded and client/server, the parameters might have to be tweaked to achieve an acceptable test duration.

      Note that the test results will only be valid for runs performed on the same machine. The intended purpose is to run the test against a clean trunk first, followed by a run with the patch possibly affecting the Blob performance.
      Also note that the compared builds must have been built with the same sanity mode.

      1. derby-3805-1a-blobaccesstest.diff
        19 kB
        Kristian Waagan
      2. derby-3805-1b-blobaccesstest.diff
        22 kB
        Kristian Waagan

        Issue Links

          Activity

          Hide
          Kristian Waagan added a comment -

          'derby-3805-1a-blobaccesstest.diff' is the first revision of the Blob performance regression test.

          Patch ready for review.

          Show
          Kristian Waagan added a comment - 'derby-3805-1a-blobaccesstest.diff' is the first revision of the Blob performance regression test. Patch ready for review.
          Hide
          Kristian Waagan added a comment -

          I'm attaching the two sets of output obtained from patch revision 1a. Don't pay to much attention to the absolute numbers, just the difference between the two sets. To make sure sanity checks didn't mess up the numbers, I ran with insane builds. The first set is from trunk, the second one is the same revision with DERBY-3766 (2a) applied.

          ----- clean trunk
          java version "1.6.0_06"
          Java(TM) SE Runtime Environment (build 1.6.0_06-b02)
          Java HotSpot(TM) Client VM (build 10.0-b22, mixed mode)
          .Test-testFetchSmallBlobs: framework:Embedded_40: run#0 iterations: 50 : elapsedTime(ms): 12311
          Test-testFetchSmallBlobs: framework:Embedded_40: run#1 iterations: 50 : elapsedTime(ms): 11505
          Test-testFetchSmallBlobs: framework:Embedded_40: run#2 iterations: 50 : elapsedTime(ms): 12715
          Test-testFetchSmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12110
          .Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40: run#0 iterations: 50 : elapsedTime(ms): 12479
          Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40: run#1 iterations: 50 : elapsedTime(ms): 12475
          Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40: run#2 iterations: 50 : elapsedTime(ms): 11511
          Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 11993
          .Test-testModifySmallBlobs: framework:Embedded_40: run#0 iterations: 50 : elapsedTime(ms): 11509
          Test-testModifySmallBlobs: framework:Embedded_40: run#1 iterations: 50 : elapsedTime(ms): 11410
          Test-testModifySmallBlobs: framework:Embedded_40: run#2 iterations: 50 : elapsedTime(ms): 13954
          Test-testModifySmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12682
          .Test-testFetchLargeBlobs: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 11023
          Test-testFetchLargeBlobs: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 9784
          Test-testFetchLargeBlobs: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 9812
          Test-testFetchLargeBlobs: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 9798
          .Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 1350
          Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 987
          Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 1000
          Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 993
          .Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 277649
          Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 277868
          Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 276765
          Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 277316
          .Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 5173
          Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 5163
          Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 5116
          Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 5139
          .Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 17344
          Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 17408
          Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 17437
          Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 17422
          .Test-testLargeBlobGetLength: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 11
          Test-testLargeBlobGetLength: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 2
          Test-testLargeBlobGetLength: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 2
          Test-testLargeBlobGetLength: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 2

          Time: 1,131.121

          OK (9 tests)

          real 18:51.7
          user 11:07.9
          sys 7:12.2

          ----- trunk with DERBY-3766 (2a) applied (I kept only the averages for conciseness)
          java version "1.6.0_06"
          Java(TM) SE Runtime Environment (build 1.6.0_06-b02)
          Java HotSpot(TM) Client VM (build 10.0-b22, mixed mode)
          Test-testFetchSmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 11841
          Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12468
          Test-testModifySmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12164
          Test-testFetchLargeBlobs: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 9773
          Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 999
          Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 272976
          Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 5196
          Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 159
          Test-testLargeBlobGetLength: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 2
          // Ignore this test (SingleRecordSelectClient) for now, it wasn't included in the clean trunk run.
          .Number of threads: 16
          Test duration (s): 60.009
          Number of transactions: 1165902
          Average throughput (tx/s): 19428.785682147678
          Test-testConcurrency: framework:Embedded_40: run#0 iterations: 1 : elapsedTime(ms): 108794

          Time: 1,181.123

          OK (10 tests)

          real 19:42.0
          user 12:51.2
          sys 7:17.3


          Looking at the results, the patch seems to have fixed one problem and not caused any regressions. This can be seen from the duration of the test 'testFetchLargeBlobPieceByPiece'. It dropped from 17422 ms to 159 ms!!!
          Also, there seems to be a serious problem when the Blob is modified and then read back byte by byte ('testFetchLargeBlobOneByOneByteModified'). My guess is this is either a buffering issue or a bad (positioning) algorithm somewhere.

          The current tests use around 20 minutes. We can add more tests, but I feel the test should take maximum one hour (preferably less).
          Any suggestions for new tests?
          Are any of the existing ones "useless"?

          Show
          Kristian Waagan added a comment - I'm attaching the two sets of output obtained from patch revision 1a. Don't pay to much attention to the absolute numbers, just the difference between the two sets. To make sure sanity checks didn't mess up the numbers, I ran with insane builds. The first set is from trunk, the second one is the same revision with DERBY-3766 (2a) applied. ----- clean trunk java version "1.6.0_06" Java(TM) SE Runtime Environment (build 1.6.0_06-b02) Java HotSpot(TM) Client VM (build 10.0-b22, mixed mode) .Test-testFetchSmallBlobs: framework:Embedded_40: run#0 iterations: 50 : elapsedTime(ms): 12311 Test-testFetchSmallBlobs: framework:Embedded_40: run#1 iterations: 50 : elapsedTime(ms): 11505 Test-testFetchSmallBlobs: framework:Embedded_40: run#2 iterations: 50 : elapsedTime(ms): 12715 Test-testFetchSmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12110 .Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40: run#0 iterations: 50 : elapsedTime(ms): 12479 Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40: run#1 iterations: 50 : elapsedTime(ms): 12475 Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40: run#2 iterations: 50 : elapsedTime(ms): 11511 Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 11993 .Test-testModifySmallBlobs: framework:Embedded_40: run#0 iterations: 50 : elapsedTime(ms): 11509 Test-testModifySmallBlobs: framework:Embedded_40: run#1 iterations: 50 : elapsedTime(ms): 11410 Test-testModifySmallBlobs: framework:Embedded_40: run#2 iterations: 50 : elapsedTime(ms): 13954 Test-testModifySmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12682 .Test-testFetchLargeBlobs: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 11023 Test-testFetchLargeBlobs: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 9784 Test-testFetchLargeBlobs: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 9812 Test-testFetchLargeBlobs: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 9798 .Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 1350 Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 987 Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 1000 Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 993 .Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 277649 Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 277868 Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 276765 Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 277316 .Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 5173 Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 5163 Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 5116 Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 5139 .Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 17344 Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 17408 Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 17437 Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 17422 .Test-testLargeBlobGetLength: framework:Embedded_40: run#0 iterations: 5 : elapsedTime(ms): 11 Test-testLargeBlobGetLength: framework:Embedded_40: run#1 iterations: 5 : elapsedTime(ms): 2 Test-testLargeBlobGetLength: framework:Embedded_40: run#2 iterations: 5 : elapsedTime(ms): 2 Test-testLargeBlobGetLength: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 2 Time: 1,131.121 OK (9 tests) real 18:51.7 user 11:07.9 sys 7:12.2 ----- trunk with DERBY-3766 (2a) applied (I kept only the averages for conciseness) java version "1.6.0_06" Java(TM) SE Runtime Environment (build 1.6.0_06-b02) Java HotSpot(TM) Client VM (build 10.0-b22, mixed mode) Test-testFetchSmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 11841 Test-testFetchSmallBlobsInaccurateLength: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12468 Test-testModifySmallBlobs: framework:Embedded_40:iterations: 50 : Avg elapsedTime(ms): 12164 Test-testFetchLargeBlobs: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 9773 Test-testFetchLargeBlobOneByOneByteBaseline: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 999 Test-testFetchLargeBlobOneByOneByteModified: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 272976 Test-testFetchLargeBlobOneByOneByte: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 5196 Test-testFetchLargeBlobPieceByPiece: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 159 Test-testLargeBlobGetLength: framework:Embedded_40:iterations: 5 : Avg elapsedTime(ms): 2 // Ignore this test (SingleRecordSelectClient) for now, it wasn't included in the clean trunk run. .Number of threads: 16 Test duration (s): 60.009 Number of transactions: 1165902 Average throughput (tx/s): 19428.785682147678 Test-testConcurrency: framework:Embedded_40: run#0 iterations: 1 : elapsedTime(ms): 108794 Time: 1,181.123 OK (10 tests) real 19:42.0 user 12:51.2 sys 7:17.3 Looking at the results, the patch seems to have fixed one problem and not caused any regressions. This can be seen from the duration of the test 'testFetchLargeBlobPieceByPiece'. It dropped from 17422 ms to 159 ms!!! Also, there seems to be a serious problem when the Blob is modified and then read back byte by byte ('testFetchLargeBlobOneByOneByteModified'). My guess is this is either a buffering issue or a bad (positioning) algorithm somewhere. The current tests use around 20 minutes. We can add more tests, but I feel the test should take maximum one hour (preferably less). Any suggestions for new tests? Are any of the existing ones "useless"?
          Hide
          Kristian Waagan added a comment -

          Attached updated version (1b).

          Show
          Kristian Waagan added a comment - Attached updated version (1b).
          Hide
          Kristian Waagan added a comment -

          Committed patch 1b to trunk with revision 701351.
          I expect a number of changes will be made later, for instance tuning the run parameters (iterations/repetitions) and adding/removing tests.

          Show
          Kristian Waagan added a comment - Committed patch 1b to trunk with revision 701351. I expect a number of changes will be made later, for instance tuning the run parameters (iterations/repetitions) and adding/removing tests.
          Hide
          Kristian Waagan added a comment -

          Closing the issue, as the first version of the test has been completed.
          More work can be done, for instance investigate the performance with the client driver and add new/more tests.

          Show
          Kristian Waagan added a comment - Closing the issue, as the first version of the test has been completed. More work can be done, for instance investigate the performance with the client driver and add new/more tests.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development