Profiling with procexp (process explorer)

While running your program in memory intensive workflows, you may often run into a situation where the low memory condition starts to thrash the system.  Such a program usually exhibits a performance problem as it has consumed most of its available virtual memory.  Developers often use their favorite profilers to figure out the performance bottlenecks though profilng such programs is difficult and sometimes impractical.  A lot of good profilers crash when collecting data in such situations.  They need additional memory and resources to collect and consolidate the data which makes the situation even worse.

The good thing about a program that is thrashing a system is that it tends to be in the slow portion of the code for a long period of time.  So when it is bringing down the system, it is mostly executing the code that is responsible for the situation and all we want is to take a peek at the call stack at that very moment.  An obvious choice is to use a debugger or a profiler but given the low memory condition of the system, one may get little help from such tools.  When debugging or profiling become painfully slow, people may get evil ideas of reformatting their system or may start comparing their state of the art machines with ones they had five years back :).  This article describes a light weight profiling trick where one can get the call stack of the unresponsive program without really loading the system further.

Procexp (Process Explorer) is a tool from sysinternals (now Microsoft) and both the download and documentation is available at the link here (Microsoft’s site).

The tool allows one to view the call stack of any running program on the system.  Below are the steps needed to display a call stack of any running program.

  1. Launch procexp.
  2. In the process tree, find your process that is thrashing the system.
  3. Right click on “Properties” and select the “Threads” tab.    

    procexp threads tab    

     

     

     

     

    procexp threads tab
  4. Sort the “Cycles Delta” (on Vista) or “CSwitch Data” (on Windows XP) column in descending order and select the topmost thread.  For some programs there might be just one thread.
  5. For the selected thread click on the stack button to see the current call stack of the program.  Do note that this is a snapshot of the call stack and does not change dynamically.      

    procexp call stack    

     

     

     

     

    procexp call stack

This call stack can provide a good insight of the area of the code that is causing the system to stall.  In the example above functiondothis() is where the thread is spending the most time.  Take more than one sample to reconfirm the findings.  This is a very unintrusive and light weight method of getting a call stack of a running program.  The same trick can be used to debug a hang but there a debugger works equally well. 

Sometimes you don’t need heavy debugging tools and sometimes you just can’t use them.  Procexp is a nifty debugging utility (in addition to being a process explorer) that a developer should download and keep handy for times when nothing else works.

strace Those Crashes On Linux

strace is a great tool on Linux that every developer should be aware of.  It helps trace system APIs – the APIs used, parameters passed and the error value returned.   It does not require root permissions to run.  You can generate a system call trace on a command that is executed or you can trace an already running process.

Sample Usage

strace ./my_crashing_binary

strace ./my_crashing_binary 2>out.txt

strace -p 12345 2>out.txt

The strace Output

A sample output of strace is given below –

<snip>
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fe1000
mprotect(0x645000, 4096, PROT_READ) = 0
mprotect(0x51a000, 4096, PROT_READ) = 0
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7fe16c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
munmap(0xb7fe3000, 115297) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 5), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fff000
write(1, "Hello World\n", 12) = 12
brk(0) = 0x940e000
brk(0x942f000) = 0x942f000
open("/myfile", O_RDONLY) = -1 ENOENT (No such file or directory)
--- SIGSEGV (Segmentation fault) @ 0 (0) ---
+++ killed by SIGSEGV (core dumped) +++

In the above example each line of the strace output has the system call, the parameters passed to it and the return value.

Take note that just before the above program crashed, it tried to access /myfile. With experience it is not hard to guess that the file is being accessed even though it was not found.  Either this file is absolutely necessary for the program to run or the required error checks are missing that could have averted the crash.

When Is strace Useful?

strace is very useful while debugging crashes.  Some scenarios where strace can be helpful are –

  1. Debugging why an installation crashes on a machine.
  2. Detecting file contention issues such as a file name clash while creating temporary files.
  3. Debugging random crashes that are most probably due to the program running out of memory or due to it requesting an arbitrarily large chunk of memory.
  4. Finding out how the program interacts with the file system.
  5. Debugging crashes reproducibly only on one machine.
  6. Debugging crashes in unfamilar code or in cases when sources are unavailable.

More Information

This article is meant as a pointer to the strace utility but it is not a substitute for the man page.  Go to the man page to explore all options strace provides.

man strace

strace is not a substitute for a debugger but a lightweight tool which can be used to generate logs, diagnose common problems and study the usage of system calls in a program.  Like any other program in a programmer’s toolset, it can save a lot of debugging time if used at the right time.

 

 

Temporary Breakpoint – Now You See It, Now You Don’t

Have you faced the problem of breakpoint clutter where breakpoints keep piling up only to hinder the debugging session?  It is then that one realizes that there are some breakpoints that can be deleted and others disabled.

A useful feature in a debugger is a temporary breakpoint that automagically gets deleted when hit thereby reducing the clutter of unnecessary breakpoints.  These breakpoints are useful when you wish to stop at a code location only once and do not require the execution to stop at that location ever again.

For example, say you are trying to determine whether a particular test scenario invokes a specific line of code or not, in that case a temporary breakpoint can be used as the breakpoint is not useful once it has been hit alteast once.

Below are steps on how to set temporary breakpoints in various debuggers.

gdb

Use the tb command to set a temporary breakpoint in gdb.  It is similar to the break command but the breakpoint will automatically be deleted when hit.

(gdb)help tb
Set a temporary breakpoint.
Like “break” except the breakpoint is only temporary,
so it will be deleted when hit.  Equivalent to “break” followed
by using “enable delete” on the breakpoint number.

Windbg

In Windbg, breakpoints set in the Command window using the bl /1 command can be used to create temporary breakpoints.  The /1 tells Windbg that the breakpoint should be deleted when hit.

In Windbg temporary breakpoints are also known as “one shot breakpoints”.

Visual Studio

I found it a bit painful to create temporary breakpoints in Visual Studio.  The only way I could create one was by setting a breakpoint and then setting the hit count for the breakpoint to be equal to 1.   The  article here explains how to set a hit count in Visual Studio.

The amount of work involved to do this sometimes doesn’t make temporary breakpoints worthwhile to set.  Moreover the breakpoint lingers on and doesn’t actually get deleted when hit.

GDB – Debugging In Assembly

If you haven’t debugged in assembly yet, you haven’t debugged enough 🙂  Debugging assembly in gdb can be tricky at times.

A normal debugging session involving assembly language consists of the following steps –

  1. Launch the program in gdb and set the required breakpoint(s).
  2. When the breakpoint is hit, use the disassemble command to view the assembly language of the current frame.
  3. Use the frame command and figure out the program counter and thus your location in the assembly that gdb produced in the last step.
  4. Use the si and ni commands to step in and step over the instructions in assembly language.

The problem is that this may require a bit of scrolling to do if the disassembled function is very long.  The display command can be used to solve this problem.

The display command in gdb allows a user to configure the variables that should show up each time the program is suspended.

(gdb) help display
Print value of expression EXP each time the program stops.
/FMT may be used before EXP as in the “print” command.
/FMT “i” or “s” or including a size-letter is allowed,
as in the “x” command, and then EXP is used to get the address to examine
and examining is done as in the “x” command.

With no argument, display all currently requested auto-display expressions.
Use “undisplay” to cancel display requests previously made.

One can use the display command to view the next instruction that is about to be executed.  The pointer to the instruction yet to be executed is stored in the computer’s program counter (also known as the instruction pointer).   The following command will show the next 3 instructions that are pointed to by the program counter.

display /3i $pc

The /3i above causes three instructions to be printed and $pc references the program counter register.  A sample output is shown below.

1: x/3i $pc

0x401175 <main+37>:     call   0x4103f0 <__main>
0x40117a <main+42>:     lea    0xffffffe8(%ebp),%eax
0x40117d <main+45>:     mov    %eax,(%esp)
(gdb)

 

Aliases In Visual Studio’s Command Window

One trick I picked up from fellow developers was to open a file real quick in Visual Studio.  The trick was to go to the Command Window and type open <filename>.  This is a great productivity tip as you don’t have to search the file through the Solution Explorer.  And if you miss the command prompt after having worked with debuggers such as gdb, this is a must try feature.  Try this in a huge code base and you will come to appreciate it as well.

I then explored the Command Window in more depth and found out that it has some real nice commands which save you a lot of mouse clicks and time.

The Command Window is available through the shortcut CTRL + A or through the Menu ( View -> Other Windows -> Command Window).

Visual Studio 2005 Command Window
Visual Studio 2005 Command Window

Instead of the open command you could also have used the File.OpenFile command (analogous to Menu->File->Open File).  However the Command Window is not just an alternate way of accessing the menu.

The Command Window provides the ability to use aliases and to create new ones.  This is what makes it very powerful and useful.  open in the above example is an alias for File.OpenFile.  It is easy to remember and type in.

Visual Studio has a lot of predefined aliases and below are some that I found very useful.

alias     : lists all existing alias or creates a new alias.
cls       : clears the text from the Command Window.
disasm    : switches to disassembly view.
code      : switches to the code view.
bp        : toggle an existing breakpoint.
? <var>   : prints the value of the variable.
?? <var>  : displays the variable in the quickwatch window.
open file : opens the file and supports auto-complete.
nf        : new file.
closeall  : close all open windows.
|         : list processes.
~         : list threads.
r         : list registers.
g         : run program.
q         : stop debugging.

 

New aliases can be set by using the alias command and the auto-complete facilitates this.  They continue to persist even after you have exited Visual Studio.  For example, the following command will create an alias only  that will close all files except for the active one.

alias only File.CloseAllButThis

Many aliases in the Command Window do the task that can also be performed with keyboard shortcuts.  Aliases are not meant to replace keyboard shortcuts or menu items but provides an alternative way of debugging in Visual Studio which is intuitive to those who have worked on command line interfaces.  Some commands such as only  (created above) are more easily used through the Command Window whereas others might be more accessible through keyboard shortcuts.

 

Debugging – Divide And Conquer The Input Data

As a developer, the first step for solving any bug is to reproduce it. This is an important step before the investigation actually begins. Once the issue is reproduced, the developer starts investigating the bug with the knowledge, tools and debugging skills at hand.  The source of the problem is then determined, a fix is proposed and later checked in after completing the unit testing and other required processes followed by the team.   This may sound very simple but there are obstacles at every step unless the bug is very trivial.    This is routine work for any seasoned software developer.

One mistake developers often make is to jumpstart the debugging process sooner than needed.  They fire up their favorite debugger, set the breakpoints and then start debugging when actually they should have first reduced the data set required for reproducing the bug.

The rule of debugging is very simple  –

“Every developer should strive to reproduce the bug by hitting the required set of breakpoints the least number of times. This allows faster and efficient debugging sessions.”

So if you are hitting a breakpoint hundred times more than you should have, then you are either not using the debugger efficiently or you have not worked enough to reduce the data required to reproduce the bug.

The latter problem is more common as sometimes developers put in little effort to reduce the input data and start debugging prematurely.   This leads to longer debugging cycles where a lot of time is wasted on investigating code that is not even relevant to the problem being solved.

For example, if a there is 1MB text file that is processed by your program and crashes it, then one should first try minimizing the text file such that if it is reduced any further, the crash goes away.  The text file obtained in such a manner is the smallest input data set required to reproduce the crash.  Once this goal is achieved, the program will now be processing lesser data and effectively less code will be executed which results in important breakpoints being hit fewer times.

Well how does the developer go about reducing the input data set?  There is no single method but the one that commonly works is to run a binary search on the input data.  For example in the above case, the text file should be split into two.  Two text files of half MB each would be obtained and one should test to see if the crash reproduces with either one of the files.   If you still see the crash, you have halved the data set.  Then the smaller file should be again split into  two and the process should be repeated till a very small text file is obtained that still causes the crash to occur.  Depending on what your program does, you can even reduce the 1 MB text file to a single character file.  Debugging your program with a single character file is much simpler than using the initial 1MB file.

reducing data set
Reducing The Data Set

The Caveat

Sometimes a large data set may have multiple issues.  By reducing it as described above, one may solve a partial problem but other problems may go unnoticed in the reduced set.  Therefore once a bug has been solved on a reduced input data set, it should be tested against the one provided with the original bug.  This ensures that no other issue that should have been fixed got ignored in a bid to made debugging more efficient.

Final Note

Reducing the input data is essential before starting the debugging process and a great productivity aid too.  If possible, this should be a part of the bug reporting process for quality engineers or customers who often log the issue.    Reducing the data may not always be possible but it is certainly worth an attempt.

 

Debugging – Using Breakpoint Hit Count For Fun And Profit.

If you are familiar with hit count breakpoints already, you may want to click here to jump to the advanced tricks shared in this article.

What is the hit count of a breakpoint?

A debugger allows users to set a breakpoint at a specific line in code.  When the execution reaches that line, the breakpoint is said to have been *hit* and the execution of program being debugged is suspended.

Internally the debugger also keeps a count of the number of times the breakpoint has been hit.  This is called the hit count of a breakpoint.  Debuggers allow users to set conditions based on the hit count of the breakpoint.  For example, you can specify that the execution of the program should only be suspended when the hit count is greater than or equal to 250. To put it in other words, the breakpoint will be skipped for the first 249 times it is hit.

The advantage of being able to set a condition with the hit count of a breakpoint is to make the process of debugging faster.

 

How can hit count based breakpoints be set?

Debuggers today have either a command line or a graphical user interface.  Mostly all debuggers provide a means to set hit count based breakpoints. Below are steps on setting such breakpoints in some of the debuggers I have used.

Microsoft Visual Studio 2005

  1. Set a breakpoint at a line in your code.
  2. Right click the breakpoint and then click on “Hit Count”.  You can also go to Debug -> Windows -> Breakpoints  and right click on the breakpoint that was just created and select “Hit Count”.
  3. In the dialog that pops up, you can choose from four ways of controlling the breakpoint based on its hit count.  The default is to ignore the hit count and suspend the program always when the breakpoint is hit. It is good to take note of the other three options.
Hit Count Window In Visual Studio 2005
Hit Count Window In Visual Studio 2005

When the program is in suspended mode, one can see the current hit count of the breakpoint in the breakpoint window.  In the image below, the “Hit Count” column shows the current hit count of the breakpoints.

Visual Studio Breakpoint Window

gdb

In gdb, the command continue is used to resume execution of the suspended program. When followed by a number N, the breakpoint is hit the Nth time.

(gdb) help continue
Continue program being debugged, after signal or breakpoint.
If proceeding from breakpoint, a number N may be used as an argument,
which means to set the ignore count of that breakpoint to N – 1 (so that
the breakpoint won’t break until the Nth time it is reached).
(gdb) continue 20

gdb is available on Mac OSX, Linux, AIX, Solaris, HPUX and Cygwin on Windows, etc so this is one command one should learn by heart.

On Mac OSX, the XCode IDE uses gdb internally and allows access to it through the menu (Debug -> Console Log).  Through the command line interface continue can be used as described above.

In gdb the info breakpoints command can be used to view the current hit count of all breakpoints.

(gdb) info breakpoints
Num Type           Disp Enb Address    What
1   breakpoint     keep y   0x0040118a in main at try.cpp:6
breakpoint already hit 246 times
3   breakpoint     keep y   0x004011a5 in main at try.cpp:8

Visual Studio and gdb differ slightly in terminology.  One allows setting breakpoints with a hit count and the other lets skipping of breakpoints for a certain count.  However they are essentially the same features that allows the programmer the option of not having to stop always at a breakpoint.  In the subsequent sections, the term “set a hit count breakpoint” is used instead of “skip the breakpoint n times”.  It should be trivial to interpret the tricks in terms of skipping a breakpoint.

 

WinDbg

I did not find a way to set hit count breakpoints in windbg yet.
Here is how you set a hit count breakpoint in WinDbg.

  1. Go to the source view and set a breakpoint in the source code.  The shortcut F9 can be used to toggle a breakpoint.
  2. In the command window (alt + 1), list all breakpoints using the bl command.
  3. Take note of the breakpoint that you just set and copy the location of the breakpoint which is listed in the format of <module_name>!<function_name>+<offset>.  See example below.
  4. Now redefine the breakpoint with the bp command.  After the bp command paste the location that you copied in the previous step followed by the hit count.

0:000> bl

1 e x86 00000000`004113b2     0001 (0001)  0:**** test_project!wmain+0x42
0:000> bp test_project!wmain+0x42 2300
breakpoint 1 redefined
0:000> bl
0 e x86 00000000`004113b2     2300 (2300) 0:**** test_project!wmain+0x42

The hit count in the above example is set to 2300.  This current  hit count as shown above is decremented each time the breakpoint is hit but the execution stops only when this number is equal to 1.  The number within the parentheses denotes the hit count that was originally set by the user. 

Using Hit Count For Fun And Profit

Many developers set breakpoints without the hit count conditions.  There are lot of nifty ways in which a hit count breakpoint can be used.

Below are some scenarios which developers will find useful while using hit count breakpoints:

Break In A Loop More Conveniently.

Setting an unconditional breakpoint in a loop (e.g. for, while, do-while) may break execution more often than needed.  If you know the iteration of the loop when you want to suspend execution of the program, you can set a hit count breakpoint.

For example, in the while loop below if the intention is to break in the 21stiteration,  a hit count based breakpoint will be more useful and simpler than a conditional one.  Do note that in the loop below, the variable i does not increment by one.

<code>int i = 0;
while( !flag &amp;&amp; i &lt; N )
{
/* some code */
i *= 2;
}</code>

Likewise, the for-loop below traverses through the int vector using an iterator.  If the intent is to break when the 10thelement in the vector is being processed in the loop, then a hit count breakpoint will be more useful and easy to set.

<code>std::vector&lt;int&gt;::iterator iter;
for( iter = vec.begin() ; iter != vec.end() ; ++iter )
{
/* some code */
}</code>

 

Create A Quick And Dirty Profiler And Much More.

 

Part I

Profilers that instrument code log the time taken by a function and the number of times it is called.  It is the latter where hit count breakpoints are very useful.  The greatest advantage of being able to track the number of times a function is called is that you don’t have a to run the code through a profiler but you get the results with the same accuracy.  Moreover profilers may crash at times but debuggers are pretty stable when it comes to debugging code.

The trick here is to set a hit count breakpoint that will never be reached.  For example, set a hit count to an unpractically large value (say 1000000) and set one breakpoint at the program termination (for example at the end of the main() function).

When the program is run, due to the large hit count, the breakpoint will never be hit and only the breakpoint at the end of the program will be hit.  The debugger however has no knowledge that the breakpoint hit count is too large for it to be hit and therefore tracks the count whenever execution reaches the breakpoint.

At program termination, when the program gets suspended due to your second breakpoint, you have the debugger waiting to tell you what the hit count of the first breakpoint currently is.  In other words it just told you how many times did the line of code get hit before the program terminated.  That exactly is the kind of information that the profiler would have told you.  Voila – you have that quick and dirty profiler ready for use :-).

Maybe someday I will write about how how a breakpoint works internally and then you can relate the similarity between what do the debugger and code instrumenting profiler have in common.

The above trick is explained in the C code snippet below.

<code>
void profile_me()
{
/* set hit count breakpoint here with a very large hit count */
/* function code */
}</code>

<code>
int main()
{
profile_me();
/* Set the second breakpoint here and when this is hit,*/
/* observe the hit count of the breakpoint set above */
return 0;
}</code>

Part II – Smart Breakpoints

Another use of hit breakpoints is very similar to the quick and dirty profiler trick.  At times when one encounters a crash in a loop or in a repeated function call, it may make more sense to debug a few iterations prior to when the crash actually happens.  For example,  say a loop is processing tokens  and a crash happens while processing the 2520th token.  The crash itself may not make much sense once it has occured but it may help to know what happened 5 iterations prior to the crash.  That way, the programmer  can collect data for prior iterations and reach the crash condition.   This will equip the programmer with relevant data needed to solve the crash at hand.

<code>while( token = get_token() )
{
/* some code */
switch( token )
{
case token_1: /*do code */
case token_2: /*do code */
/* more case statements */
}
}</code>

The trick here again is to set a very large hit count so that the breakpoint is never hit.  Once the crash occurs, the hit count of the breakpoint is noted.  Then the hit count of the breakpoint is reset to 5 minus the hit count obtained when the crash had occured.  From now on whenver the hit count condition is met and the breakpoint is hit, the programmer will know that in 5 iterations a crash is expected.  The data collected for the 5 iterations may be essential for resolving the crash.

 

Part III – Matching calls.

Hit count breakpoints have yet another use in debugging – matching the call count for a pair of functions.  For example, for every malloc call a free call should have been made in order to have zero memory leaks.  Similarly, a constructor (for now assume there is only one) and a destructor of a class should be called equal number of times.  These calls have an opposite effect but their pair should match to ensure that resources don’t leak.

<code>
C::C()
{
/* constructor */
}</code>

<code>~C::C()
{
/* destructor */
}
</code>

The trick is to set two hit count breakpoints with very large values that will never be reached in both the constructor and destructor above.  Also a breakpoint should be set at the point of program termination (for example at the end of function main() ).  The two breakpoints in the constructor and destructor will not be reached due to the very large values.  When the program’s execution is suspended at program termination due to the final breakpoint, the hit count of the two breakpoints set in the constructor and destructor should be checked and hopefully their hit counts should match.  Here I am assuming the class C was not involved in creating global or static objects.  A mismatch of hit counts may suggest that not all objects of class C were destroyed and a possible resource leak should be looked into.

In summary, if there are two calls that should be called equally during the life span of a program, then this trick can be used to check that the call hit counts do indeed match.

 

Final Note

Hit count is a slightly under used feature of a debugger but it can be used in many innovative ways to gain better control over debugging.  It is not a replacement for profilers but a great tool when you do not have one with you at hand.  The infinite-hit-count-breakpoints are useful to keep track of code workflow as these breakpoints are set with the intention of never wanting them to be hit.  However the information that such breakpoints can provide can be pretty useful and accurate.