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:
- Download the stopwatchclass.nsf database from the article abstract page.
- Copy the Stopwatch script library from the database to the database you would like to use it in.
- Use the Stopwatch class using its very simple API.
- 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.