Archive | gprof RSS for this section

Profiling With Gprof

As promised, today I’ll be talking about GProf.

What Is GProf?

Gprof is a profiling tool. There are two versions: the original written for BSD UNIX, and a re-implementation for Linux. There are some minor differences between the two that you can read about here. We are going to concern ourselves with the Linux version.

Gprof is a pretty bare-bones utility. In the spirit of UNIX it does just one thing well. It doesn’t have any fancy menus or exotic extras. You just run it and it goes.

Preparing Your Program

First things first, we need to compile and link our program with profiling enabled. Using gcc, this is easy; just add -pg to the compile and linking options. If you’re using NetBeans, this is simple as well.

In NetBeans, right click your project and click Properties

Click Build > C Compiler. In the Additional Options field, add -pg to the end.

Click Build > Linker. In the Additional Options field, add -pg to the end.

Click OK. You are now good to go. Clean and build your project and you are ready for the next step.

Run Some Test Cases

Here is where things get confusing. You’ve compiled your program, surely you have to run your application within gprof similar to how you ran Valgrind, right? Let’s give that a shot…

# gprof [your_program] gmon.out: No such file or directory

Hmm… I’ll save you some time: Google will tell you that gmon.out should be there, clearly you messed something up and you’re a bad person.

Here’s the secret: you aren’t supposed to run your program through gprof at first. You need to run your program by itself first and it will create gmon.out in the current directory upon termination. Repeated runs will replace the existing gmon.out file. Run your application and perform some test cases. Follow good test practices and really stress your program. Now, you are ready to generate your profile data. Make sure gmon.out is in the current working directory and then…

gprof [your_program] > [output_file]

GProf should return without error and there should be a new file. Open it up in your favorite text editor. As you can see, it contains a flat profile, and a call graph of your program. Below each is a description of the columns. You should be able to take it from here, but if you want additional information check out the GNU gprof webpage.

Oh yeah, and don’t forget to remove the -pg from your compiler and linker lines when you’re done; they’ll tank your performance.

DMP Photo Booth: Underwater

You’ve heard it before: “Premature optimization is the root of all Evil.” Capital Evil. So you go on about your day, arranging the ones and zeros in pretty christmas tree shapes and suddenly the day arrives: your program is slow as molasses. What are you going to do now?

Last monday was that day for me, and I’ve been underwater ever since. “Why is this happening to me?!” I thought. While not prematurely optimizing, I thought I did things right. I have no nested for loops. I’m not using an array when I need a list. Threads aren’t modifying the UI willy-nilly. Why has God forsaken me?

The Symptoms

I first noticed it while working on the printer module. After the program is open for some length of time, my whole computer begins to lag. Not just a little bit either; things completely fall apart. In the space of about 5 minutes, the computer becomes unusably slow. Killing the Photo Booth process doesn’t help; only physically shutting the computer off helps. Of course, the computer is so slow that I can’t use the shutdown option; I have to press The Button.

At this point, I feel some context is in order. I had been trying to figure out how to make my printer print on photo paper. Apparently printing is one of the areas Linux still hasn’t caught up to windows on, so this was proving to be difficult. After printing a few strips, I realized that my low-res photo strips weren’t going to cut it, so I bumped the resolution from 100 pixels wide to 1000. It was then that I noticed things were off.

Ten years of troubleshooting experience kicked in: “what changed?” I thought. The obvious answer was the image size. Clearly my photo strip assembly algorithm was operating at O(n^n^n) or something. What can be done?

Doing It Wrong

I took a look at my assemble strips function. After poking around for a while, I zeroed in on something that had been bugging me for a while. I had been using a function MagickResetImagePage combined with MagickCoalesceImages to composite images over each other. I had decided to use these functions before I knew this operation was called “compositing”, and I had found them in a tutorial on making animated .gif files in MagickWand. At the time, I was never really happy with this implementation, so I went back to the API docs to see if there was a function with “composite” in its name. There was.

MagickCompositeImage is a lot more intuitive to use than MagickResetImagePage. It doesn’t have that Magickal formatting string that MagickResetImagePage uses, it just takes coordinates. Perhaps this was the solution to my problem. I refactored, and recompiled.

Still broke.

Measure, Don’t Guess

That old gem: I’m sure you’ve heard it too. I decided that maybe this was my best course of action. I decided it was time to learn how to use this Valgrind thing all the Cool Kids are talking about these days. For those of you not in the know, Valgrind is a utility that will tell you various things about your program. The most important/most well-known thing that it can do for you is identify memory leaks. Thinking that prehaps I have a memory leak, I installed Valgrind and got to work.

It turns out that GTK has more than a few memory leaks. Allegedly this is due to the fact that it doesn’t cleanup on exit, relying on the OS to free the memory on program termination. While the general consensus is that this is fine, it doesn’t help us. The folks at Gnome are aware of this, and there is even a Wiki page on ways to mitigate this. The cliff’s notes version of that page being: “Just search for ‘definitely lost'”.

Armed with this piece of wisdom, I set off. I ran the Photo Booth in Valgrind, and examined the results. Valgrind actually turned up some memory leaks, which I corrected. Maybe now we’re set!

Nope.

Breaking Out The Profiler

This is what they usually want you to do when they tell you to Measure. Unfortunately for me, NetBeans’ built-in profiler is only for Java. After some google searching, I found gprof. Gprof is a pretty bare-bones profiler. It does what it says and not much else, which is fine. I hooked my program into the profiler and got to work. The results? Nothing. My two GTK idle functions ran some 7 million times, returning basically immediately each time as expected. Every other function performed as expected.

What now?

Trying The Process Monitor

Having run through Valgrind and GProf, coming out empty-handed, I was at a loss. I got into development because I wanted to fix my own broken code instead of mitigate somebody else’s, and fix it I will. Luckily I have 10 years of sysadmin experience to fall back on. I dusted off my process monitor and got to work.

I fired up DMP Photo Booth, and watched it in the process monitor. I pushed the button. I pushed it again. And again. memory use rose and fell predictably as the strip was assembled, but CPU usage stayed relatively low. Then boom!

I tried again, this time doing literally nothing. Still my computer sputtered and died. I killed the process, but again it was too late.

But wait, isn’t the OS supposed to clean up after me when my process ends? Something fishy is going on.

Have I Mentioned That Threads Are Hard?

Having eliminated all other possibilities, I was forced to consider that I was having a threading issue. “But I was so careful!” I thought. Shortly thereafter I noticed it: I was getting random pthread mutex errors on my console. Clearly I had a threading issue on my hand. Was I spawning extra threads? Was something not releasing its lock? Was I being victimized by gremlins? I set a break point on line one of main() and fired up my debugger. It was time to see just what was being done when nothing was being done.

So, I stepped through my program. Whenever I got to a g_thread_new call, I made sure the thread function was solid. Finally, I got to my g_idle_add calls. I had two of them, one to monitor the status indicators, and one to retrieve photo strip thumbnails. Both of these functions pop from a result from a GAsyncQueue. These Queues are fed by worker threads. I thought back to my profiler output and remembered how often these are called. Looking a few lines down I saw a call to g_timeout_add_seconds. This function is basically adds an idle function, but is only called at most X seconds. Maybe replacing the g_idle_add calls with g_timeout_add_seconds was my answer. I refactored and reran.

Nope.

Well, crud. “Are these functions even my problem?” I thought. I commented them out, recompiled and reran.

Fixed.

“So, what’s the difference?” I wondered. All three of these functions rely on the same basic behavior: pop from a GAsyncQueue some result placed there by a worker thread. I looked at the three threads: the thread that was working properly calls g_async_queue_ref/unref, and the two that don’t work do not take a reference, instead accessing the static global variable in their module. I refactored all thread functions that access a GAsyncQueue to take a reference and work on their local copy only. I recompiled, reran, and went to bed. 46,100 seconds later, everything was humming along just fine.

Wait, So I Just Had To Increment A Reference Count?

It certainly seemed odd. That’s like your car not starting if the headlights are out. Sure, they’re important, but the car should still start right?

Looking through the source of glib didn’t help. So far as I can tell, all that does is increment the reference count, and return a pointer. I turned to the documentation, which says “… Whenever another thread is creating a new reference of (that is, pointer to) the queue, it has to increase the reference count (using g_async_queue_ref()). Also, before removing this reference, the reference count has to be decreased (using g_async_queue_unref()). …” While not definitive, this certainly seems to indicate that taking a reference is important.

Frankly, I’m not happy about this answer. This is just the sort of magic solution that I hate; it’s fixed, but I’m not sure why. For the time being, I won’t dwell on it. Moving forward, I’ll be sure that my threads take a reference of a GAsyncQueue before calling methods on it. At some point when all of this is said and done, perhaps I’ll investigate this mysterious reference count.

I have taken away from this a new appreciation of just how brittle threads are. Sure, they are powerful, but shooting yourself in the foot with a 50 cal hurts a lot more than with a 9 mm. I’ll have to be more careful.

It was also a good introduction to GProf and Valgrind. Expect blog posts on the usage of each of these tools soon!

%d bloggers like this: