Mark Gilbert's Blog

Science and technology, served light and fluffy.

Web Service Testing – Part 2 of 4

In Part 1 of this series, I mentioned that each test hits the web service twice – once to do an “include by X” search, and the second to do an “exclude by X” search, where X was some search criteria.  This uncovered an interesting performance issue which I’ll explain in this post.

Some days the tests seem to run slowly, each requiring 5-10 seconds to complete.  Some days, the tests would run downright glacial, requiring 25-30 seconds each.  When I started running the tests against the pre-production and production servers, they started timing out.  I started to get concerned about performance.  If my unit tests were causing the service to time out, what would a production web site consuming the service do?  I had to look into it.

Fortunately, much of the structure that I had built so far lent itself rather well to opportunities for caching.  It was also fortunate that I knew exactly where the problem was, so it should be a relatively simple matter to implement caching there.  I happily plunked away for a couple of hours implementing my idea.  I re-ran my full suite.

No improvement.

I ran it again.  Perhaps the DLLs were being compiled, so the first hits weren’t representative.

No improvement.  I was still seeing the tests require 5-10 seconds each to complete.

Ok, so perhaps I DIDN’T really know where the problem was.

So, the next step was to do what I should have done as step 1: collect some hard data.  I had written a class a couple of years ago to dump out messages to a log file, and record the time it took to get there.  The class was called “MyStopWatch”, and I originally wrote it to wrap the System.Diagnostics.Stopwatch class. However, that class was introduced in .NET 2.0, and the project I was working on was targeting the 1.1 framework, so I had to modify MyStopWatch to simply count clock ticks:

Imports System.IO

Public Class MyStopWatch
    Private _LogFileWriter As StreamWriter
    Private _TimeOfLastCheckPoint As Long
    Private _IsEnabled As Boolean

    Public Sub New(ByVal FunctionBeingMeasured As String, ByVal IsEnabled As Boolean)
        Dim LogFileName, LogFilePath As String

        Me._IsEnabled = IsEnabled
        If (Not Me._IsEnabled) Then Return

        LogFileName = FunctionBeingMeasured & “_” & Now.ToShortDateString.Replace(“/”, “”) & “_” & Now.Hour & Now.Minute & Now.Second & “.log”
        LogFilePath = Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.Desktop), LogFileName)

        Me._LogFileWriter = New StreamWriter(LogFilePath, False)
        Me._LogFileWriter.AutoFlush = True

        Me._TimeOfLastCheckPoint = DateTime.Now.Ticks
        Me._LogFileWriter.WriteLine(“L = Time since last checkpoint (milliseconds)”)
    End Sub

    Public Sub RecordCheckpoint(ByVal CheckPointDescription As String)
        Dim CurrentTickMark, ElapsedTicks As Long

        If (Not Me._IsEnabled) Then Return

        CurrentTickMark = DateTime.Now.Ticks
        ElapsedTicks = CurrentTickMark – Me._TimeOfLastCheckPoint
        Dim ElapsedSpan As New TimeSpan(ElapsedTicks)

        Me._LogFileWriter.WriteLine(“(L: “ & ElapsedSpan.TotalMilliseconds & “) “ & CheckPointDescription)

        Me._TimeOfLastCheckPoint = CurrentTickMark
    End Sub

    Protected Overrides Sub Finalize()
        If (Not Me._IsEnabled) Then Return

            If (Not IsNothing(Me._LogFileWriter)) Then Me._LogFileWriter.Close()
        Catch ex As Exception
           ‘ Ignore these; it means that the log file was already closed
        End Try
    End Sub
End Class

The constructor sets up the log files to dump out to the desktop so I could find them easily.  Once I included the class in my project, I could use it as follows:

{ some code here }

Dim X As MyStopWatch

X = New MyStopWatch(“MySlowFunction”, True)

{ some code here}

X.RecordCheckpoint(“First loop complete”)

{ some code here }

X.RecordCheckpoint(“Business object instantiated; data loaded”)

{ some code here }

X.RecordCheckpoint(“Web service call complete”)

{ some code here }

X = Nothing

After a few runs, and some tweaking to the placement of the RecordCheckpoint() calls, I was able to narrow down the real problem.  The timing tests showed that the slowness was with the stored procedure call itself.

On a hunch I decided to try varying which fields the database returned with each call.  The stored procedure accepted a delimited list of fields to include, and would build the field list dynamically, so it was relatively easy to change what was being returned.  Through trial and error I found that a small handful of fields that when included in the result set would cause the stored procedure to slow down by one or more orders of magnitude.  Those fields happened to all be Oracle CLOB (character large object) fields.  As long as none of these were included in the result set, the stored procedure ran very quickly (a second or less).  Each CLOB field included would add time, even if I included multiple CLOBs from the same table.

Asking the client to modify their table structure to not use CLOBs for these fields was out of the question.  The best we would be able to do for the production web service would be to urge people to filter the list heavily, which would mean fewer CLOBs for the server to pull together, and quicker overall response times.  That advice, however, wouldn’t work for my test suites, which relied on bringing back most or all of the records in each test.

I pondered the problem for a while and it finally dawned on me: I was only counting records to make sure that “include by X” and “exclude by X” were returning record counts that added up to the total number of records – I wasn’t really interested in the data that was brought back.  So, why couldn’t I modify the calls to only bring back an ID field, and none of the CLOB fields?  I quickly implemented that and reran the suite.  The tests were now running in a second or less each.  I could run through a hundred or so tests that hit the actual web service, and do it in a couple of minutes instead of an hour or more.  Not bad for a morning’s work.

While finding out about the performance hit with the CLOBs was interesting, the real lesson for me was to not assume I knew where the performance issue was.  Always get some hard numbers on the various parts of the code that seems to be performing poorly;  otherwise you’ll waste time optimizing where it isn’t needed.

In the next installment of this series, I’ll be examining the value that the test suite brought to the project.

July 20, 2008 - Posted by | Agile, Visual Studio/.NET

1 Comment

  1. […] a web service I wrote.  The first three posts covered the basic structure of the test suite, a performance issue that I worked around, and the value that the suite brought to the […]

    Pingback by Web Service Testing - Part 4 of 4 « Mark Gilbert’s Blog | August 5, 2008

Sorry, the comment form is closed at this time.

%d bloggers like this: