Profiling with cygwin/mingw (some bugs, hangs, fixes, new features)

In the past few days I’ve been trying to optimise my emulator.  It’s been going quite well, though I’m running out of good optimisations to do now.

It all started going downhill when I tried using gprof in cygwin.  Turns out there is a bug in the current version which results in profile times showing zeros instead of real figures.  http://www.nabble.com/gprof-time-accumulation-problem-td19125108.html talks about this bug and provides some fixes.  Basically you need the latest gprof.exe or a really old one.  I checked out the source from CVS and rebuilt it.

The next problem I came across was that not everything was being profiled.

I wrongly thought I had to recompile libstdc++ with profiling support when I came across the next bug.  In all versions of mingw and cygwin, a program that is compiled with profiling support, and that exits very quickly, may hang.  I noticed this when configure scripts were hanging after testing the C compiler with int main() { return 0; }.

The bug turned out to be the use of TerminateThread in libgmon.

The GNU profiler works by injecting code into the target program to call the profiling code.  This profiling code is initiated by monstartup, and creates a new thread which every 100 milliseconds or so looks at the main thread (the program being profiled) and notes done  in a list where the program counter is.  At program exit, this list is dumped to gmon.out.  Then gprof parses gmon.out matching those addresses to symbols in the binary.

To turn off profiling in mingw, such as when the program is exiting. profile_off is called which uses TerminateThread to kill the profiling thread.  The problem with this is that TerminateThread can kill the thread when its just acquired a lock.  If the main thread uses this lock, it can hang since the terminated thread never released it.  The profiling thread in minimimalistic but it still uses some win32 functions which shouldn’t be terminated mid stream.

I rewrote the profiling exit code to exit gracefully, by examining a flag indicating termination is requested.  This fixed the hang.

I will hopefully submit a patch to mingw when I have some time.

In any case, I still wasn’t able to get full profiling information from my program.  Infact, libstdc++ is linked in statically to mingw.  Debug symbols are important to keep, as gprof works by using symbols available in the binary.  I overwrite libstdc++.a with the debug version since it wasn’t being used automatically.  Take that advice with a grain of salt.  Don’t do it unless you think you need to.  I could be wrong.

Another problem with profiling, is that it doesnt profile library or system calls.  I wrote a patch to libgmon so that if during a sample it found the program counter not to be contained by the program (eg, a library call), then it would do a stack traversal to find the first caller that can is inside the image; and thus can be profiled.

This works and I get generally close to 100% total times in a flat profile (I assume any discrepancy is from rounding errors).  The only problem with my patch to libgmon, is that you don’t get much extra information.  For example, I know that the new operator is using up 15% of the time in my program, but I don’t know who calls it.

In this particular case, I simply might hack at the code to extract the information on a case by case basis, but I don’t have a general solution which can be neatly packaged in a patch.

If your interested.. After a few rounds of optimisation, I can unpack a minimalist program of 5k by upx in about 0.15 seconds.  This is on my 2.5gz quadcore.  I can unpack calc.exe which is around 112k, packed by rlpack which is of medium complexity, in about 2.15 seconds.  There are other packers which are more complex than rlpack which incur more processing costs but I haven’t run too many tests yet.  I think my emulator is fast enough as-is for use in an email scanning AV, but not fast enough for on-access.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s