Page 1 of 2 12 LastLast
Results 1 to 10 of 16

Thread: Simple Profiling

  1. #1
    Legendary Member cairnswm's Avatar
    Join Date
    Nov 2002
    Location
    Randburg, South Africa
    Posts
    1,537

    Simple Profiling

    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:
    Code:
    PROFILE
    1&#58; 0 called 88 average  0.00000000000000E+0000 ms
    2&#58; 0 called 88 average  0.00000000000000E+0000 ms
    3&#58; 1250 called 88 average  1.42000000000000E+0001 ms
    4&#58; 16 called 87 average  1.80000000000000E-0001 ms
    5&#58; 0 called 88 average  0.00000000000000E+0000 ms
    6&#58; 1517 called 88 average  1.72400000000000E+0001 ms
    7&#58; 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]
    William Cairns
    My Games: http://www.cairnsgames.co.za (Currently very inactive)
    MyOnline Games: http://TheGameDeveloper.co.za (Currently very inactive)

  2. #2

    Simple Profiling

    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 ).
    "All paid jobs absorb and degrade the mind."
    <br />-- Aristotle

  3. #3
    Legendary Member cairnswm's Avatar
    Join Date
    Nov 2002
    Location
    Randburg, South Africa
    Posts
    1,537

    Simple Profiling

    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!
    William Cairns
    My Games: http://www.cairnsgames.co.za (Currently very inactive)
    MyOnline Games: http://TheGameDeveloper.co.za (Currently very inactive)

  4. #4
    Legendary Member cairnswm's Avatar
    Join Date
    Nov 2002
    Location
    Randburg, South Africa
    Posts
    1,537

    Simple Profiling

    Correction on last post....

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

    Code:
    PROFILE
    1&#58; 2 called 172 average 0.01 ms
    2&#58; 3 called 172 average 0.02 ms
    3&#58; 2258 called 172 average 13.13 ms
    4&#58; 7 called 171 average 0.04 ms
    5&#58; 5 called 172 average 0.03 ms
    6&#58; 3269 called 172 average 19.01 ms
    7&#58; 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.
    William Cairns
    My Games: http://www.cairnsgames.co.za (Currently very inactive)
    MyOnline Games: http://TheGameDeveloper.co.za (Currently very inactive)

  5. #5

    Simple Profiling

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

  6. #6

    Simple Profiling

    Quote Originally Posted by dUmAsS
    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.
    "All paid jobs absorb and degrade the mind."
    <br />-- Aristotle

  7. #7

    Simple Profiling

    interesting

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

  8. #8
    Legendary Member cairnswm's Avatar
    Join Date
    Nov 2002
    Location
    Randburg, South Africa
    Posts
    1,537

    Simple Profiling

    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.
    William Cairns
    My Games: http://www.cairnsgames.co.za (Currently very inactive)
    MyOnline Games: http://TheGameDeveloper.co.za (Currently very inactive)

  9. #9
    Legendary Member cairnswm's Avatar
    Join Date
    Nov 2002
    Location
    Randburg, South Africa
    Posts
    1,537

    Simple Profiling

    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
    William Cairns
    My Games: http://www.cairnsgames.co.za (Currently very inactive)
    MyOnline Games: http://TheGameDeveloper.co.za (Currently very inactive)

  10. #10

    Simple Profiling

    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]

Page 1 of 2 12 LastLast

Bookmarks

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •