Condividi tramite

Readlog summary output: process run times

  • Articolo

Posted by: Sue Loh

Today I got a question about the readlog summary output:

When using the most recent version of readlog.exe with the '-s' (summary) option, I noticed that execution time for each process is divided between "Thread Run Time" and "Code Run Time".
What is the exact meaning of the two measures? Does "Thread Run Time" count the time spent in thread context? And what does "Code Run Time" stand for?

This is actually something I've been meaning to write up an answer to, for a while.  What I really want to do is write up a set of explanations for the readlog summary output to go underneath this help topic:  https://msdn.microsoft.com/library/en-us/wcedebug5/html/wce51tskCreatingLogSummary.asp  So, let's get it started.

If you have most of the CeLog zones enabled when you collect data, and run readlog with the "-s" (summary) parameter on your log, you'll find that readlog prints a summary of process run-times near the end of the output.  Here is an example:

Process information:
Process: Thread Run Time: Code Run Time: Status: Name:
0x00000000 0:12:59.168.614 0:12:59.168.614 Active Idle
0x0D9FF876 0:00:02.649.434 0:00:00.785.367 Active myapp.exe
0x0DFFF002 0:00:00.054.109 0:00:00.366.120 Active NK.EXE
0xADF860A6 0:00:08.906.271 0:00:25.196.551 Active device.exe
0xEDD7A0AA 0:00:01.084.391 0:00:28.635.039 Active gwes.exe
0xEDCC250E 0:00:00.500.821 0:00:00.254.410 Active services.exe
0x4DF8F23E 0:00:00.633.649 0:00:00.028.381 Active CeLogFlush.exe
0x8DF8F6C6 0:00:00.010.050 0:00:00.000.360 Deleted shell.exe
0x4DCE1F22 0:00:00.885.874 0:00:00.360.582 Active connmgr.exe
0xEDFC8BEE 0:00:08.646.739 0:00:32.265.645 Active filesys.exe

(I cut some processes out of the table to simplify it.)   The summary includes two different run-time sums per process.  The first one, "thread run time," is the total amount of time that the threads owned by that process ran.  The second, "code run time," is the total amount of time that threads owned by ANY process ran inside that process.  I fished around for a while trying to come up with a good name, and "code run time" was the best I could do.  After I explain it you can tell me if I should have picked something else.  :-)

If you are pretty familiar with Windows CE, you might already know what I'm talking about.  If you're relatively new to CE, you may not know that in Windows CE, threads can jump from one process to another.  Every thread has an "owner" process, but when it makes a call to an API that's implemented in a different process, the thread actually jumps into that process.  An application thread will probably make at least a few system calls, so the thread will spend a little time outside its own process.  So a typical application's thread run time will be a little higher than its code run time.  Meanwhile system threads never jump into applications, so the application's code run time will never be higher than its thread run time.  So, as you can see above, myapp.exe's threads ran for about 2.6 seconds, but they were only inside myapp.exe for 0.8 of those seconds.  The rest of the time, the threads had been calling into system processes.

On the other hand, system threads call APIs inside of other system processes all the time.  There is no real relationship between the thread run time and code run time of a system process.  The process' threads may have been calling out to other system processes, reducing their owner process' code run time.  Or applications and system processes may have been calling in, increasing the system process' code run time.  If you think about it, whenever threads are running inside a particular process, they are executing that process' code.  That's why I chose the name "code run time."  It tells you that the value represents how much time the code inside that process was executing.

Between the two values you get somewhat meager "profiler."  Sometimes the system is slow because a particular thread keeps running and running when it shouldn't.  Sometimes the system is slow because you're executing code that does a lot of work.  By looking at these values you can sometimes tell what you need to look further into.

The "Idle" process isn't really a process, and just represents how long the system was idle.  Its "thread run time" and "code run time" should always match, because they just represent how long the false "idle thread" is logged as running.  (CeLog represents CPU idle as a thread switch to a false idle thread, and the false idle process in the readlog summary output is a representation of the total time of the false idle thread.)

If you look above the process summary when you run readlog with the "-s" parameter, you'll also see a summary of thread run-times.  For example, you might see a few threads like this:

Thread information:
Thread: StartProc: CurProc: Run Time: Status: Name:
0x00000000 0x00000000 0x00000000 0:12:59.168.614 Active Idle
0xEDF86082 0xEDD7A0AA 0xEDD7A0AA 0:00:00.509.695 Active gwes.exe
0x8D9780AA 0x2DCC24C6 0x2DCC24C6 0:00:00.142.762 Active ossvcs.dll + 0x0000ad00
0x6DEBBFDE 0xADF860A6 0xADF860A6 0:00:00.021.637 Deleted NDIS.Dll + 0x000029f4

This output only shows the thread run time, not its run time in any particular process.  If you use the "-s" parameter in combination with the "-v" (verbose) parameter, readlog will also give you the thread run-times per process:

Thread information:
Thread: StartProc: CurProc: Run Time: Status: Name:
0x00000000 0x00000000 0x00000000 0:12:59.168.614 Active Idle
Time in process 0x00000000: 0:12:59.168.614 (100.0% of thread run-time)
0xEDF86082 0xEDD7A0AA 0xEDD7A0AA 0:00:00.509.695 Active gwes.exe
Time in process 0xEDD7A0AA: 0:00:00.254.310 ( 49.8% of thread run-time)
Time in process 0x0DFFF002: 0:00:00.006.231 ( 1.2% of thread run-time)
Time in process 0xEDFC8BEE: 0:00:00.246.854 ( 48.4% of thread run-time)
Time in process 0xADF860A6: 0:00:00.002.298 ( 0.4% of thread run-time)
0x8D9780AA 0x2DCC24C6 0x2DCC24C6 0:00:00.142.762 Active ossvcs.dll + 0x0000ad00
Time in process 0x2DCC24C6: 0:00:00.007.707 ( 5.3% of thread run-time)
Time in process 0x2DC966A6: 0:00:00.000.051 ( 0.0% of thread run-time)
Time in process 0x4DCE1F22: 0:00:00.000.010 ( 0.0% of thread run-time)
Time in process 0x0DA37B3A: 0:00:00.000.007 ( 0.0% of thread run-time)
Time in process 0xEDCC250E: 0:00:00.000.008 ( 0.0% of thread run-time)
Time in process 0xADF860A6: 0:00:00.068.886 ( 48.2% of thread run-time)
Time in process 0xEDFC8BEE: 0:00:00.061.775 ( 43.2% of thread run-time)
Time in process 0xEDD7A0AA: 0:00:00.004.314 ( 3.0% of thread run-time)
0x6DEBBFDE 0xADF860A6 0xADF860A6 0:00:00.021.637 Deleted NDIS.Dll + 0x000029f4
Time in process 0xADF860A6: 0:00:00.013.837 ( 63.9% of thread run-time)
Time in process 0xEDFC8BEE: 0:00:00.007.660 ( 35.4% of thread run-time)
Time in process 0x0DFFF002: 0:00:00.000.139 ( 0.6% of thread run-time)

You can see, for example, that the gwes.exe main thread spent only about half of its time inside gwes.exe (process 0xEDD7A0AA), and the other half inside filesys.exe (process 0xEDFC8BEE).  The output is not all that great, since it would be better to print the process name instead of the process handle.  It's something I hope to improve in the future.  But anyway this output can tell you, when you have a thread that runs for a long time, whose code that thread is running.  So you know where to look next.

The major use we put this information to in the past is looking at how much time threads spend inside filesys.exe.  Because that represents most of the file I/O -- reading code and data, and writing data.  If you are paging in a relatively large module or from a relatively slow file system, that can show up here.  If you are writing a lot of data or doing "secondary" writes like calling RegFlushKey (which turns into file system writes) you may see that show up here.

It is pretty easy, when looking at this output, to get so swamped with information you don't know what you're looking at anymore.  For the most part, this is more useful to us on the Windows CE team than it is to you out there, because we can actually go change filesys.exe or whatever is taking so much time.  But if you were writing a driver, you could look at this data to see how much time your driver thread is taking and where.  If you were writing a file system driver or block driver, you could potentially get a fuzzy idea how much time your driver is being called.

Finally, this data comes from having CELZONE_MIGRATE enabled, which makes the kernel log CELID_THREAD_MIGRATE events whenever a thread jumps into a different process.  If you don't have that zone enabled, there will not be any migration events in the log, so it will appear as if the threads always stayed inside their owner process.  In that case, the "thread run time" for every process will be the same as its "code run time."

Comments