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.
- Create a breakpoint however you usually do (I usually use
F5)
- Bring up the Source Breakpoint Properties dialog (I
usually right click on the breakpoint and choose Breakpoint
Properties... from the context menu.)
- Click the Advanced >> button.
- Uncheck the Break check box.
- Click the OK button.
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.
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:
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.
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.
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.
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.
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.
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.
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!
