The Lazy Man’s Profiler

The way we're all taught to profile is you install a profiler like dotTrace and then run your code under it. It shows you the hotspots and you dive in to that code to figure out how to optimize it. This is a great approach for many cases. I've used it myself a lot, especially back when I did game programming.

However, there are a lot of times where a much easier approach is equally effective. And for some cases, much more effective. It's fast, it's simple, and it gets the job done. What is it?

1. Start your program under the debugger.
2. Every 10 seconds hit pause in the debugger. Record where you are in the program.
3. After doing this 5 – 10 times, stop.

For a great many situations you will find that of the 10 times you broke into the program, it is in the same code each time. You now know where the code is spending its time. And you did this without installing a profiler, without running it, without having to dive into its results.

This approach is not a panacea. First off, a profiler will give you the actual lines of code that are taking the time, and how much on each line. This quick approach works great when it is a single line of code. The more spread out the issue is, the less helpful it is. Even if the time is all in one method, it can be certain parts of a loop for example that are sucking up the time – but it is various parts each taking significant time. There are many other cases where this is not the best approach.

But there are also some great advantages to this approach. With our reporting/docgen program a lot of the time the big hit is a single select in the report template. A profiler will show that it is the selects that are taking the time. But breaking into the debugger makes it easy to see what select on each break. If it is consistently the same 1 or 2 selects, then you know that what needs to be optimized is not executing a select, but a specific select. (Or a column in the database needs to be indexed.)

Another case we have seen at times is the hit is importing images or sub-reports from a specific server. Again, if on each break it is waiting for a file to be read from a website, and the break always shows that it is when hitting a specific website, then the problem clearly is not reading a file, but the response time of a specific server.

When to use it?

With very rare exceptions I always use the debugger break approach first. When that is sufficient (about 60% of the time), then I am working on the performance issue a minute or two after starting.

And for the other 40% of the time, I have dotTrace (.NET) and YourKit (Java) installed and I fire them up and dive into the result tree from them.

Comments

[RobotDadcat]

"Record where you are in the program?" You mean just eyeball where you are and make a mental note of it? Every 10 seconds? And just hope you land on a piece of code that's a bottleneck? This sounds like a very crude approach.

Could you perhaps give an example of how you've successfully tuned code like this while writing Enterprise-grade software?

[David Thielen]

Hi RobotDadcat;

I can give you a good recent example. We have a customer who ran under a profiler and found that ExecuteSelect() was taking all the time. They were next going to set up a profiler in Sql Server when I suggested this approach.

They did 10 breaks and found each time it was for the same select - which had a condition on a column that was not indexed. They indexed the column and it then ran super-fast. So a minute of hitting break instead of configuring Sql Server to profile incoming selects.

As I said in my post, it's not always the best approach. But it works well in many cases. And when it does, it saves a lot of time.

[robert annett]

I also use this all the time. A recent example (for RobotDadcat) was a report running very slowly on a piece of third party software (financial reporting software that cost well over $1M). I hit pause a few times and it was always stopping on the same piece of code that was loading simple data. I looked down the stack and it turns out that that the data was being loaded 25,000 (for each item in the system) but it should have been loaded only once at the start. Once this was removed the report run in under half the time.

This method is very good for discovering really stupid errors rather than subtle ones.

[Jerven]

In the java world you can do the same even easier using ThreadDumps. Using the command jstack which is in the java bin path.

For example in a linux shell.

for i in `seq 0 10`;do jstack $PID_OF_JAVA_THAT_NEEDS_PROFILING;sleep 10s;done |less

And you can quickly see extreme hot spots.
However, once the worst problems are found you might want to break out the free jvisualvm and use the sampling profiler included for the less obvious performance problems.

[Scott Wells]

As long as you're already connected with a debugger, why not set your breakpoints up so that they don't pause any threads and log very simple expressions. I've used this technique extensively to instrument "ad hoc logging" and to do entry/exit logging on key methods that I suspect/know are involved in the operation I'm investigating. The debuggers in all three major IDEs (IDEA, Eclipse, and NetBeans) support this feature.

[Cédrik]

Or you could use a light-weight sampling profiler like the one I built for MessAdmin, my open-source monitoring tool.

In addition to CPU profiling, you will also get tons of information on your application, including when you leave your dev box and go in production.

(Disclaimer: the CPU profiler is unreleased yet as of this writing. Send me an email should you want to have a copy before I release it to the world.)