Rediscovering a lost gem – Stopwatch

Got a call from a customer reporting that the news on frontpage on their intranet was appearing very slowly. The news are displayed using an AJAX approach for asynchroneous loading using an agent as the data source for the XML. So far I haven’t been aware of any performance problems but “suddenly” the functionality is performing very poorly. Time to debug.

While pondering how to troubleshoot the performance problems I remembered the Stopwatch LotusScript class. I have used the class previously in other projects and it works like a charm. The class is originally from a THE VIEW article called “Performance Testing LotusScript Code Using Object-Oriented Design Techniques” by Burke LaShell (January/February 2000).

Using the class is a simple as these steps:

  1. Download the stopwatchclass.nsf database from the article abstract page.
  2. Copy the Stopwatch script library from the database to the database you would like to use it in.
  3. Use the Stopwatch class using its very simple API.
  4. After each run the class will produce a nice looking e-mail report.

Below is an example of using the class. The code should be self-explainatory but notice the use of the Stopwatch class and its Start and Stop methods.

Sub Initialize
   'declarations
   Dim session As New NotesSession
   Dim docContext As NotesDocument
   Dim subsite As String
   Dim fetcher As NewsFetcher
   Dim xml_conv As XmlConverter
   Dim repositories As Vector
   Dim xml As String
   Dim query_string As String

   'create stopwatch
   Dim stopwatch As New Stopwatch

   'error
   On Error Goto catch

   'get document context
   Set docContext = session.DocumentContext

   'get QueryString
   query_string = docContext.QUERY_STRING(0)

   'get the requested sub-site key if any (i.e. sdainfo, scaninfo)
   subsite = Strrightback(query_string, "&subsite=")

   'create a NewsFetcher
   Call stopwatch.Start(|New NewsFetcher|)
   Set fetcher = New NewsFetcher(subsite)
   Call stopwatch.Stop(|New NewsFetcher|)

   'create a XMLConverter
   Call stopwatch.Start(|New XmlConverter|)
   Set xml_conv = New XmlConverter()
   Call stopwatch.Stop(|New XmlConverter|)

   'get the news documents
   Call stopwatch.Start(|fetcher.GetRepositories()|)
   Set repositories = fetcher.GetRepositories()
   Call stopwatch.Stop(|fetcher.GetRepositories()|)

   'convert the documents to XML
   Call stopwatch.Start(|xml_conv.Convert()|)
   xml = xml_conv.Convert(repositories)
   Call stopwatch.Stop(|xml_conv.Convert()|)

   'write the XML back to the browser
   Call stopwatch.Start(|Print XML|)
   Print "Content-type: text/xml"
   Print xml
   Call stopwatch.Stop(|Print XML|)

   'exit
   Goto finally

catch:
   Print Error & ", line: " & Erl
   Resume finally
finally:

   'send
   Call stopwatch.MailAllWatchValues(|jdoe@example.com|, |Agent Debug - "(WEB - NewsFeed)"|)

   'exit
   Exit Sub
End Sub

The above code will produced a report like the one shown below for each run (the report is e-mailed to jdoe@example.com). As you can see the total run time was 8,8 seconds (!!!) with the fetcher.GetRepositories() call taking up all of the time.

seconds     %        calls     secs/call   event
===========================================================================
00008,812   100,0%   0000001   00008,812   Total run time
00008,812   100,0%   0000001   00008,812   fetcher.GetRepositories()
00008,812   100,0%   0000001   00008,812   NotesRepo.GetDocs() - get news docs
00000,000   000,0%   0000001   00000,000   New NewsFetcher
00000,000   000,0%   0000001   00000,000   New XmlConverter
00000,000   000,0%   0000001   00000,000   NotesRepo.GetDocs() - get view
00000,000   000,0%   0000001   00000,000   xml_conv.Convert()
00000,000   000,0%   0000001   00000,000   Print XML

Using this data I was able to diagnose and solve the problem. Below is performance data from the agent after solving the problem (a view index refresh problem) – notice how the runtime is now a mere 0,015 seconds…

seconds     %        calls     secs/call   event
===========================================================================
00000,015   100,0%   0000001   00000,015   Total run time
00000,015   100,0%   0000001   00000,015   xml_conv.Convert()
00000,000   000,0%   0000001   00000,000   New NewsFetcher
00000,000   000,0%   0000001   00000,000   New XmlConverter
00000,000   000,0%   0000001   00000,000   fetcher.GetRepo()
00000,000   000,0%   0000001   00000,000   NotesRepo.GetDocs() - get view
00000,000   000,0%   0000001   00000,000   NotesRepo.GetDocs() - get first document
00000,000   000,0%   0000001   00000,000   NotesRepo.GetDocs() - loop documents
00000,000   000,0%   0000001   00000,000   Print XML

There are two caveats to using the Stopwatch class:

  • The agent has to allow restricted operations since the script library uses a function from kernel32.dll.
  • Since the class uses kernel32.dll the script library only works on Windows.