Profiling each thread in a multithreaded environment

Question

Is there any way to find out the actual time spent by a thread inside the CPU using MFC/Win32? By actual time, I mean I don't want to count the time the thread spent in states other than "Running". I tried GetThreadTimes() method in Win32 SDK but couldn't get the proper values. I want to do this because I want to check effect of setting the ThreadPriority on its scheduling i.e. how much of a difference does it make if I set the thread priority to THREAD_PRIORITY_BELOW_NORMAL instead of THREAD_PRIORITY_NORMAL?

Here is the actual code:

#include<iostream>
#include <afxwin.h>
#include <afxmt.h>
#include <time.h>



bool bStop = false;
long k1 = 0;
long k2 = 0;



UINT run1(LPVOID param)
{
    while(!bStop)
    {
     for(int i = 0; i < 10; ++i)
     {
      ++k1;
     }
    }


    return 0;
}


UINT run2(LPVOID param)
{
    while(!bStop)
    {
     for(int i = 0; i < 10; ++i)
     {
      ++k2;
     }
    }

    return 0;
}



void main(int argc,char *argv[])
{

    CWinThread* pThread1 =  AfxBeginThread(&run1, NULL, THREAD_PRIORITY_NORMAL);
    CWinThread* pThread2 =  AfxBeginThread(&run2, NULL, THREAD_PRIORITY_BELOW_NORMAL );

    Sleep(3 * 1000);

    bStop = TRUE;

    FILETIME f1,f2,f3,f4;
    GetThreadTimes(*pThread1, &f1,&f2,&f3,&f4);
    CTime t1(f4);



    std::cout<<"K1="<<k1<<"\n";
    std::cout<<"K2="<<k2<<"\n";
    std::cout<<"Thread1 Time="<<t1.GetSecond()<<"sec\n";
    std::cout<<"Exit\n";
}

Answer 1

Before going into profiling you should understand what the difference means. There is significant difference between NORMAL and BELOW_NORMAL. Since NORMAL is the default it's always part of "NORMAL priority" scheduling queue. However BELOW_NORMAL is not executed when there is at least one pending thread in NORMAL queue and other higher priority queues. On a loaded system, this can make a BELOW_NORMAL thread to wait for at least five seconds before Balance Set Manager kicks in and boosts BELOW_NORMAL priority temporarily to get it run.

NORMAL only waits for ABOVE_NORMAL and above which constitute minority of threads on a system. But anything below than NORMAL has to wait for all NORMAL and above.

Answer 2

GetThreadTimes() will give you the correct values. The problem is it gives it in FILETIME structure. You will have to convert FILETIME structure into a time that is easy to display to a user. You can do it with API FileTimeToSystemTime :

SYSTEMTIME stUTC;        
FileTimeToSystemTime(&f4, &stUTC);
std::cout<<"Thread1: Hour:"<<stUTC.wHour<<" Min:"<<stUTC.wMinute<<" Sec:"<<stUTC.wSecond<<" millSec:"<<stUTC.wMilliseconds<<std::endl;

In my machine the output was : Thread1: Hour:0 Min:0 Sec:3 millSec:0

Please ignore the year\day details as FILETIME Contains a 64-bit value representing the number of 100-nanosecond intervals since January 1, 1601 (UTC).

Don't forget to add kernerl time and user time to get the total time.