Delphi Clinic C++Builder Gate Training & Consultancy Delphi Notes Weblog Dr.Bob's Webshop
Dr.Bob's Delphi Notes Dr.Bob's Delphi Clinics Dr.Bob's Delphi Courseware Manuals
 Dr.Bob Examines... #131
See Also: Dr.Bob's Delphi Papers and Columns

Delphi XE and AQtime Standard
AQtime is a third-party tool integrated into the Delphi XE IDE. The free integrated edition is AQtime Standard Edition, which does not include all features, but does offer you a 10% discount if you want to upgrade to the AQtime Pro edition.
Although we can start using AQtime on open projects, which is an ad-hoc approach, we should actually start by creating a new AQtime Project first (as first project of a project group), to enable profiling for the entire project group.Or the first five modules actually (a built-in limitation of AQtime Standard Edition).

The result is a new project group with an AQtime project as well as a AQtimeModule which is opened to show modules as well as areas:

The areas we can select are determined by the current selected profiler.

Profile Project
Once we have a AQtime project, we can either open existing Delphi projects and add them to the project group, or create a new Delphi project and add it to the group. Let’s start with a new example, so right-click on the Project Group and select Add New Project to get the Object Repository again.This time, add any project you want – for the example here I’ll add a normal VCL Forms Application.
For this example, I want to demonstrate the use of the Performance Profiler (the default selected profiler of AQtime).The application will contain a number of routines that perform tasks: I have a routine BigTask, which will take a long time, but will be executed only once.I also have a routine called SmallTask which will take less time, but will be executed more often.Finally, I’ll implement a routine called Work, which first calls BigTask and then several times calls the SmallTask to complete the work.These three routines are placed in their own unit, to make testing easier, so right-click on the Delphi project and do Add New | Unit to add a new unit.I’ve saved the new unit in file Works.pas.

  unit Works;
  interface
  uses
    CodeSiteLogging;

  procedure BigTask;

  procedure SmallTask;

  procedure Work;

  implementation
  uses
    SysUtils;

  procedure BigTask;
  begin
    CodeSite.EnterMethod('BigTask');
    CodeSite.Send('Sleep 1000');
    Sleep(1000);
    CodeSite.ExitMethod('BigTask');
  end;

  procedure SmallTask;
  begin
    CodeSite.EnterMethod('SmallTask');
    CodeSite.Send('Sleep 100');
    Sleep(100);
    CodeSite.ExitMethod('SmallTask');
  end;

  procedure Work;
  var
    i: Integer;
  begin
    CodeSite.EnterMethod('Work');
    BigTask;
    for i:=1 to 42 do SmallTask;
    CodeSite.ExitMethod('Work');
  end;

  end.

Note that if we run the Work procedure, we can view the results in the CodeSite Live Viewer already, but that doesn’t really show us where the biggest performance problem is that we should focus on.
In the CodeSite Live Viewer, we can select the columns to display, and uncheck the Date but change the Time column to “Time Difference", so we can see the time difference between two subsequent log messages, which shows that the BigTask ExitMethod is called 0.999 seconds after the previous log message (which indicated that we’re about to sleep for 1000 ms).

This may be the longest time between two CodeSite log messages, but it may not be the biggest bottle-neck in our application.For that, we need to measure with AQtime.
AQtime can be seen as a debugger tool, like the Delphi integrated debugger.And where we have the “Run" (with Debugging)" as well as “Run without Debugging" options, we now also have the “Run with Profiling" option, which uses the AQtime profiler as debugger.As a consequence, you cannot use the Delphi IDE debugger while profiling (but that wouldn’t make much sense anyway, as the breakpoints in the Delphi debugger would cause the profiling measurements to be incorrect as well).
Where the Delphi Project Manager can hold different projects – including the AQtime project – there can be only one project “active" at a given time.This is the project that we compile and run if we do Ctrl+F9 (for compile) or Shift+F9 (for Build) or just F9 to run the project, or Shift+Ctrl+F9 to run the project without debugging.However, for AQtime, there is also an active project to profile, which is not necessarily the active project from the project group.
In order to make sure we can profile a project, we need to click on the AQtimeModel tab, and then in the left pane (with the list of Modules – currently empty), right-click and select the Add Module option.This will give us a File Open dialog, where we can select an executable.In our case, the profiling project we just implemented (which can be found in the Win32\Debug subdirectory of our current project directory).
Note that you need to ensure that debug information is added to the compiled executable, otherwise you’ll get an error message from AQtime telling you that the debug information was not found:

The Modules list will then also indicate that the ProfileProject.exe has no debug info.Fortunately, this is easy to remedy, by opening the Project Options dialog, going to the Linking page, and setting the Debug information option to True (I’m not sure why this option was set to False in the DEBUG Build Configuration in the first place actually):

Then, we need to recompile the project in order to produce a new executable, this time with full debug information attached.We need to right-click on the executable in the Modules list to refresh the information, however.
After we’ve made sure to include debug information, we can open up the ProfileProject and see all the units that are part of this project.We should find the unit with the code that we want to debug, which is the Works.pas unit (right at the bottom of the list).
We can open up the Works unit, and see the BigTask, SmallTask and Work routines.We can select them all, right-click and select the Add Selected to Area option, which will result in a new action “Add New Area" to be shown – which will show the Add Area dialog where we can specify the name of the new area to add these three routines to.Let’s call the new area “My Work Area".

We can select the level to trace, which can be class (not supported), routine, or line (also not supported).
The result is a new display in the areas, where we can now select a full check of all routines, or only my work area with the three manually added routines.This demonstrates how we can either profile all routines in the project, or only the selected routines (in case you want to profile a specific module only).

In order to actually profile the project, we should now do AQtime | Run With Profiling, which first recompiles the project (even when this is not needed), and then show a dialog to offer us some options:

As active counter, we can only select the Elapsed Time (other options are not supported in the AQtime Standard edition).
We then get a list of all routines that are ignored since they could not be instrumented due to the fact that there were too small (less than 5 bytes) or had to ret instruction for example.As long as these do not include our methods we want to measure, it’s no problem:

Finally, the application itself starts, and we do whatever we need (click on the button to start the Work procedure for example).As soon as we close the application again, the result of the profiling is shown.Note that in order to get accurate results, we should of course disable the CodeSite logging.

The result of the profiling shows that while BigTask is taking 1 second to execute, it is in fact only executed once, so it’s not on the top of the list when we sore based on (total) “Time".The number one bottle-neck is the “SmallTask", which takes 4.23 seconds to execute (since it’s executed 42 times).
We can also sort based on the Time with Children column, in which case the Work routine itself gets on top, right after the Button1Click which started Work.This is of course only useful to see the combined time of the routine with all child calls.In practice, it’s the time in the routine that counts.For Button1Click as well as Work the “Shared Time" is 0, since the time spent in these methods is 0 compared to the time spent by the child routines.
Apart from the Report that we see in the IDE, we can also view other AQtime results using the View | AQtime Profile Windows menu, selecting either the Report, Summary, Explorer or Details (with an option to see even more reports including the Call Graph, Call Tree, Disassembler, Event Viewer, Monitor and PE Reader).
The AQtime Summary Report shows the Worst performance (body only) to be the SmallTask, followed by BigTask.The Explorer view shows a window where we can select the results from different profiling runs and view them in the report:

The Details report can be used to see for a particular routine how it contributes to the time of its parent, and how the child routines contribute to the time of this routine.For example, for the Work routine, the Details are as follows:

Again, it should be clear that SmallTask is the biggest performance bottle-neck at this point.Any optimization here (from a Sleep 100 to a Sleep 90 even) will have a big impact on the total time, since it’s executed 42 times, so 10 ms saved will be 420 ms saved in total, which is almost 10% of the total time.While a reduction of 10ms. in the BigTask will have an almost unnoticeable effect.

References
See the "Getting Started with AQtime 7 Standard for Embarcadero RAD Studio.doc" and "AQtime 7 User Manual.doc" documents in the directory C:\Program Files\Automated QA\AQtime 7\Help to get more information on the other profilers.


This webpage © 2010-2011 by Bob Swart (aka Dr.Bob - www.drbob42.com). All Rights Reserved.