Archive

Posts Tagged ‘Profiler’

SamplingProfiler v1.7.3 bug fix

May 22nd, 2009

SamplingProfiler v1.7.3 has now been released and should be used in place of 1.7.2 which was pulled.

1.7.2 had a nasty bug in the timings statistics (promptly spotted by Robert Houdart) which should be fixed in 1.7.3, there are no other changes and additions in this version.

News , ,

SamplingProfiler v1.7.2

May 20th, 2009
Comments Off

SamplingProfiler v1.7.2 has now been released.

This version includes the following changes:

  • added an option to display line numbers in the source preview
  • extended the process CPU affinity options to allow individually selecting up to 16 cores

The UI has been slightly rearrange to accomodate the CPU affinity options (I guess I’ll need to find something prettier for those upcoming 256 core CPUs…). There may be other indirect minor changes.

News , , ,

Code Optimization: Go For the Jugular

May 6th, 2009

Code optimization can sometimes be experienced as a lengthy process, with disruptive effects on code readability and maintainability. For effective optimization, it is crucial to focus efforts on areas where minimal work and minimal changes will have to most impact, ie. go for the jugular


The Prey

I will illustrate this using SamplingProfiler in a small example, taken from a small library that deals with short vectors of varying length (but usually less than 10 dimensions), which I simplified, isolated & anonymized for the purpose of this article.

uses TypInfo;

type
   TDoWhat = (dwInc, dwDec);

procedure DoSomething1(var data : array of Integer; what : TDoWhat);
var
   i : Integer;
begin
   for i:=Low(data) to High(data) do
   begin
      case what of
         dwInc : Inc(data[i]);
         dwDec : Dec(data[i]);
      else
         raise Exception.Create('Unsupported: '+GetEnumName(TypeInfo(TDoWhat), Integer(what)));
      end;
   end;
end;


Get Meat into Belly

Before starting any kind of optimization, one has to define goals and limits, ie. figure out what “good enough” will be rather consider  “good enough” to be the state of the code one has grown tired of optimizing it!

The sample code above is quite straightforward and simple. It would of course be possible to blow this code to huge proportions for optimization’s sake. If you are after getting every last drop of CPU-cycle juice, and allow yourself to use every trick in the book, a fully optimized version could represent several thousandths of lines of code (I’m not exaggerating). If it’s your core business, it might be okay, but if it’s just a utility library, the increased maintainability issues could never be justified.

But since this article is intended more as an illustration than a discussion on the methodology, I’ll get straight to the buffalo (beef). For further reading on that subject, you can start from Big O Notation, Benchmarking and Software metrics articles in wikipedia, there are also whole books on the subject.


Stalking the Prey

Looking at the above code, the first obvious optimization that developers suggest seems to be taking the conditional out of the loop, resulting in several case-specific loops. On small vectors, this nets about a 30% speedup. For further speedups, the suggestions are typically to go for loop unrolling, asm, and other heavy-handed solutions that come with a significant development time and code complexity increase.

Of course, readers of this website will know better than to jump straight into the code and apply optimization recipes: they would run the code through a profiler first. And since we’re dealing with a single procedure, an instrumenting profiler would be of little help, so they would run Sampling Profiler instead, and would get to see something like this:

Going For The Jugular - Initial Profiling Results

In this run, only the dwInc case was stressed (line 37), and obviously the procedure spends less than 30% of its time doing what it was asked of, and most of its time (33%) on the “end“, ie. cleaning up, plus 8% setting up in “begin“. That’s 40%+ doing nothing but stack and setup/cleanup work!
The conditional in the loop that could have looked like the most worrying bit is eating a bit less than 20% of the time.

What is the source of all that begin/end work? Place a breakpoint on begin, run and hit Ctrl+Alt+C when your breakpoint is reached, go have a look at the CPU view, and you’ll see this:

Going For The Jugular - CPU view near "begin"

This is a fairly significant stack setup for such a small procedure, and those instructions with “fs:” at the bottom are the setting up of an (implicit) exception frame. An exception frame for what? if you haven’t guessed already, navigate your CPU view near the “end” line.

Going For The Jugular - CPU view near "end"

No wonder “end” was a bottleneck! The call to UStrArrayClr indicates that the exception frame is here to cleanup several strings… these strings are those of the raise Exception, one is the string returned by GetEnumName, the other is the result of the concatenation passed to Exception.Create.


Isolate and Kill

How to get rid of that exception frame? One typical way is to use “Exception.CreateFmt”, and pass only constant strings to it, but that is not possible here with the call to GetEnumName, which returns a string. The other way is to isolate the exception to its own (nested) procedure:

procedure RaiseUnsupported(what : TDoWhat);
begin
   raise Exception.Create('Unsupported: '+GetEnumName(TypeInfo(TDoWhat), Integer(what)));
end;

and call RaiseUnsupported in the “case else“. Doing so will move the exception frame to the new procedure, where it’s irrelevant in terms of performance.
This simple change nets us a 33% speedup, ie. we reclaimed most of the lost time in begin/end! We also gained a bit from the UStrArrayClr, which did essentially nothing since those strings it was used to clear weren’t defined (as long as we did not hit the exception).

Note that if you use a nested procedure for RaiseUnsupported, you can be tempted not to pass it the “what” parameter, but use directly the “what” from its parent procedure. However by doing so, you’ll have the compiler use a special stack setup (so that the nested procedure can access the parent procedure’s variables). This setup will be faster than the exception frame it replaces, but with it, begin/end would still be taking about 18% of the CPU time spent in the procedure.


Repeat Until Belly.Full;

Those first 33% were easily gained. Let’s go for another round of SamplingProfiler:

Going For The Jugular - Further Profiling Results

Things are more satisfying: the line performing the actual work is now taking up most of the CPU time. Second comes the case of line. For further speed improvements, we now need to move the conditional out of the loop:

procedure DoSomething3(var data : array of Integer; what : TDoWhat);

   procedure RaiseUnsupported(what : TDoWhat);
   begin
      raise Exception.Create('Unsupported: '+GetEnumName(TypeInfo(TDoWhat), Integer(what)));
   end;

var
   i : Integer;
begin
   case what of
      dwInc :
         for i:=Low(data) to High(data) do
            Inc(data[i]);
      dwDec :
         for i:=Low(data) to High(data) do
            Dec(data[i]);
   else
      RaiseUnsupported(what);
   end;
end;

We have increased the line count noticeably, but most of those extra lines are still cosmetic. What further makes it a reasonable trade-off is that the execution time has been reduced by 66% from the initial version, it now executes 3 times faster!

Are there any more easy gains to be had? Let’s run the last version through SamplingProfiler:

Going For The Jugular - Final Profiling Results

More than 92% of the execution time now goes to the loop and actual work. We got only a wee bit left for stack setup (line 96) and the case of (line 97). At this point, the above makes it clear that if you want to go faster you’ll have to increase the line count and code complexity significantly as you’ll need to replace the two-liner loops with something else, which is bound to be heavier (unrolling, SIMD, etc.)


Rest Under A Tree

Some quick final notes to conclude.

When moving an exception to a procedure, there are two things to keep in mind:

  • the exception will be triggered at another place in the code, to know where it was actually triggered, you’ll have to look up one step in your exception log stack trace… You do have an exception log stack trace in place, don’t you?
  • the compiler won’t “know” about the exception in the called procedure, so it will assume execution continues after your RaiseUnsupported, so you may want to place an Exit after it (which will never be reached), to avoid warnings and allow the occasional register optimization by the compiler.

In the final version, we gained more than the previous profiling run hinted at: the new code allowed the compiler to make better use of the registers. Ofttimes, getting the fat out of the way is all you need to see improvements.

If you check the CPU view, you’ll see everything is quite efficient now, but even then, using all the remaining tricks in the book could probably net noteworthy gains, just at a significant complexity increase. I didn’t try, but I would guess a 2x or 3x speed up should be about right.

If you were to need to go that route, SamplingProfiler could still help you there: on ASM code, you get profiling data down to the ASM instruction… but that’s food for another article.

Tips , , , , , ,

ZJDBGPack re-release

May 4th, 2009
Comments Off

ZJDBGPack is again available, but as an independent download (it used to be bundled with SamplingProfiler).

This is a command-line utility intended for use in a build process or from the Delphi tools menu, whose purpose is to integrate debug information into an executable. The debug information format  is a compressed version of JCL‘s JDBG.

As of know, SamplingProfiler is the only published utility that understands this format, so you can use it either to reduce the size of the executables you deploy for profiling purposes, or if you do not want to deploy directly-readable debug information files.

News , , , , , , ,

SamplingProfiler v1.7.1 bugfix release

April 16th, 2009

SamplingProfiler v1.7.1 is now available, it fixes the crash in the paths dialog reported by Kazan in the forums.

Incidentally this was due to a very old Delphi 5 bit of code that somehow survived Delphi 2009 at the compilation level, but bombed at runtime… I dropped the code and made use of the already existing D2009 version, hence the smaller executable.

For further details on this version, see the v1.7.0 post.

News , , ,

SamplingProfiler 1.7.0 still hot from the compiler

April 15th, 2009

SamplingProfiler v1.7.0 is now available, you can get the zip and release details from its changelog page.

As announced last week, the changes are a fix for a bug that could drastically affect the execution speed of the profiled application when relying on MAP files for debug information, if you were hit by this bug, things should be like night and day with this version (and hopefully I didn’t break anything else in the process…).

The other main addition is that of the real-time monitor, which with default parameters and when activated locally should be reachable at http://localhost:880/ (see the help for other details). The monitor is still at an early stage, and only provides real-time information, as time allows, it may grow to offer more profiling and debug features.SamplingProfiler RealTime MonitorThe current monitor page is a rather basic html page that is fully refreshed periodically, which isn’t very pretty at the moment… an XML version of the real-time information is available at http://localhost:880/sampling.xml, if you come up with a pretty AJAX-based version before I do, feel free to contribute it ;)

News , , , , , , ,

MapFileStats v1.2 out and other news

April 9th, 2009
Comments Off

MapFileStats v1.2 is now available for download, it fixes reported issues and introduces a few minor improvements, such as using the ability to abort search paths scans and remembering MAP File and Search Paths options between executions. You can find the complete list in the changelog.

In other news v1.7 of SamplingProfiler should be ready “soon”. It fixes a bug that could drastically reduce the profiled application’s execution speed (when using MAP file information), and will introduce a “Real Time Monitor”, which allows to see what a profiled application is doing in real-time (unsurprisingly).
The monitor is actually a simple web server embedded into the profiler, so you can monitor an application that is run locally or on another machine. Real-time data will be accessible both as a bare-bones HTML page, or in XML form for the AJAX freaks out there.

News , , , , , ,

How familiar are you with code profiling?

March 30th, 2009
Comments Off

SamplingProfiler was initially released in the Delphi ASM newsgroup, and I’m curious about the audience of this website, so I’ve setup a small poll.

How familiar are you with code profiling and/or Delphi code optimization? Can you tell apart instrumenting and sampling profilers merely by their respective heisenbugs, or is that profiler business sounding like a TV series from the last century?

Poll - Familiarity with Profilers

News , , , , , ,

SamplingProfiler 1.6.1 released

March 26th, 2009

Still hot out of the D2009 linker is v1.6.1 of SamplingProfiler.
This is essentially a bugfix release which should solve the Win2k compatibility issue.

Changes since from 1.6.0 to 1.6.1:

  • Supports rough profiling when MAP file does not hold detailed information.
  • Fixed a transient case in which irrelevant samples could be collected.
  • Fixed a dll reference that caused issues on Win2k.
  • Minor UI fixes and changes.

You can grab it from its changelog page.

News , , , ,

begin…end as bottlenecks?

March 25th, 2009

There will come a time when SamplingProfiler may report you that begin or end are your bottlenecks. This may sound a little surprising, but it’s actually quite a common occurrence, and something that instrumenting profilers are not going to point out, so it might be worth a little explanation.

This can be illustrated it with the minimalistic example of an array property getter. Witness the innocuous looking code below:

function TMyList.GetItem(index : Integer) : T;
begin
    if (index < 0) or (index >= Count) then
       Error(index);
    Result := FItems[index];
 end;

Nothing out of the ordinary there, you can find similar looking code in practically every array-based collection in the RTL and many third party libraries. But someday, that GetItem will be bottleneck, and you could be left looking at code profiling results like those:

begin-end-critical-01

Yes, those are the are the begin and end lines taking up more than 70% of the CPU time spent inside GetItem
You knew it! Sampling profilers are unreliable… or are they? Surely the index range checking must be the culprit? or the assignment and the reference counting business? Well, they could be, but in this case they aren’t.

To understand why, let’s have a look in the CPU view. Place a breakpoint on your begin, run up to there and hit Ctr+Alt+C, here is what you could see:

begin-end-critical-02

That’s a whole lot of traffic to the stack: 3 registers saved, 3 copies. Those things aren’t free, they can dwarf what your explicit code does, and in this example, they do. We didn’t even have any local variables, if we did, they would have taken setup and teardown code, and this code would have been “hidden” in begin and end too.

This illustrates a difference of sampling vs instrumenting profilers: the ability to pinpoint an actual bottleneck, even if it is “outside” of your explicit code, so you can find where the actual bottleneck is, and don’t waste time trying to optimize what isn’t critical.

Now what can you do to improve things locally? With generics, an interface type and Delphi 2009 sp2, nothing much, short of going BASM. The bottleneck code is compiler-generated, optimizing the assignment or the range checking would only provide minimal benefits. If you want to go faster, you’ll have to reduce the number of calls to GetItem, ie. open that “Show Callers” pane, have a look there, and solve the issue at the higher-level routines that are involved.

But there are other situations in which you can influence the auto-generated begin/end code, the solutions then typically revolve around distributing the code across smaller local functions or methods, tweaking your variable usage, separating branches, or if all else fails, going BASM… but that is food for future posts!

Tips , , , , , , ,