Profiling with TStopwatch

Delphi includes a helpful unit called System.Diagnostics, which implements a TStopwatch record. It allows us to measure time events with a better precision than 1 millisecond and has a pretty exhaustive public interface, as shown in the code fragment below:

type
  TStopwatch = record
  public
    class function Create: TStopwatch; static;
    class function GetTimeStamp: Int64; static;
    procedure Reset;
    procedure Start;
    class function StartNew: TStopwatch; static;
    procedure Stop;
    property Elapsed: TTimeSpan read GetElapsed;
    property ElapsedMilliseconds: Int64 read GetElapsedMilliseconds;
    property ElapsedTicks: Int64 read GetElapsedTicks;
    class property Frequency: Int64 read FFrequency;
    class property IsHighResolution: Boolean read FIsHighResolution;
    property IsRunning: Boolean read FRunning;
  end;

To use a stopwatch, you first have to create it. You can call TStopwatch.Create to create a new stopped stopwatch or TStopwatch.StartNew to create a new started stopwatch. As TStopwatch is implemented as a record, there's no need to destroy a stopwatch object.

When a stopwatch is started, it is measuring time. To start a stopwatch, call the Start method and to stop it, call the Stop method. The IsRunning property will tell you if the stopwatch is currently started. Call the Reset method to reset the stopwatch to zero.

The TStopwatch contains a few functions that return the currently measured time. The most precise of them is ElapsedTicks, but as there is no built-in (public) function to convert this into standard time units, this function is hard to use. My recommendation is to just use the ElapsedMilliseconds property which will give you elapsed (measured) time in milliseconds.

For a simple demo, this code will return 1,000 or a bit more:

function Measure1sec: int64;
var
  sw: TStopwatch;
begin
  sw := TStopwatch.StartNew;
  Sleep(1000);
  Result := sw.ElapsedMilliseconds;
end;

Let's now use this function to measure the SlowMethod method.

First, you have to add the System.Diagnostics unit to the uses list:

uses
  System.SysUtils,
  System.Generics.Collections,
  System.Classes,
  System.Diagnostics;

Next, you have to create this stopwatch inside SlowMethod, stop it at the end, and write out the elapsed time:

function SlowMethod(highBound: Integer): TArray<Integer>;
var
 // existing variables
 sw: TStopwatch;
begin
  sw := TStopwatch.StartNew;

  // existing code

  sw.Stop;
  Writeln('SlowMethod: ', sw.ElapsedMilliseconds, ' ms');
end;

We can use this code to verify the theory that SlowCode has time complexity O(n2). To do this, we have to measure the execution times for different counts of processed numbers (different values entered at the How many numbers prompt).

I did some testing for selected values from 10,000 to 1,000,000 and got the following numbers:

If you repeat the tests, you will of course measure different values, but the growth rate should be the same.

For a quick confirmation, I have plotted a Scatter Chart of this data in Excel and the result surely looks like a square function. To be more sure, I have added a power trendline which created a function in the form of nc, where c was a constant that Excel has calculated from the data.

In the case of my specific measurements, this fitting function was y = 10-6 * x1.7751, which is not that far from x2:

Next, I repeated this curve fitting process on the wonderful Wolfram Alpha (www.wolframalpha.com) where you can find a Regression Calculator Widget, a tool designed specifically for this task. I entered measurements into the widget and it calculated a fitting function of 4.76372×10^-8 * x^2 + 0.0064733 * x - 143.666. If we ignore all unimportant factors and constants, the only part left is x^2.  Another confirmation for our analysis!

Now we know how the program behaves in global terms, but we still have no idea of which part of the code is the slowest. To find that out, we also have to measure execution times of the ElementInDataDivides and Filter methods.

These two methods are called multiple times during the execution of the program so we can't just create and destroy a stopwatch each time Filter (for example) is executed. We have to create a global stopwatch, which is a bit inconvenient in this program because we have to introduce a global variable.

If you check the SlowCode_Stopwatch program, you'll see that it actually creates three global stopwatches, one for each of the functions that we want to measure:

var
  Timing_ElementInData: TStopwatch;
  Timing_Filter: TStopwatch;
  Timing_SlowMethod: TStopwatch;

All three stopwatches are created (but not started!) when the program starts:

Timing_ElementInData := TStopwatch.Create;
Timing_Filter := TStopwatch.Create;
Timing_SlowMethod := TStopwatch.Create;

When the program ends, the code logs elapsed time for all three stopwatches:

Writeln('Total time spent in SlowMethod: ', 
  Timing_SlowMethod.ElapsedMilliseconds, ' ms');
Writeln('Total time spent in ElementInDataDivides: ', 
  Timing_ElementInData.ElapsedMilliseconds, ' ms');
Writeln('Total time spent in Filter: ', 
  Timing_Filter.ElapsedMilliseconds, ' ms');

In each of the three methods, we only have to Start the stopwatch at the beginning and Stop it at the end:

function Filter(list: TList<Integer>): TArray<Integer>;
  // existing variables
begin
 Timing_Filter.Start;

 // existing code

 Timing_Filter.Stop;
end;

The only tricky part is the ElementInDataDivides function which calls Exit as soon as one element divides the value parameter. The simplest way to fix that is to wrap the existing code in a try .. finally handler and to stop the stopwatch in the finally part:

function ElementInDataDivides(data: TList<Integer>; value: Integer): boolean;
var
  i: Integer;
begin
  Timing_ElementInData.Start;
  try
    Result := True;
    for i in data do
      if (value <> i) and ((value mod i) = 0) then
        Exit;
    Result := False;
  finally
    Timing_ElementInData.Stop;
  end;
end;

If you run the program and play with it for a while and then exit, you'll get a performance report. In my case, I got the following result:

We now know that most of the time is spent in ElementInDataDivides, but we don't know how many calls to it were made directly from SlowMethod and how many from the Filter method. To find that out, we have to add two new global variables and some more code:

var
  Generate_ElementInData_ms: int64;
  Filter_ElementInData_ms: int64;

function SlowMethod(highBound: Integer): TArray<Integer>;
var
  i: Integer;
  temp: TList<Integer>;
begin
  Timing_SlowMethod.Start;
  temp := TList<Integer>.Create;
  try

    Timing_ElementInData.Reset;
    for i := 2 to highBound do
      if not ElementInDataDivides(temp, i) then
        temp.Add(i);
    Generate_ElementInData_ms := Generate_ElementInData_ms +
      Timing_ElementInData.ElapsedMilliseconds;

    Timing_ElementInData.Reset;
    Result := Filter(temp);
    Filter_ElementInData_ms := Filter_ElementInData_ms +
      Timing_ElementInData.ElapsedMilliseconds;

  finally
    FreeAndNil(temp);
  end;
  Timing_SlowMethod.Stop;
end;

The code (which can be found in the SlowCode_Stopwatch2 program) now resets the Timing_ElementInData stopwatch before the data generation phase and adds the value of the stopwatch to Generate_ElementInData_ms afterwards. Then it resets the stopwatch again for the Filter phase and adds the value of the stopwatch to Filter_ElementInData_ms afterwards.

At the end that will give us  the cumulative execution time for ElementInDataDivides called directly from SlowMethod in Generate_ElementInData_ms and the cumulative execution time for ElementInDataDivides called from Filter in Filter_ElementInData_ms.

A test run with an upper bound of 100,000 produced the following output:

Now we can be really sure that almost all the time is spent in ElementInDataDivides. We also know that approximately 75% of the time it is called directly from SlowMethod and 25% of the time from the Filter method.

We are now ready to optimize the program. We can either improve the implementation to make it faster, or replace it with a faster algorithm, or both.

But first, let's see what profilers can tell us about our program.