Code Profiling with Non-Breaking Breakpoints by Jim McKeeth

By: Jim McKeeth

Abstract: Sometimes it is nice to know how long a specific piece of code takes to execute. The Borland IDE actually provides a means to accomplish this using non-breaking breakpoints and the event log.

Either there is a point in your program when it is running much slower then you expected, or you are debating which way would be faster to do something.  Either way, you need to profile the performance of some code.  Back in the old days we would add code to our programs to output the start and stop time to a log for specific processes, then we would remove it or comment it out until we needed it again.  Nowadays we use code profilers that time the execution of every line of our code and provide us with detailed reports and graphs.  We could spend weeks examining all all the data available.

Code profilers are nice, but sometimes we don't have one convenient or we really don't want to mess with one to test a couple lines of code.  Maybe inserting all the additional debug information for a profiler to work changes the behavior of our program too much.  Instead of going back to adding all that code to log start and stop times we can instead use non-breaking break points. 

The major advantage of this technique over a traditional code profiler is when you have a fairly complex program running and you want to profile the code now without restarting it and launching the profiler.  You can target this profiling so specifically that it doesn't have the impact on the overall behavior of your program that other profilers do.  In instances were you have a few select routines you want to profile you will find this technique much quicker and easier to deploy. 

This article is written for Delphi 7, but the techniques should work with little or no changes in other versions of Delphi as well as C++ Builder and Kylix.  The attached code is specific for Windows, but I am sure a resourceful Kylix programmer would know which Linux API's to use instead. 

Before I show you how to use non-breaking breakpoints to profile your code I am going to cover some basics about non-breaking breakpoints.  If you are already comfortable with the advanced features of breakpoints then you can skip to the section on Profiling

What are Non-Breaking Breakpoints?

I know you are probably thinking that a non-breaking break point sounds like an oxymoron.  As we will see it really is not.  Cary Jensen offers a great article titled Using Non-Breaking Breakpoints in Delphi that is also available on the Borland Developers Network.  Not to worry if you haven't read that one.  I'll cover everything you need to know here.

The Free On-Line Dictionary of Computing defines a breakpoint as follows:

Breakpoint

A point in a program that, when reached, triggers some special behavior useful to the process of debugging; generally, breakpoints are used to either pause program execution, and/or dump the values of some or all of the program variables. Breakpoints may be part of the program itself; or they may be set by the programmer as part of an interactive session with a debugging tool for scrutinizing the program's execution.

So breakpoints only generally pause program execution.  Maybe a better name would be non-pausing breakpoints.  Regardless of what you call them, we are using breakpoints that still trigger special behavior, but don't actually pause execution.  So how do you obtain one of these funny breakpoints?  It really is very simple.

  1. Create a breakpoint however you usually do (I usually use F5)
  2. Bring up the Source Breakpoint Properties dialog (I usually right click on the breakpoint and choose Breakpoint Properties... from the context menu.)
  3. Click the Advanced >> button.
  4. Uncheck the Break check box.
  5. Click the OK button.
Break Point Properties

The Source Breakpoint Properties dialog before the Advanced >> button is clicked.  This is the default configuration for a break point.  Notice it specifies the filename and the line number that the breakpoint is on.  These are grayed out from this view because we are editing an existing breakpoint's properties.  If we were creating or editing the breakpoint from the Breakpoint List ([CTRL]+[ALT]+[B] for the list, [CTRL]+[A] and [CTRL]+[E] to create a breakpoint) then these fields would not be grayed out and we could specify them. 

Break Point Properties Advanced

The Breakpoint Properties dialog after the Advanced >> button is clicked.  There are a lot of very powerful features available from this dialog.  For now we are just interested in the Break checkbox.  Uncheck it and click OK.

Your breakpoint still looks the same.  It is not disabled (as indicated by a green line and a gray stop symbol), but if you run your program now it won't pause on that line.  If, when you run your program the line changes color to a dark green, then your breakpoint is on a non-executing line.  Choose one of the lines with a blue dot next to it and repeat the process.  It's ok, I'll wait.

If you did it right then your program will run without pausing on that line.  Right now this isn't very useful, but at least you know how to make a non-breaking breakpoint.

Logging with a Breakpoint

Now that we have our non-breaking breakpoint we want it to write to a log to know when the line of code it marks is executed.  Go back to the Breakpoint Properties dialog.  Notice it goes straight to the Advanced view since you have a change in the Actions section.  We are going to make another change.  We are going to add text to the Log message: combobox.  When profiling my code I usually have a logging breakpoint at the start and end of my block of code to be profiled.  I usually have those breakpoint log "Begin" and "End", respectively.

Now if you run your program after making this change you will not notice any obvious difference.  The message was logged to the Event Log, and the Event Log can be accessed from View -> Debug Windows -> Event Log, or by pressing [Ctrl]+[Alt]+[V].  I had three breakpoints set in my program, with the first and last ones logging a message.  This is what my Event Log looks like:

Evnet Log

The lines in red are the ones resulting from a break point.  You will notice 3 "Source Breakpoint" lines and two "Breakpoint Message" lines.  Now while all the other lines are interesting they are a little distracting so lets hide those for now.  Simply [Right-Click] in the log window and choose Properties.  That will display the Debugger Event Log Properties.

Debugger Event Log Properties

In the Messages groupbox you can uncheck any checkbox for a message you do not want to see.  Simply uncheck all of them including the Breakpoint messages checkbox.  The breakpoint messages checkbox is a little deceiving.  It actually removes the "Source Breakpoint" lines, leaving the Breakpoint Message lines.  You can also change the colors and other information if you like.  I find the log is easier to read for profiling if you clear the Display process info with event checkbox as well.  If you use your Event Log for other purposes as well you will want to remember to change these settings back when you are done.

Now when I run my program my Event Log looks like this.  Hopefully yours is similar.

Event Log Concise

I imagine you will agree that this is much more concise. 

TIP: Instead of using Begin and End you may find other messages more useful.  Some suggestions: name of a function being called, line number, object being accessed, name of query being run, loop definition, etc.

Profiling

Now that we know how to enter logs into our event log we can use this feature to profile our code performance.  While showing that a block of code is entered and exited is useful, it is not exactly profiling.  What we need is a measurement of time to show how long it takes to execute some code.  This can be accomplished using the Eval Expression feature of the breakpoint.  Go back to the Source Breakpoint Properties dialog.  This time put GetTickCount in the Eval Expression combobox. 

GetTickCount is a Win32 API call that returns a cardinal containing the number of milliseconds since the computer was last booted.  For Delphi programming this function is found in the Windows unit, so make sure it is in your uses clause.  While the number returned is in milliseconds, the resolution isn't actually in milliseconds.  If you have two calls that are just a couple milliseconds apart then they may still return the same number.   This resolution can be found by calling the  GetSystemTimeAdjustment API.  Also, since a cardinal (or DWORD) is used the, the value will loop around to 0 every 49.7 days.  Not that you will probably need to worry about running on a MS Windows system that has been up that long, but it is something to keep in mind.

In my program I added GetTickCount to all three breakpoints, leaving the Begin and End on the first two.  Running my program again generates a much more useful Event Log.

Event Log with GetTickCount

The Salmon or Pink colored lines show the results of the expression evaluation.  Notice there are two Breakpoint Message lines, and three Breakpoint Expression lines.  If we put a message on the second breakpoint, such as "middle" then we would have an even number of each.  Otherwise we have no way to associate the GetTickCount result with a specific place in the code.  If we re-enable the Breakpoint messages to be displayed in the Debugger Event Log Properties dialog then we would have the line number as well.  I personally prefer using meaningful messages (maybe including the line number), but you can use whatever best suits your needs. 

As we can see for this data it took 1.5 seconds to get from the first break point to the second, and about 1 second to get to the third.  Looks like I have some optimizing to do.  If you are curious where I arrived at those values it was simply a matter of subtracting each number from the one after it and dividing by 1000, rounding to the nearest half second. 

When using the Eval Expression feature of the breakpoints the expression it evaluates must be referenced globally and can only be a function that is included in your compiled code.  Since Delphi has an optimizing linker it removed functions that have no chance of being executed by the program.  GetTickCount is one of those functions that always has a chance of getting called and is included if we call it specifically or not, so it is always in there.  If we use another function, one we write, or another library or API call, we need to make sure it is linked in.  Also, when a method call into an object that change a field value those changes may not actually carry over after the evaluation completes.

Advanced Profiling

What if you don't want to do subtraction in your head?  Or maybe you really need 1 millisecond resolution in your profiling.  This involves adding some code to your program, but there is a trick we can use to ensure that the code is actually not compiled in when your program is built without debug information.

Instead of using GetTickCount we can use the high-performance timer routines also provided in the Windows AP.  These routines are not as straight forward to use, so instead of putting in complex Eval Expressions I suggest building some functions to make things easier.  These functions can also subtract the values between calls. 

The QueryPerformanceCounter and QueryPerformanceFrequency API calls access the high-performance timer available on most systems.  I am not aware of a situation when these would not be available.  For more information on these API calls consult the MSDN or the Windows SDK document included with Delphi.  For now just be aware that is uses Int64's instead of Cardinals, and is is accurate beyond 1 millisecond.

In Code Central you will find my library to use these API calls.  It is very simple to use; there are three functions: ElapsedMS, ResetElapsed and UpTimeMS.  Add the unit JimProfiling to your uses clause and you can use these function in your Eval Expressions.

ElapsedMS
Display how many milliseconds have elapsed since the last call to ElapsedMS.
ResetElapsed
Restart the elapsed counter.
UpTimeMS
Display how many milliseconds have elapsed since the program started (see comments).

After running your program you have really useful, and highly accurate, output in your Event Log.

Event Log using the Jim Profiling unit

Notice that the second call to ElapsedMS has a lower value than the first.  This is because it is the time since the first call.  The UpTimeMS call is actually greater then the sum of the two calls to ElapsedMS because it includes the time before the call to ResetElapsed as well as the small amount of time after the second ElapsedMS call.

TIP: If you need a line to put a breakpoint on for a call to ResetElapsed or some other function then just add a line of Sleep(0); While this does have a slight impact on your program it should be very minor. The exception is if you are dealing with multiple threads since it will give another thread a time slice when you call sleep.

All of the code in this unit in enclosed inside {$IFOPT D+} directives so that when you compile your application without debug information it will be left out, you don't need to remember to remove it from your uses clause.  Since the scope of the Eval Expression is global you can actually just put the unit in any one uses clause in your application and still be able to use it in all other units throughout your application.

Final Tips

If you want to keep your profiling setup between programming sessions be sure to use the Autosave Project Desktop option.  This will save the location of all your windows as well as any Breakpoints you may have.  You can enable it from the Tool -> Environment Options screen, on the Preferences tab under the Autosave Options header. 

Environment Options

If you don't want your desktop changes to always be saved you can turn this option on, save the project once, and then turn it off.  That will make a snapshot of things that will not change when future changes are made.  These settings are stored in the [project].dsk file, which is plain text (INI format).  You can edit it directly if you like.  The breakpoints from my project look like this:

[Breakpoints]
Count=4
Breakpoint0='C:DevBorlandDelphi7ProjectsTempUnit1.pas',43,'',0,1,'',0,0,0,'End',1,'ElapsedMS','','' Breakpoint1='C:DevBorlandDelphi7ProjectsTempUnit1.pas',42,'',0,1,'',0,0,0,'Middle',1,'ElapsedMS','','' Breakpoint2='C:DevBorlandDelphi7ProjectsTempUnit1.pas',41,'',0,1,'',0,0,0,'Begin',1,'ResetElapsed','','' Breakpoint3='C:DevBorlandDelphi7ProjectsTempUnit1.pas',44,'',0,1,'',0,0,0,'',1,'UpTimeMS','',''

Remember if you edit this file, and you have the IDE open and the auto save enabled, then it may overwrite your changes.  Also, they are tracked by line number, so if you insert or delete a line above a line with a Breakpoint then the it may be moved onto the wrong line.

TIP: If you specify a condition then the logging will only be carried out when that condition is true. 

The Breakpoint List screen is another valuable resource.  I mentioned it earlier as another way to create Breakpoints.  You can get to the screen using the [CTRL]+[ALT]+[B] keyboard shortcut, or from the View -> Debug Windows -> Breakpoints menu item.

Breakpoint List

Notice the Action column shows the messages and expressions we are logging.  You could have various groups of profiling breakpoints, each in a different group.  Then from the context menu you can enable or disable an entire group of breakpoints.  You can also use the Enable / Disable Group feature of another breakpoint to turn these groups on or off as needed. 

TIP: Editing (Right click or use [CTRL]+[E]) breakpoints from this screen allows to you move them to other lines or files.  This is especially useful if you have complex actions setup and don't want to recreate them.  You can also set multiple breakpoints on a single line (use the Keep Existing Breakpoint option).

Conclusion

This technique for profiling your code using only the standard Delphi IDE and non-breaking break points provides you with highly targeted, 1 ms accurate execution profiling times.  While this doesn't completely replace the need for a code profiling tool in your programmers toolbox, it does provide you with another powerful alternative to create faster programs in less time using the powerful IDE you already own. 

Code Central:
Title: Non-Breaking Breakpoint Profiling Library 1.0
ID: 21280
http://codecentral.borland.com/codecentral/ccWeb.exe/listing?id=21280

About the Author

Jim McKeeth is president of the Boise Software Developers Group ( www.bsdg.org ), a support group for people addicted to software development in Delphi or other languages.  He co-contributed a chapter on consuming .NET XML web services on Linux using Kylix for the book  "Building Web Applications with ADO.NET and XML Web Services".  He is named inventor on six patents, trains and mentors other developers, enjoys writing when he gets the chance, presented at BorCon2003 on Peer-2-Peer software development and is currently working as a Senior Software Developer for www.mw-inc.com.  When he isn't exploring software development with Delphi he enjoys spending time with his family.  You can contact Jim at jim@mckeeth.org.

Copyright © 2004 by Jim McKeeth.
ALL RIGHTS RESERVED.  NO PART OF THIS DOCUMENT CAN BE REPRODUCED OR COPIED IN ANY FORM WITHOUT THE EXPRESS, WRITTEN PERMISSION OF THE AUTHOR.  So ask and I will probably let you!


Server Response from: ETNASC03