Obtaining actual effective execution time per thread with hyperthreading

Hi!

I'm looking for a function like GetThreadTimes, but one that gives correct results in a hyperthreading CPU.

For instance, if you start 2 threads on a CPU with 1 physical core and 2 logical cores, GetThreadTimes will say that both these threads use 100% CPU.

However, in reality they only use 50% each. Is there a function that returns correct results, or is there another workaround?

Regards / Z

GetThreadTimes returns elapsed time in kernel + user-space. It doesn't really care what cores they were run on.

In what way do you see the returned values from GetThreadTimes as being incorrect?

gg

Quote:

---

Originally Posted by Codeplug

In what way do you see the returned values from GetThreadTimes as being incorrect?

---

Well, this problem is not only hyperthreading related. The issue is that GetThreadTimes returns the time the thread wanted to run, not the time when it was actually allowed to run by the scheduler (or CPU in case of HT). If I start 10 threads on a single core machine, and let each thread call GetThreadTimes after 10 seconds, it will return 10 seconds for each thread when it IMO should only return ~1 second.

GetThreadTimes returns info about
creation time of the thread
exit time of the thread of if the thread has terminated
time spent in kernal mode
time spent in user mode

Which values are you using that you think are not correct when multi-threads are used?

Quote:

---

Originally Posted by 2kaud

Which values are you using that you think are not correct when multi-threads are used?

---

Not wrong I guess, I'm only looking for a different function.

A function that takes the timeslices used by the scheduler into account - so that the value returned will be lower if many threads are competing to run on a single CPU.

>> The issue is that GetThreadTimes returns the time the thread wanted to run, not the time when it was actually allowed to run by the scheduler (or CPU in case of HT).
That's not what I see...

Code:

---

#include <Windows.h>
#include <iostream>
using namespace std;

CRITICAL_SECTION cs;

DWORD WINAPI MyThread(void *p)
{
    int n = reinterpret_cast<int>(p);

    if (n)
    {
        EnterCriticalSection(&cs);
        Sleep(10 * 1000);
        LeaveCriticalSection(&cs);
    }//if
    else
    {
        Sleep(1000);
        EnterCriticalSection(&cs); // should block
        LeaveCriticalSection(&cs);
    }//else

    return 0;
}//MyThread

ostream& operator<< (ostream &out, const FILETIME &ft)
{
    const ULONGLONG &ll = *reinterpret_cast<const ULONGLONG*>(&ft);
    out << ll / 10000.0 << "ms";
    return out;
}//<<FILETIME

void PrintThreadTimes(HANDLE t, const char *name)
{
    FILETIME create_t, exit_t, kernel_t, user_t;
    if (!GetThreadTimes(t, &create_t, &exit_t, &kernel_t, &user_t))
    {
        cout << "GetThreadTimes failed, ec = " << GetLastError() << endl;
        return;
    }//if

    cout << name << " , kernel=" << kernel_t << ", user=" << user_t << endl;
}//PrintThreadTimes

int main()
{
    InitializeCriticalSection(&cs);

    HANDLE t[2];
    t[0] = CreateThread(0, 0, &MyThread, reinterpret_cast<void*>(1), 0, 0);
    t[1] = CreateThread(0, 0, &MyThread, reinterpret_cast<void*>(0), 0, 0);

    WaitForMultipleObjects(2, t, TRUE, INFINITE);

    PrintThreadTimes(t[0], "Thread 1");
    PrintThreadTimes(t[1], "Thread 2");

    CloseHandle(t[0]);
    CloseHandle(t[1]);

    DeleteCriticalSection(&cs);

    return 0;
}//main

---

Output:

Code:

---

Thread 1 , kernel=0ms, user=0ms
Thread 2 , kernel=0ms, user=0ms

---

A whole lot of nothing going on for 10 seconds.

gg

From this code

Code:

---

#include <windows.h>
#include <process.h>
#include <ctime>
#include <iostream>
#include <iomanip>
using namespace std;

const int NOTHREADS = 10;        //Number of threads to start
const int THREADTIME = 10;        //Seconds for each thread to run

UINT __stdcall threadfunc(void* pArgs);
void PrintTime(FILETIME ft);

int main()
{
HANDLE        hdls[NOTHREADS];

UINT        id;

FILETIME create,
        exit,
        kernel,
        user,
        process;

        for (int i = 0; i < NOTHREADS; i++) {
                hdls[i] = (HANDLE)_beginthreadex(NULL, 0, &threadfunc, NULL, 0, &id);
        }

        cout << "Waiting " << THREADTIME << " seconds for threads..." << endl;

        if (WaitForMultipleObjects(NOTHREADS, hdls, TRUE, THREADTIME * 2000) - WAIT_OBJECT_0 >= NOTHREADS) {
                cout << "Problem with threads" << endl;
                return 1;
        }

        for (int i = 0; i < NOTHREADS; i++) {
                if (!GetThreadTimes(hdls[i], &create, &exit, &kernel, &user)) {
                        cout << "GetThreadTimes() failed. Error: " << GetLastError() << endl;
                        return 2;
                }

                cout << "Thread " << i;

                cout << " User: ";
                PrintTime(user);

                cout << " Kernel: ";
                PrintTime(kernel);

                cout << " Ran for: ";
                process.dwHighDateTime = 0;
                process.dwLowDateTime = exit.dwLowDateTime - create.dwLowDateTime;
                PrintTime(process);

                cout << endl;
        }

        return 0;
}


UINT __stdcall threadfunc(void* pArgs)
{
double        t = 0;

const time_t        st = time(NULL);

        while (time(NULL) - st < THREADTIME) {

                //Do some work
                for (int i = 0; i < 1000000; i++) {
                        t += i * 23.0 / 34.0 + i - 3456.0 / i;
                }
        }
        return 0;
}

void PrintTime(FILETIME ft)
{
SYSTEMTIME        systim,
                local;

        if (!FileTimeToSystemTime(&ft, &systim)) {
                cout << "File time conversion failed. Error: " << GetLastError() << endl;
                return;
        }

        if (!SystemTimeToTzSpecificLocalTime(NULL, &systim, &local)) {
                cout << "Local time conversion failed. Error: " << GetLastError() << endl;
                return;
        }

        cout << setw(2) << setfill(' ') << right << local.wSecond << "." << left << setw(3) << setfill('0') << local.wMilliseconds << " secs";
        return;
}

---

I get the following result

Code:

---

Waiting 10 seconds for threads...
Thread 0 User:  3.460 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 1 User:  3.265 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 2 User:  4.265 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 3 User:  4.640 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 4 User:  3.460 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 5 User:  3.640 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 6 User:  4.109 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 7 User:  4.390 secs Kernel:  0.000 secs Ran for:  9.218 secs
Thread 8 User:  3.937 secs Kernel:  0.150 secs Ran for: 10.140 secs
Thread 9 User:  4.406 secs Kernel:  0.150 secs Ran for: 10.140 secs

---

Where does this differ from you would want/expect?

This system has 2 physical one-core processors using hyperthreading giving 4 CPUs.

Quote:

---

Originally Posted by zerver

and let each thread call GetThreadTimes after 10 seconds, it will return 10 seconds for each thread when it IMO should only return ~1 second.

---

and how ar eyou doing this ?

if you have a loop that keeps checking the current time until 10 sec passed, then yes, that's 10 seconds of time the CPU was actually busy running your code, even if that code didn't do anything useful. (this is what 2kaud's example in #7 shows).

if you used ::Sleep(), one of the WaitFor...(), or one of several other ways to make the CPU give up it's timeslice to other threads, then your code should be near 0 for that (as evidenced by codeplug's test in #6)

Thanks for the replies. I was getting incorrect results because my threads load the CPU in bursts, e.g. 2ms of work and 10ms of sleep, and GetThreadTimes only has a resolution of 15ms.

GetThreadTimes works like this: Every 15ms it checks which thread is currently running, and then records the 15ms of execution time as belonging to that thread. This can of course give very skewed results. If a thread happens to be running at that very instant every 15ms and sleeps the rest, it will be recorded as a 100% load.

The results in CodePlug's post is what I would expect, but since it is hyperthreading it would be more correct if it returned 2 seconds per thread instead of 4. However, I have given up on using GetThreadTimes due to the low resolution.