Does TrueTime profile elapsed or processor time?

0 Likes

Problem:

Does TrueTime profile elapsed or processor time?

Also, when I instrument only 1 program, 99% of the time is reported as being spent in the kernel - does this make sense?

Resolution:

Truetime can profile both 'elapsed' and 'processor' time.  By unchecking quantum technology (turning it off), TrueTime will report elapsed time of your running application, including threads that are running in the background of your system processes.

With quantum technology 'on', TrueTime profiles running time with the exception that when the operating system pre-empts the CPU from your thread, the time is 'paused' until your thread gets to run again.  This is (obviously) much more accurate on a heavily loaded system, but not so important if this is the only process you're running.

I take 'processor' time to mean the amount of clock cycles executed.  TrueTime can currently profile in this mode with version 2.x and beyond.  Clock Cycles can be reviewed in your session file within TrueTime under View=>Scale=>Cycles  .

If your statistics (% of time spent in function) are being skewed by, for instance, a WaitForSingleObject call, and you want to even them out, one of the things you can do is exclude (See PCShared

mexclud.txt or the 'Exclude Images' menu item) the appropriate Windows DLL.  For instance, if you're spending too much time in WaitForSingleObject*, exclude kernel32.dll and user32.dll.

Here's an example that might make this a little clearer.

Process A is calling Process B through a TCP/IP socket using some kind of protocol.

Process A calls MyProtocol::SendMessage() which sends some data on the socket and then blocks the thread while waiting for the other process to reply.  10 seconds later, a reply is received, SendMessage() returns, and Process A goes back to doing other things.

Process B is blocking in MyServer::AwaitMessage() for 2 minutes before receiving the data block from ProcessA.  It calls MyServer::ProcessMessage(), which takes 9 seconds, and then spends another second in MyServer::SendReply().  It then goes back to AwaitMessage() for another minute before we close the process.

If you're running TrueTime on both Process A and B, by default, you'll end up with two session files with profiling information from the calls.

Your timing will indicate:

ProcessA::SendMessage(): 12 seconds   (say 10 seconds to wait and 2 seconds to do local processing)

ProcessB::AwaitMessage(): 3 minutes (2 1)

ProcessB::ProcessMessage(): 9 seconds (10 seconds with children)

ProcessB::SendReply(): 1 second

In some cases this doesn't track down the problem you're trying to solve.  You may not care, in ProcessB, that it took 3 minutes for a message to arrive - you only care how long it took to ProcessMessage()s (and the local portion of AwaitMessage(), perhaps, not indicated in my example).

If you look at the function call hierarchy for AwaitMessage() you will see that, at a low level, it calls some socket routines, and has a lot of time spend in WaitForSingleObject (the part which blocks waiting for input).  If you use the 'Exclude Images...' option in TrueTime to exclude the DLL that WaitForSingleObject is in, you will find that the %'s are now distributed over more of your code and less on the system.

Old KB# 11467
Comment List
Anonymous
Related Discussions
Recommended