Simple Profiling

[cairnswm]

I've designed a very simple profiling framework. Currently its in the shape of a Delphi Unit.

The Profiling.pas unit should be included in your project. At the start of each functionaility being profiled just execute a [pascal]ProfileOn(<ID>)[/pascal] statement, where ID is a unique identifier for the section.

Currently the profiling unit can only monitor 10 unique sections but the MaxProfiles constant can be change to monitor as many as you want.

At the end of your program (I do it on FormDestroy) just do a [pascal]SaveProfile('Profiles.txt');[/pascal] statement to store the profile information to a file.

Open the file created to see the impact of each section in the program.
The file will look something like this:

PROFILE
1: 0 called 88 average  0.00000000000000E+0000 ms
2: 0 called 88 average  0.00000000000000E+0000 ms
3: 1250 called 88 average  1.42000000000000E+0001 ms
4: 16 called 87 average  1.80000000000000E-0001 ms
5: 0 called 88 average  0.00000000000000E+0000 ms
6: 1517 called 88 average  1.72400000000000E+0001 ms
7: 186 called 88 average  2.11000000000000E+0000 ms

From this output we can see that Profile Section 1 was called 88 times and used a total of 0ms (therefore an average of 0), while section 6 was called 88 times and used a total of 1517 milliseconds - an average of 17ms each time it is called. (BTW this was the canvas function and Profile section 3 was the DXDraw.Flip statement).

Using this output file it is possible to identify sections of the code that are significantly slower than others.

The complete source code for the profiling unit is included below. I have tried to optimise as much as possible. e.g. Using Records as they do the memory allocation on program start and not during the program run time etc.


[pascal]
unit Profiling;

interface

Uses
Math, Windows;

Const
MaxProfiles = 10;

Type
TProfile = Record
Time : Integer;
Count : Integer;
End;

Var
Profiles : Array[0..MaxProfiles] of TProfile;
CurrentProfile : Integer;
LastTime : Integer;

Procedure ProfileOff;
Procedure ProfileOn(ProfileID : Integer);
Procedure SaveProfile(FileName : String);
Procedure ClearProfile;

implementation

// Stop all profiling activities.
Procedure ProfileOff;
Var
T : Integer;
Begin
If CurrentProfile <> 0 then
Begin
T := GetTickCount;
Profiles[CurrentProfile].Time := Profiles[CurrentProfile].Time + T - LastTime;
Inc(Profiles[CurrentProfile].Count);
CurrentProfile := 0;
End;
End;

// Start Profiling a specfic ID
Procedure ProfileOn(ProfileID : Integer);
Var
T : Integer;
Begin
T := GetTickCount;
If CurrentProfile <> 0 then
Begin
Profiles[CurrentProfile].Time := Profiles[CurrentProfile].Time + T - LastTime;
Inc(Profiles[CurrentProfile].Count);
End;
CurrentProfile := ProfileID;
LastTime := T;
End;

// Save Profiling information to a Text File
Procedure SaveProfile(FileName : String);
Var
T : TextFile;
I : Integer;
Begin
AssignFile(T,FileName);
Rewrite(T);
WriteLn(T,'PROFILE');
For I := 0 to MaxProfiles do
Begin
If Profiles[I].Count > 0 then
WriteLn(T,I,': ',Profiles[I].Time,' called ',Profiles[I].Count,' average ',RoundTo(Profiles[I].Time / Profiles[I].Count,-2),' ms');
End;
CloseFile(T);
End;

// Clear all current profiling records.
Procedure ClearProfile;
Var
I : Integer;
Begin
For I := 0 to MaxProfiles do
Begin
Profiles[I].Count := 0;
Profiles[I].Time := 0;
End;
CurrentProfile := 0;
LastTime := GetTickCount;
End;

Initialization
// Start by ensuring that no profiles are being done.
CurrentProfile := 0;

end.
[/pascal]

Here is the example that I used to profile. Its the gameloop procedure from a game to be:

[pascal]procedure TForm1.GameLoop(Sender: TObject; var Done: Boolean);
Var
I : Integer;
Begin
Done := False;

{ Game Stuff Goes here... }

DXDraw1.Surface.Fill(clBlack);

ProfileOn(7);
Map.Draw;

ProfileOn(1);

ProfileOn(2);
DXImageList1.Items[5].Draw(DXDraw1.Surface, 10, 10,0);
DXImageList1.Items[4].Draw(DXDraw1.Surface, 40, 30,0);
DXImageList1.Items[6].Draw(DXDraw1.Surface, 40, 90,0);

// Release the Canvas!
ProfileOn(6);
For I := 0 to 10 do
Begin
DXDraw1.Surface.Canvas.MoveTo(900+I, 50+(ABS(I-5)));
DXDraw1.Surface.Canvas.Pen.Color := $00AAFF-(ABS(I-4)*$001515);
DXDraw1.Surface.Canvas.LineTo(900+I,700-(ABS(I-5)));
End;
ProfileOn(5);
DXDraw1.Surface.Canvas.Release;

// Flip the Back-Buffer to the Screen
ProfileOn(3);
DXDraw1.Flip;

ProfileOn(4);
End;[/pascal]

To-Do
ProfilePause - Just delay while somethign else executes.
Neaten the output.
Use a better method than GetTickCount to calculate delays as GetTickCount seems to work in increments of 10ms at a time therefore does not give a really acurate view (But probably good enough anyway).
[/code]

[Alimonster]

Try using timeGetTime for more accurate results than GetTickCount. Use it like this:

initialisation (done once at program start-up):

[pascal]var
TimeCaps: TTimeCaps;

FillChar(TimeCaps, SizeOf(TimeCaps), 0);
timeGetDevCaps(@TimeCaps, SizeOf(TimeCaps));
timeBeginPeriod(TimeCaps.wPeriodMin);[/pascal]

at the end (done once at program finish):
[pascal]timeEndPeriod(TimeCaps.wPeriodMin);[/pascal]

Then you can use timeGetTime in exactly the same way as GetTickCount (literally just replacing the two). Remember to add MMSystem to your uses clause. Alternatively, you can use QueryPerformanceFrequency/QueryPerformanceCounter instead.

As an aside, should you not be using unsigned values (Cardinal or Longword instead of Integer) when dealing with GetTickCount? I seem to recall that it gives back a dword. This change may be handy if you get signed/unsigned warnings.

Anyway, it looks quite handy (except for the fact that I've done sod all programming recently so I won't be using it soon ).

[cairnswm]

I made the changes to use timeGetTime and the results were similar so those profiled sections were obviously very fast.

I was very surprised to see how slow the Flip command was!

[cairnswm]

Correction on last post....

After doing the changes (correctly this time) I have got much better looking results:

PROFILE
1: 2 called 172 average 0.01 ms
2: 3 called 172 average 0.02 ms
3: 2258 called 172 average 13.13 ms
4: 7 called 171 average 0.04 ms
5: 5 called 172 average 0.03 ms
6: 3269 called 172 average 19.01 ms
7: 182 called 172 average 1.06 ms

I also added the formatting......

BTW: Profile 7 is drawing 200 isometric tiles, and about 20 objects on the map.

[tux]

will this work for non delphix games? it could be of interest for me

[Alimonster]

will this work for non delphix games? it could be of interest for me

It should do -- from what I can see, the functions are in a self-contained unit with only two dependencies (Math and Windows, both standard units). GetTickCount/timeGetTime/QueryPerformance* are standard Windows timing functions so they shouldn't be a problem unless you're using Kylix.

The simplest method to find out is to try it yourself and see what happens, of course.

[tux]

interesting

it works well but i wont need it yet until my games a bit more then a gfx test

[cairnswm]

To get best benifit from profiling start doing it now. As you test various GFx routines test them for performance. If while developing the Object drawing routines you optimize it properly you dont need to profile it again later.

My plan is to use it right through my project life cycle to ensure that I get the best possible performance.

[cairnswm]

I tried using this code on my new RTS game and found that the following statement:

[pascal] S2DLDraw.WindowCaption('FPS: '+IntToStr(S2DLDraw.FPS));[/pascal]

takes on average 12ms per call. Its the longest of anything in my code....

I have also started calling this unit S2DLProfiler

[Sly]

This goes to show that there are some gems buried in these forums.

It would be interesting to see the tests performed using RDTSC. This will count the time taken in CPU cycles.

[pascal]function RDTSC: Int64; assembler;
asm
RDTSC
end;[/pascal]