This week was Abbott Informatics’ APAC Forum. Speaking with old colleagues, I got inspired to try to revive this site for the 4th time (or is it the 5th?).
I’m currently sitting in a performance enhancement session and thinking to myself: heh, that’s NOT how I would go about it (sorry guys!). Silver bullets? Nah.
The first step to improving performances is to identify what is slow (duh!). What are the bottleneck? Why is it slow?
As a STARLIMS developer, I know that oftentimes, the code written in there is not necessarily the most efficient one. Therefore, why not start by monitoring the performances of, let’s say, SSL scripts, which represent the backbone of the business layer?
I’m thinking: why not have a simple tool that will record, like a stop watch, all block of code execution time, and then provide a report I can read? Heck, .NET has a StopWatch class! Hey! STARLIMS IS .Net!
The more I think about it, the more I consider: let’s do it!
How do we do this?
First, let’s create a class. I like classes. I like object-oriented code. I like the way it looks in SSL afterward, and it makes it way easier to scale through inheritance later on. Question is: what should the class do?
Well, thinking out loud, I think I want it to do is something like this:
- Start the stop watch
- Do something
- Monitor event 1
- Do something
- Monitor event 2
- Do something else
- Monitor event x
- so on and so forth
- Provide a readable report of all the event duration
I also want it to count the number of time an event run, and I want to know the AVERAGE time gone in there as well as the TOTAL time this event took.
Now that I know what I want, let’s write the class that will do it (for the sake of this example, I created it in the Utility global SSL category).
:CLASS perfMonitor;
:DECLARE oStopWatch;
:DECLARE nLastCheck;
:DECLARE aEvents;
:DECLARE WriteToLog;
:PROCEDURE Constructor;
:PARAMETERS bAutoStart;
:DEFAULT bAutoStart, .T.;
Me:WriteToLog := .F.;
Me:nLastCheck := 0;
Me:aEvents := { {"Event", "Total Duration", "# of calls", "Avg Duration"} };
Me:oStopWatch := LimsNetConnect("System", "System.Diagnostics.Stopwatch");
:IF bAutoStart;
Me:Start();
:ENDIF;
Me:WriteToLog := .T.;
:ENDPROC;
:PROCEDURE Monitor;
:PARAMETERS sMessage;
:DEFAULT sMessage, "";
:DECLARE nElapsed, nDuration, i, bNew;
:IF Me:oStopWatch:IsRunning;
Me:oStopWatch:Stop();
nElapsed := Me:oStopWatch:ElapsedMilliseconds;
nDuration := nElapsed - Me:nLastCheck;
:IF Me:WriteToLog;
UsrMes("Performance Monitor ==> " + LimsString(nDuration) + " ms. Message: " + sMessage);
:ENDIF;
Me:nLastCheck := nElapsed;
bNew := .T.;
:FOR i := 1 :TO Len(Me:aEvents);
:IF Me:aEvents[i][1] == sMessage;
Me:aEvents[i][2] += nDuration;
Me:aEvents[i][3] += 1;
Me:aEvents[i][4] := Me:aEvents[i][2] / Me:aEvents[i][3];
bNew := .F.;
:ENDIF;
:NEXT;
:IF bNew;
aAdd(Me:aEvents, { sMessage, nDuration, 1, nDuration });
:ENDIF;
Me:oStopWatch:Start();
:ENDIF;
:ENDPROC;
:PROCEDURE Restart;
Me:Monitor("Internal Restart");
Me:oStopWatch:Restart();
:ENDPROC;
:PROCEDURE Stop;
Me:Monitor("Internal Stop");
Me:oStopWatch:Stop();
:ENDPROC;
:PROCEDURE Start;
Me:Monitor("Internal Start");
Me:oStopWatch:Start();
:ENDPROC;
:PROCEDURE ToString;
:RETURN BuildString2(Me:aEvents, CRLF, " ");
:ENDPROC;
The above gives us an object we can start, restart, and monitor events (messages). At the end, we use typical ToString() and will have our “report”. Example of using this:
:DECLARE oPerformanceMonitor;
oPerformanceMonitor := CreateUdObject("SGS_Utility.perfMonitor");
lWait(1.3); /* fake doing something that takes time;
oPerformanceMonitor:Monitor('Step 1');
lWait(0.8); /* fake doing something that takes time;
oPerformanceMonitor:Monitor('Step 2');
lWait(1.1); /* fake doing something that takes time;
oPerformanceMonitor:Monitor('Step 3');
lWait(1.45); /* call Step 1 again to generate an aggregate;
oPerformanceMonitor:Monitor('Step 1');
:RETURN oPerformanceMonitor:ToString();
If I run the above, the output will look like
Event Total Duration # of calls Avg Duration
Step 1 2025 2 1012.5
Step 2 1015 1 1015
Step 3 1011 1 1011
I have been using this in many places in our system and it did help me to find the best places to optimize our code. Sometimes, the same insert will run 500 times and will total up to 15 seconds; that is worse than one call that runs only once and take 3 seconds (at least for the end user).
I hope this can help you find the bottlenecks of your SSL code!