0

Our top 3 functions are all showing up as thread sync objects; Mostly WaitForSingleObject().

Is this function extremely taxing, even when called with a 0 to just check status of a thread? Getting very concerned with values on these functions showing up 2 orders of magnitude more in selftime than any other value it profiles. Or perhaps Glowcode is just freaking out on this function because the code pointer happens to be there when it looks a whole bunch.

Neysor
  • 3,893
  • 11
  • 34
  • 66
Michael Dorgan
  • 12,453
  • 3
  • 31
  • 61

1 Answers1

0

First of all, Don't Look At Self-Time.

The only reason it's in there is because somebody might write code that spends too much time in tight CPU loops in their own code. Does your program spend all it's time inverting matrices or doing FFT?

The whole reason gprof was invented, and the whole avalanche of profilers that followed, is that real software contains lots of subroutines that call each other in a big rat's nest, and by far the easiest way to take too much time is to make subroutine calls that could be avoided. Self time does not expose those.

Next, whether you are looking at Wall time or CPU time, if WaitForSingleObject() is active a large fraction of time, that means your thread is mostly waiting for something. You need to find out what.

There is a very simple way to find out. Just hit Pause, Ctrl-C, Esc, or whatever key makes it halt in its tracks, and then look at the stack. Every line of code on the call stack represents an unfulfilled request which, if that request had not been made, the program would not be waiting. So that's how you know what it is waiting for.

If you happen to catch it when it's not in WaitForSingleObject(), do it again, maybe a few times. This may seem to be more effort than profiling, but you can choose between finding the problem or doing something easy.

Community
  • 1
  • 1
Mike Dunlavey
  • 40,059
  • 14
  • 91
  • 135
  • Thank you for the response and the links. I'd love to debate the usefulness of poor man's profiling, but not today. Turns out in my example, I had the profiler set to a mode that included thread time asleep against its overall usage, causing all our sleeping job threads to show up as time used by the app. Switching this option gave me the view of the code I was looking for. I will say that the thread you linked sure has a negative view of profilers in general. I've found them to be amazing tools myself (when used and setup properly). – Michael Dorgan Apr 09 '12 at 14:25
  • And, self time did catch some really stupid function calls landing in our top-10 overall usage list. Nice when fixing those gives a huge boost to performance for nearly free. – Michael Dorgan Apr 09 '12 at 14:26
  • @Michael: I've been called the "anti-profiling evangelist" :) There are problems that profilers find. There are problems that they don't find. What that means is the overall speedup ratio you can get is artificially low with profilers. Speed is limited by the problems that are not found. In *[this link](http://sourceforge.net/projects/randompausedemo/files/)* there's a 730x speedup. Certainly one can be skeptical of that, but all versions of the C++ code are there, and I would like to see if that could be achieved with that code, with some profiler. – Mike Dunlavey Apr 09 '12 at 14:38