Friday, September 30, 2005

measuring elapsed time for blocks of code (Delphi version)

in a production application quite often is nice to see how long each part of the program takes, i.e. you have an application that performs an operation on a database, then on some files, is nice (and useful) to see something like:

Averages-
db access time: 120ms
file creation : 420ms

if you didn't have that information, and your program one day started working slow (perhaps after a Windows update), you would have no idea where the problem is, but by adding this small feature to your program, you know where you should focus to solve the problem:

db access time: 15000ms
file creation : 420ms

now, to create this information you tipically need to declare some variables:

DBLastTime:Cardinal; //stores the last time it took for this operation
DBTotal :Cardinal; //a sum of all the time it has taken
DBCount :Cardinal; //how many times the operation has been executed
DBAvg :Real; //average time for this operation (unless you wanted to calculate it every time)


I have seen countless times when developers start adding a set of those 4 variables for each operation that they want to measure on the application, and not only that, but also add code to capture the times:

DBLastTime:=GetTickCount;
SomeOperation; //
DBLastTime:=GetTickCount-DBLastTime;
Inc(DBCount);
Inc(DBTotal, DBLastTime);
DBAvg:=DBTotal div DBCount;

FileLastTime:=GetTickCount;
SomeOtherOperation;
FileLastTime:=GetTickCount-FileLastTime
...

this greatly bloats the code and makes it hard to see what the intent was, when all it is, is duplicated code, for such simple task

my approach is as follows:

I create a structure to store all the required values for an operation:

TTimeRecord = record
LastTime:Cardinal;
Total :Cardinal;
Count :Cardinal;
Avg :Real;
end;

I have some constants:

TR_OPEN_DB = 0; //time it takes to connect to the database
TR_MOVE_ZIP = 2; //time it takes to move one zip

TR_MAX_TR_COUNTS = 2;

I declare an array of those structures

TimeRecords : array[0..TR_MAX_SITES-1, 0..TR_MAX_TR_COUNTS-1] of TTimeRecord;

on this example this is a bidimensional array, that I use to have counters on the same operations for both a local and a remote sites

by using those constants you an easily extend your code to add another operation that you want to measure

then I have these 2 functions to do all the "dirty" work:

procedure OpenTime(var timeRecord:TTimeRecord);
begin
timeRecord.lastTime:=GetTickCount;
end;

procedure CloseTime(var timeRecord:TTimeRecord);
begin
timeRecord.lastTime:=GetTickCount-timeRecord.lastTime;
Inc(timeRecord.count);
Inc(timeRecord.total, timeRecord.lastTime);
timeRecord.Avg:=timeRecord.Total div timeRecord.Count;
end;

and the code is simplified to:

OpenTime(TimeRecords[TR_OPEN_DB]);
SomeOperation();
CloseTime(TimeRecords[TR_OPEN_DB]);

OpenTime(TimeRecords[TR_MOVE_ZIP]);
OtherOperation();
CloseTime(TimeRecords[TR_MOVE_ZIP]);

of course you could go further and make this a class or a component, where you specify which controls are updated with the values, etc... but the idea here is to simplify a task

I hope you can use this technique, I'll post the C# version soon, that version should make things even easier, because we can use Static Classes there

No comments: