Reporting Your Own CPU Time on Windows
Unix has the ‘time’ command to report the running time of a process. Actually there’s both the time command, /bin/time or /usr/bin/time, provided by time-1.7 on my CentOS server, and the bash builtin command time. They have slightly different output formats but they both report the run time (aka wall clock time) and CPU time in both user mode and kernel mode:
[smikes@arthur ~]$ time ls >/dev/null
real 0m0.055s
user 0m0.000s
sys 0m0.004s
[smikes@arthur ~]$ /usr/bin/time ls >/dev/null
0.00user 0.00system 0:00.00elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+253minor)pagefaults 0swaps
[smikes@arthur ~]$
Windows? No native equivalent. If you install Cygwin (which you should) then you get /usr/bin/time and bash-time as above. That’s handy for you, but unless you can guarantee your users will have Cygwin installed too, not something you can rely on.
Ages ago I had put in some trivial timing code into $CLIENT’s main application. It was just based on recording time() at program start and successful exit and reporting the run time in hours, minutes, and seconds from that. Some time later while my brain was thoroughly disengaged, I added another counter based on clock_t and, to distinguish it from the first one, I reported that as “CPU time”.
Now it’s several years later and I get the following exceedingly polite bug report:
Consider these two successive builds of ___, one without the error files and one with. The error files are significant, but not that significant.
ST:Total CPU Time: 1:39:12.42
ST:Total Wall Time: 1:39:14.Second run, when I got the computer much busier doing test builds.
ST:Total CPU Time: 2:16:23.08
ST:Total Wall Time: 2:16:25.The reported CPU time should not be significantly higher than the first run, but it is suspiciously close to 100% of the Wall Time. As I used a significant amount of CPU time on other processes, I know the reported CPU tim [sic] cannot be correct.
Busted! I must have been thinking that clock_t was magically going to give me a CPU time number since I associate clock_t with timing loops. But over the entire run time of the application, of course it will record all the time, both execution time and wait time.
After poking around for a while I rediscovered WMI, the Windows Management and Instrumentation service. Among other things it keeps per-process counters for kernel mode and user mode execution time. It comes with a wealth of baroque interfaces, including COM (of course), an interactive/batch command-line client (wmic.exe), and others. I didn’t want to add any more COM to this C application, so decided to try the command-line client first.
Here’s my first spike solution:
#include <stdio.h>
#include <process.h>
int main()
{
FILE * pf = NULL;
pf = _popen( "wmic process where Handle=5612 list FULL", "r" );
while( !feof( pf ) )
{
char acLine[512];
fgets( acLine, 512, pf );
if( strncmp( acLine, “KernelModeTime”, 14 ) == 0 )
{
printf( “Kernel mode time: %.2f s\n”, atof(acLine+15)/1.0e6 );
}
}
}
Note that I’m just hardcoding a process ID in (that happened to be my MSDEV.exe process ID at that time, actually) and reading into a static fixed-size buffer. The wmic command line was developed by repeated hacking around with wmic /? and some judicious googling.
When I compiled this with MSVC (cl test.c => test.exe) and ran it under cygwin, I got a hard hang of my rxvt. But running it under cmd.exe worked fine, yielding a reasonable-enough looking number. Encouraged, I proceeded to integrate it into the application.
My first version was quite similar to the spike above, but with a longer buffer. This worked fine but gave nonsense results, reporting 222 seconds in user time when the total execution time was only 85 seconds. Apparently the WMI data is reported in tenths of microseconds instead of microseconds. The older documentation I initially found gave milliseconds as the unit for the script object interface, but more recent documentation says 100-ns units, as I found. Apparently the reasonable-seeming result I saw in my spike solution was ten times too high.
Then I decided to do away with the fgets(), static buffer, and strncmp and switched to reading into malloc’ed storage and using strtok(). That was all good and it ran beautifully in the debugger. But when I started the program from a cygwin command-line, I again got a hard hang, uninterruptible by Ctrl-C, leading to an rxvt crash.
It turns out that Windows _popen() and Cygwin just do not play nicely together. Furthermore, any moderately advanced Cygwin console (e.g., an rxvt) uses a pty device instead of the raw Windows console device, and ptys are confusing to the wmic command-line client. You can find the source material yourself on Google: http://www.google.com/search?q=wmic+cygwin and http://www.google.com/search?q=_popen+cygwin.
So I went to the age-old ugly solution of writing to a temporary file. My application runs in a dedicated directory and assumes it has exclusive control of the current directory, so I don’t protect against race conditions. But then I discovered that WMIC writes UTF-16 output which Windows had been recoding to my local code when I used _popen(). When dumped to a file, Windows left it alone and I became responsible for recoding it myself (or using it as-is). So I switched to the ‘wcs’ versions of the string functions I was using, and used our utility function read_lineW to read a line from the file into malloc’ed storage.
I think you need administrator access to read WMI performance counters (or maybe just to run WMIC?), so admin access is necessary. Since it depends on hardcoded localizable constants (UserModeTime etc.) it probably won’t run on a localized Windows where wmic.exe displays BenutzerModeTime or whatever. But it works for my purposes, and maybe for yours too:
Here’s the final code:
char * format_hmsd( double dSeconds )
{
static char acBuffer[32] = {0};
int nSeconds = (int)dSeconds;
int nMinutes = nSeconds / 60;
double dFrac = dSeconds - (nMinutes * 60);
int nHours = nMinutes / 60;
int nMinRemainder = nMinutes % 60;
sprintf( acBuffer, “%2d:%02d:%05.2f”, nHours, nMinRemainder, dFrac );
return acBuffer;
}
void wmi_time( double * pdKernel, double * pdUser )
{
FILE * pf = NULL;
char acFile[32] = {0};
char acCmd[128] = {0};
wchar_t * psLine = NULL;
DWORD nID = GetCurrentProcessId();
*pdKernel = *pdUser = 0.0;
sprintf( acFile, “wmi%04d.out”, nID );
sprintf( acCmd, “wmic process where handle=%d list FULL %s”, nID, acFile );
system( acCmd );
pf = fopen( acFile, “rb” );
for( psLine = read_lineW( pf ); psLine != NULL; free( psLine ), psLine = read_lineW( pf ) )
{
wchar_t * psKey = wcstok( psLine, L”=” );
wchar_t * psValue = wcstok( NULL, L”" );
if( psKey != NULL )
{
if( wcscmp( psKey, L”KernelModeTime” ) == 0 )
*pdKernel = wcstod( psValue, NULL ) / 1.0e7;
else if( wcscmp( psKey, L”UserModeTime” ) == 0 )
*pdUser = wcstod( psValue, NULL ) / 1.0e7;
}
}
fclose( pf );
remove( acFile );
}
/* Used like this:
double dKernel, dUser;
double dTotal = (clock() - clkStart+0.0)/CLOCKS_PER_SEC;
wmi_time( &dKernel, &dUser );
logmsg( “ST:Total Wall Time : %s.\n”, format_hmsd( dSeconds ) );
if( dUser != 0.0 || dKernel != 0.0 )
{
logmsg( “ST:Total I/O Time : %s.\n”, format_hmsd( dSeconds - dUser - dKernel ) );
logmsg( “ST:Total CPU Time : %s.\n”, format_hmsd( dKernel+dUser ) );
logmsg( “ST:Total Kernel Time: %s.\n”, format_hmsd( dKernel ) );
logmsg( “ST:Total User Time : %s.\n”, format_hmsd( dUser ) );
}
*/