previous next

Step 6 - Performance analysis

In the last section we put the InsertStringBuffer class through much more rigorous testing and found some problems that were not tested by the original test suite. Now, if we were to add another implementation of a StringBuffer algorithm, we would already have a much more precise description of the kind of things that this class would need to do. (On the other hand, the tests in the last section were specifically targeted on weaknesses of a particular implementation. A new implementation with different weaknesses might break under different conditions. That's where a general Brute-Force test might come in handy again.)
Further, we could now refactor the InsertStringBuffer class without the fear that this would break the code.

However, the original reason for writing InsertStringBuffer was to fix the performance problem of the ConcatStringBuffer algorithm. After all, both classes provide the same logical functionality, so if performance was irrelevant (and in most cases it is), ConcatStringBuffer would be completely sufficient. More than that, it would be preferrable to InsertStringBuffer, since it is much simpler, and therefore less likely to contain bugs, as the last step has demonstrated.

Manually interpreted performance check

So let's have some fun and compare the run-time performance of the two classes. Add a new fixture class called "Step6", register it in the TestSuite, and add this code to it:

'Step6.cls

Option Explicit

Implements IFixture

Private m_assert As IAssert
Private m_timer As PerformanceCounter
Private m_stringBuffer As IStringBuffer

Private Const NumPowers As Long = 6
Private m_taskSize(NumPowers) As Long

Private Sub IFixture_Setup(assert As IAssert)
Dim l As Long
  Set m_assert = assert
  Set m_timer = New PerformanceCounter
  m_assert.EnablePrintMsg
  
  For l = 0 To NumPowers
    m_taskSize(l) = 2 ^ (l + 5)
  Next l
End Sub

Private Sub IFixture_TearDown()
End Sub

Private Sub FillBuffer(ByVal numIterations As Long)
Dim l As Long
  m_timer.Start
  
  For l = 0 To numIterations
    m_stringBuffer.Append "This is the " & l & _
               "nd line in the string." & vbCrLf
  Next l
  
  m_timer.Finish
  
  m_assert.PrintMsg vbTab & numIterations & vbTab & " Strings: " & _
      vbTab & Round(m_timer.MilliSeconds, 3) & vbTab & " ms", "msg1"
  Set m_stringBuffer = Nothing    'be sure to clear the buffer
End Sub


Public Sub TestConcatStringBuffer()
Dim l As Long
  For l = 0 To NumPowers
    Set m_stringBuffer = New ConcatStringBuffer
    FillBuffer m_taskSize(l)
  Next l
End Sub

Public Sub TestInsertStringBuffer()
Dim l As Long
  For l = 0 To NumPowers
    Set m_stringBuffer = New InsertStringBuffer
    FillBuffer m_taskSize(l)
  Next l
End Sub

This code just fills a StringBuffer with a specified number of Strings and measures how long it takes. This is a performance test. It is not a unit test, since it requires a human to read and interpret its results. We could turn it into a unit test by asserting certain properties of the run-time performance, for example that processing twice as many strings will require less than 2.5 times as much time. But for now, let's just look at the results:

Step6.TestConcatStringBuffer :  32  Strings:  0.397  ms
Step6.TestConcatStringBuffer :  64  Strings:  1.054  ms
Step6.TestConcatStringBuffer :  128  Strings:  4.505  ms
Step6.TestConcatStringBuffer :  256  Strings:  20.089  ms
Step6.TestConcatStringBuffer :  512  Strings:  79.743  ms
Step6.TestConcatStringBuffer :  1024  Strings:  322.873  ms
Step6.TestConcatStringBuffer :  2048  Strings:  1490.938  ms
Step6.TestConcatStringBuffer :  4096  Strings:  8416.406  ms
Step6.TestConcatStringBuffer :  8192  Strings:  49201.083  ms
Step6.TestConcatStringBuffer :  16384  Strings:  209781.177  ms
Step6.TestConcatStringBuffer :  32768  Strings:  872458.042  ms
        
Step6.TestInsertStringBuffer :  32  Strings:  0.352  ms
Step6.TestInsertStringBuffer :  64  Strings:  0.646  ms
Step6.TestInsertStringBuffer :  128  Strings:  1.275  ms
Step6.TestInsertStringBuffer :  256  Strings:  2.502  ms
Step6.TestInsertStringBuffer :  512  Strings:  4.973  ms
Step6.TestInsertStringBuffer :  1024  Strings:  10.069  ms
Step6.TestInsertStringBuffer :  2048  Strings:  21.995  ms
Step6.TestInsertStringBuffer :  4096  Strings:  48.367  ms
Step6.TestInsertStringBuffer :  8192  Strings:  105.545  ms
Step6.TestInsertStringBuffer :  16384  Strings:  215.142  ms
Step6.TestInsertStringBuffer :  32768  Strings:  436.549  ms

Your results will of course be different, depending on the power of your computer, but the main point here is the relative performance of the two algorithms: Processing 2 times as many strings takes 4-6 times as much time for the ConcatStringBuffer, while it only takes a little more than 2 times as much time for the InsertStringBuffer (A formal analysis of the InsertStringBuffer algorithm would show that its run-time is a little worse than linear, since the time required for growing the buffer gets worse as the buffer gets larger). In absolute terms, ConcatStringBuffer needs 32 times as much time as InsertStringBuffer for processing 1024 strings, and 2000 times as much time for processing 32000 strings.

However, for less than 64 strings, the performance of ConcatStringBuffer seems totally adequate when compared to the faster implementation, so for most tasks where only a small number of strings is to be concatenated, using the traditional str = str & "some text" seems very reasonable.

Automatic (unsupervised) performance check

Should the Step6 fixture be a permanent part of our TestSuite for the StringBuffer class? That depends on how important this particular performance requirement is, and how much time each run of the tests should take. If it should indeed be part of every run, I would decrease the number of processed strings to a point where the whole test runs very quickly, so that it does not slow down the development cycle.
Further, the test should be fully automatic, so that no human interpretation of the results is required. A minimal check could be that InsertStringBuffer is faster than ConcatStringBuffer for the same amount of strings. A more rigorous test could check certain statistical properties of the performance curve.
Since the whole motivation of writing the InsertStringBuffer class was to have something that is faster than the iterative concatenation algorithm, one could argue that the performance is indeed part of the specification, and that it should therefore be part of the test suite. This will allow to work on the implementation without the fear that some change will introduce another performance hog.

So let's turn this into an automatic unit test. Create a new fixture called "Step6a.cls" and add this code to it:

'Step6a.cls

Option Explicit

Implements IFixture

Private m_assert As IAssert
Private m_timer As PerformanceCounter
Private m_stringBuffer As IStringBuffer

Private Const NumPowers As Long = 6
Private m_taskSize(NumPowers) As Long
Private m_concatResults(NumPowers) As Double
Private m_insertResults(NumPowers) As Double

Private Sub IFixture_Setup(assert As IAssert)
  Set m_assert = assert
  Set m_timer = New PerformanceCounter
  m_assert.EnablePrintMsg
  
  Dim l As Long
  For l = 0 To NumPowers
    m_taskSize(l) = 2 ^ (l + 5)
  Next l
End Sub

Private Sub IFixture_TearDown()
End Sub

Private Function CompareMessage(ByVal expected As Double, _
                          ByVal actual As Double) As String
  CompareMessage = "Expected less than " & Round(expected, 3) & _
                   ", but was: " & Round(actual, 3)
End Function

Private Function FillBuffer(ByVal numIterations As Long) As Double
Dim l As Long
  m_timer.Start
  
  For l = 0 To numIterations
    m_stringBuffer.Append "This is the " & l & _
               "nd line in the string." & vbCrLf
  Next l
  
  m_timer.Finish
  
  m_assert.PrintMsg numIterations & " Strings: " & _
                    Round(m_timer.MilliSeconds, 3) & " ms", "msg1"
  Set m_stringBuffer = Nothing    'be sure to clear the buffer
  
  FillBuffer = m_timer.MilliSeconds
End Function


Public Sub TestConcatStringBuffer()
Dim l As Long
Dim ratio As Single
  For l = 0 To NumPowers
    Set m_stringBuffer = New ConcatStringBuffer
    m_concatResults(l) = FillBuffer(m_taskSize(l))
  Next l
End Sub

Public Sub TestInsertStringBuffer()
Dim l As Long
Dim ratio As Single
  For l = 0 To NumPowers
    Set m_stringBuffer = New InsertStringBuffer
    m_insertResults(l) = FillBuffer(m_taskSize(l))
    m_assert.Verify m_insertResults(l) < m_concatResults(l), _
                 "compare Concat and Insert", vbUnit_Assertion
    If l > 0 Then
      If m_insertResults(l - 1) <> 0 Then
        ratio = m_insertResults(l) / m_insertResults(l - 1)
        m_assert.PrintMsg "Ratio: " & ratio
        m_assert.Verify ratio < 2.5, "checkRatio" & l & ": " & _
                    CompareMessage(2.5, ratio), vbUnit_Assertion
      End If
    End If
  Next l
End Sub

Make sure to add this fixture to the test suite. You can now also remove the original Step6 from the test suite, since we are turning the experimental performance test into a fully automatic unit test. Hence, your test suite should now look like this:

'vbUnitTutorialSuite.Suite

Private Function ISuite_Suite() As ITest
Dim suite As New TestSuite
  suite.SuiteName = "vbUnit Tutorial Suite"
  
  suite.AddFixture New TestStringBuffer
'  suite.AddFixture New Step6
  suite.AddFixture New Step6a
  
  Set ISuite_Suite = suite
End Function

The code in Step6a.cls fills an array with the performance results of the ConcatStringBuffer implementation:

m_concatResults(l) = FillBuffer(m_taskSize(l))

Then it runs InsertStringBuffer with the same tasks and asserts that it is always faster than ConcatStringBuffer:

m_assert.Verify m_insertResults(l) < m_concatResults(l), "compare Concat and Insert", vbUnit_Assertion

Further, the unit test checks that doubling the task size increases run-time by not more than 2.5 times:

m_assert.Verify ratio < 2.5, "checkRatio" & l & ": " & CompareMessage(2.5, ratio), vbUnit_Assertion

Note that the ratio will eventually get larger than 2.5 as the task size increases, since the InsertStringBuffer algorithm does not quite run in linear time, so this assertion holds only for a specific range of task sizes. If you want to play around with this, you should disable the ConcatStringBuffer test (since it will just take too much time), and then increase NumPowers to make the task size for the InsertStringBuffer larger. Also, this test is not totally deterministic, since Windows is not a real-time operating system. Sometimes your computer may be busy with some background tasks while running this test, and the performance measurement will fail. However, for most runs you should get something like this:

   OK (8 Tests, 29 Assertions)  

   MESSAGES: 20   
 Step6a.TestConcatStringBuffer : 32 Strings: 0.407 ms
Step6a.TestConcatStringBuffer : 64 Strings: 1.232 ms
Step6a.TestConcatStringBuffer : 128 Strings: 4.942 ms
Step6a.TestConcatStringBuffer : 256 Strings: 20.784 ms
Step6a.TestConcatStringBuffer : 512 Strings: 81.331 ms
Step6a.TestConcatStringBuffer : 1024 Strings: 320.021 ms
Step6a.TestConcatStringBuffer : 2048 Strings: 1402.208 ms
Step6a.TestInsertStringBuffer : 32 Strings: 0.363 ms
Step6a.TestInsertStringBuffer : 64 Strings: 0.646 ms
Step6a.TestInsertStringBuffer : Ratio: 1.777692
Step6a.TestInsertStringBuffer : 128 Strings: 1.35 ms
Step6a.TestInsertStringBuffer : Ratio: 2.09087
Step6a.TestInsertStringBuffer : 256 Strings: 2.551 ms
Step6a.TestInsertStringBuffer : Ratio: 1.889694
Step6a.TestInsertStringBuffer : 512 Strings: 4.98 ms
Step6a.TestInsertStringBuffer : Ratio: 1.952141
Step6a.TestInsertStringBuffer : 1024 Strings: 10.334 ms
Step6a.TestInsertStringBuffer : Ratio: 2.075175
Step6a.TestInsertStringBuffer : 2048 Strings: 24.718 ms
Step6a.TestInsertStringBuffer : Ratio: 2.391944

Severity Levels

There are two more things to note here. The first is the additional parameter given to the assertion:

m_assert.Verify ratio < 2.5, "checkRatio" & l & ": " & CompareMessage(2.5, ratio), vbUnit_Assertion

This optional parameter modifies the Severity Level for this assertion. The severity determines what happens if an assertion fails. By default, the severity level is vbUnit_Method. This means, after a failed assertion, execution terminates the current TestMethod and proceeds to the next one. The severity could also be higher: If it is set to vbUnit_Fixture, a failed assertion will terminate the current Fixture. A failed assertion with the severity level vbUnit_AllTests will completely stop the TestRunner. This may be useful for checking whether a required resource is available without which all further tests would be meaningless.
But it is also possible to decrease the severity level of an assertion. Setting the severity to vbUnit_Assertion means that a failed assertion will not exit the current test method. Instead, execution will continue at the next line within the same test method. In this test we are lowering the severity level because the test may fail once in a while, and we would still like to continue testing to see what the remaining iterations of the loop will do. For an example of this, just run this test a few times. Before long, you should get something like this:

   FAILURES: 1  
 Step6a.TestConcatStringBuffer : 32 Strings: 0.408 ms
Step6a.TestConcatStringBuffer : 64 Strings: 1.059 ms
Step6a.TestConcatStringBuffer : 128 Strings: 4.555 ms
Step6a.TestConcatStringBuffer : 256 Strings: 20.086 ms
Step6a.TestConcatStringBuffer : 512 Strings: 79.85 ms
Step6a.TestConcatStringBuffer : 1024 Strings: 314.986 ms
Step6a.TestConcatStringBuffer : 2048 Strings: 1408.038 ms
Step6a.TestInsertStringBuffer : 32 Strings: 0.358 ms
Step6a.TestInsertStringBuffer : 64 Strings: 0.638 ms
Step6a.TestInsertStringBuffer : Ratio: 1.781591
Step6a.TestInsertStringBuffer : 128 Strings: 1.272 ms
Step6a.TestInsertStringBuffer : Ratio: 1.99387
Step6a.TestInsertStringBuffer : 256 Strings: 2.546 ms
Step6a.TestInsertStringBuffer : Ratio: 2.001537
Step6a.TestInsertStringBuffer : 512 Strings: 7.746 ms
Step6a.TestInsertStringBuffer : Ratio: 3.042019
 Step6a.TestInsertStringBuffer : Verify failed : checkRatio4: Expected less than 2.5, but was: 3.042
 Step6a.TestInsertStringBuffer : 1024 Strings: 10.088 ms
Step6a.TestInsertStringBuffer : Ratio: 1.302258
Step6a.TestInsertStringBuffer : 2048 Strings: 22.729 ms
Step6a.TestInsertStringBuffer : Ratio: 2.253123

In this case, the time for processing 512 strings was 3.042 times longer than that for 256 strings, so the ratio was larger than the allowed 2.5. With a default severity level, the test method would have stopped at this point. But in this particular case, we tolerate the occasional failure and want to let the test run to its end, so the severity level is reduced.

Disabling PrintMsg

The second and last thing to note is the amount of messages that this test still produces. We are now finished playing with the performance of InsertStringBuffer and would just like to make this a permanent part of our test suite, without having to look at 20 lines of debug messages every time the tests are run. Not only do these messages become annoying and bothersome to read, they may even distract your attention from something important later on. So let's turn them off. This is easy, just comment out the line m_assert.EnablePrintMsg in the Setup method of the fixture:

'Step6a.Setup

Private Sub IFixture_Setup(assert As IAssert)
  Set m_assert = assert
  Set m_timer = New PerformanceCounter
'  m_assert.EnablePrintMsg
  
  Dim l As Long
  For l = 0 To NumPowers
    m_taskSize(l) = 2 ^ (l + 5)
  Next l
End Sub

Now all calls to PrintMsg in this fixture will be ignored. However, should you ever need to work again on this fixture, you can quickly turn them back on by uncommenting this line again. For now, run the tests again and you should just get something like this:

   OK (8 Tests, 29 Assertions)  

Summary

In this step we have manually tested some things with m_assert.PrintMsg. Later we have turned the manual tests into unit tests by making them fully automatic, which means that they require no further human interpretation.

  • If a test should be part of the test suite for a component, make it fully automatic and unsupervised.
  • Turn off PrintMsg when you are done with a component. You can always turn it back on later.
  • Each assertion has a severity level that determines where execution continues after a failed assertion.
  • The default severity level is vbUnit_Method, which means that the current test method will be terminated after a failed assertion. Hence, by default, a failed assertion is treated like an error.
  • The severity level can be changed with m_assert.SetSeverity, or by adding the optional last parameter to the assertion itself
previous next