Debugging Mutex and Locks

When there are multiple Mutex's in the program, it may be required to find if a particular thread is locked far longer than necessary. This can cause problems and the output may not be what is expected.

To get round this, I took an old example from here and modified it to help me print some debugging info.

I modified the printSomething() in Singleton.h to add a sleep as follows:

  void printSomething(char *name, int count)
 {
   Lock guard(mutex_);
   Sleep(10);
   Lock guard2(mutex_);
   std::cout << name << " loop " << count << std::endl;
 }

and I modified the Mutex.h as follows:

//Example from http://www.relisoft.com/Win32/active.html
#if !defined _MUTEX_H_
#define _MUTEX_H_

class Mutex
{
   friend class Lock;
public:
   Mutex () { InitializeCriticalSection (& _critSection); }
   ~Mutex () { DeleteCriticalSection (& _critSection); }
private:
   void Acquire ()
   {
     DWORD start = GetTickCount();
     EnterCriticalSection (& _critSection);
     DWORD elapsed = GetTickCount() - start;
     if (elapsed > 15)
     {
       //Debugging Info
        std::cout<<"Debugging Info: Waited at mutex for "<<elapsed<<std::endl;
     }
   }
   void Release ()
   {
       LeaveCriticalSection (& _critSection);
   }

   CRITICAL_SECTION _critSection;
};

#endif 

The output is as follows:

The small problem with the above approach is that if a Thread is deadlocked, we may not get the debug output as we would have to kill the process.

Measuring elapsed time in C++ using timeGetTime()

Continuing our theme of Performance Measurement by getting the elapsed time between different instances, today we look at another approach using timeGetTime() method. The code and approach is the same as GetTickCount() case except that the call is replaced.

So whats the difference and which one is better. timeGetTime() has a default resolution of around 5ms but by using the timeBeginPeriod(1) the accuracy can be made upto 1ms. GetTickCount accuracy and jitter cannot be guaranteed. timeGetTime() has more overhead than GetTickCount() so it should not be used in the case where the calls will be frequently made.

Another thing which may be obvious is that GetTickCount() actually calculates the time based on the number of clock interrupts and multiplies it by clock frequency. timeGetTime() reads a field called interrupt time which is updated by Kernel periodically.

Finally, if possible always use QueryPerformanceCounter() as thats better and receommended.

//Program tested on Microsoft Visual Studio 2008 - Zahid Ghadialy
//This program shows example of Getting Elapsed Time
#include <iostream>
#include <Windows.h>

using namespace std;

unsigned long startTime_;

void startTime()
{
  startTime_ = timeGetTime();
}

unsigned int calculateElapsedTime()
{
  unsigned int diffInMilliSeconds = timeGetTime() - startTime_;
  return diffInMilliSeconds;
}

int main()
{
  //Increasing the accuracy of Sleep to 1ms using timeBeginPeriod
  timeBeginPeriod(1); //Add Winmm.lib in Project
  unsigned int diffTime = 0, lastTime = 0, newTime = 0;
  startTime();
  cout<<"Start Time = "<<calculateElapsedTime()<<endl;

  Sleep(100);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after 100ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(100);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after 100ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(5);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after   5ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(50);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after  50ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;

  timeEndPeriod(1); //Must be called if timeBeginPeriod() was called
  return 0;
}

The output is as follows. Notice more reliable and jitter free output:

Measuring elapsed time in C++ using QueryPerformanceCounter()

Yesterday we saw a primitive approach to getting the elapsed time, today we will have a look at the most popular and standard way of getting the elapsed time using QueryPerformanceCounter and QueryPerformanceFrequency approach.

Unlike the GetTickCount approach, which is not very reliable and does not have good resolution, this approach is quite reliable and has very good resolution, often better than a ms. The only problem with this approach used to be that in old systems it may not be very reliable. For example in some old OS (before XP sp2) in case of multiple processors present, and if the clocks of both the processors are not very well synchronised (doe to buggy hardware) then you can get different results each time the QueryPerformanceCounter call is made. Another problem with some chipsets with regards to their power saving is that the frequency changes while we use GetPerformanceFrequency call only once during the program. This can result in incorrect timing being returned. There were some other problems being present as well but they have now all seem to be fixed either in firmware or in the OS. It is recommended that this calls should only be used in OS greater than or equal to Windows XP SP2.

//Program tested on Microsoft Visual Studio 2008 - Zahid Ghadialy
//This program shows example of Getting Elapsed Time
#include <iostream>
#include <Windows.h>

using namespace std;

LARGE_INTEGER timerFreq_;
LARGE_INTEGER counterAtStart_;

void startTime()
{
  QueryPerformanceFrequency(&timerFreq_);
  QueryPerformanceCounter(&counterAtStart_);
  cout<<"timerFreq_ = "<<timerFreq_.QuadPart<<endl;
  cout<<"counterAtStart_ = "<<counterAtStart_.QuadPart<<endl;
  TIMECAPS ptc;
  UINT cbtc = 8;
  MMRESULT result = timeGetDevCaps(&ptc, cbtc);
  if (result == TIMERR_NOERROR)
  {
    cout<<"Minimum resolution = "<<ptc.wPeriodMin<<endl;
    cout<<"Maximum resolution = "<<ptc.wPeriodMax<<endl;
  }
  else
  {
    cout<<"result = TIMER ERROR"<<endl;
  }
}

unsigned int calculateElapsedTime()
{
  if (timerFreq_.QuadPart == 0)
  {
    return -1;
  }
  else
  {
    LARGE_INTEGER c;
    QueryPerformanceCounter(&c);
    return static_cast<unsigned int>( (c.QuadPart - counterAtStart_.QuadPart) * 1000 / timerFreq_.QuadPart );
  }
}

int main()
{
  //Increasing the accuracy of Sleep to 1ms using timeBeginPeriod
  timeBeginPeriod(1); //Add Winmm.lib in Project
  unsigned int diffTime = 0, lastTime = 0, newTime = 0;
  startTime();
  lastTime = calculateElapsedTime();
  cout<<"Start Time = "<<lastTime<<endl;

  Sleep(100);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after 100ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(100);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after 100ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(5);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after   5ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(50);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after  50ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;

  timeEndPeriod(1); //Must be called if timeBeginPeriod() was called
  return 0;
}

The output is as follows:

Measuring elapsed time in C++ using GetTickCount()

There are variety of ways to obtain the elapsed time in a program. We will look at some of the ways in the next few posts. The first approach is using the GetTickCount() method. It should be mentioned that this method is not very accurate and some people have gone to the extent of saying that this should be deleted from the standards. Nevertheless it is quite widely used for cases where high resolution is not required.

//Program tested on Microsoft Visual Studio 2008 - Zahid Ghadialy
//This program shows example of Getting Elapsed Time
#include <iostream>
#include <Windows.h>

using namespace std;

unsigned long startTime_;

void startTime()
{
  startTime_ = GetTickCount();
}

unsigned int calculateElapsedTime()
{
  unsigned int diffInMilliSeconds = GetTickCount() - startTime_;
  return diffInMilliSeconds;
}

int main()
{
  //Increasing the accuracy of Sleep to 1ms using timeBeginPeriod
  timeBeginPeriod(1); //Add Winmm.lib in Project
  unsigned int diffTime = 0, lastTime = 0, newTime = 0;
  startTime();
  cout<<"Start Time = "<<calculateElapsedTime()<<endl;

  Sleep(100);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after 100ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(100);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after 100ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(5);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after   5ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;
  lastTime = newTime;

  Sleep(50);
  newTime = calculateElapsedTime();
  diffTime = newTime - lastTime;
  cout<<"Time after  50ms Sleep = "<<newTime<<", Difference = "<<diffTime<<endl;

  timeEndPeriod(1); //Must be called if timeBeginPeriod() was called
  return 0;
}

The output is as follows: