Thread: Weird Times I'm getting

Hi everyone,

I have been measuring some times for an application I'm doing, using some source code I found on the internet for measuring system time and user time used by an application. I am getting some very strange results though, and I wanted to ask if they were possible or were maybe due to some programming error.

The results

User time greater than real time, that's weird

Reading from Dataset
User time was: 19.333 /
System time was: 1.29179
Real time was: 18

Their sum isn't close to the real time, where is this time being spent?
Inserting to Database with engine MyISAM
User time was: 0.396942
System time was: 0.849879
Real time was: 9

Their sum isn't close to the real time, where is this time being spent?
Inserting to Database with engine InnoDB
User time was: 0.440937
System time was: 1.70573
Real time was: 211

This is the source I'm using to measure time

Code:

/* -------------------------------------------------------------

   Timer.hpp

   Implementation of a Timer class.

   (P)1999-2000  Laurentiu Cristofor

   -------------------------------------------------------------*/

#ifndef _TIMER_HPP_
#define _TIMER_HPP_

extern "C"
{
#include <stdio.h>
#include <string.h>
#include <sys/types.h>
#include <sys/time.h>
#include <sys/resource.h>
}

#include <iostream>

// This class is a container for time results
class TimeElapsed
{
 friend std::ostream& operator<<(std::ostream& os, TimeElapsed& t);

private:
  long userTime, systemTime, realTime;

public:
  TimeElapsed(long user, long system, long real)
    {
      userTime = user;
      systemTime = system;
      realTime = real;
    }

  long getUserTime()
    {
      return userTime;
    }

  long getSystemTime()
    {
      return systemTime;
    }

  long getRealTime()
    {
      return realTime;
    }
};
class Timer
{
 private:
  time_t begin, end;
  struct rusage beginusage, endusage;
  // the time counted so far
  long utime, stime, rtime;

  // indicate whether the timer has been started
  bool started;

  // if true then return number of microseconds
  // for user and system time;
  // else return number of seconds.
  bool precision; 

 public:
  // if precision is set to true, then the real and system time
  // will be measured in microseconds
  Timer(bool precision = false)
    {
      utime = stime = rtime = 0;
      started = false;
      this->precision = precision;
    }

  // start timer, if already started then do nothing
  void start()
    {
      if (started)
	return;

      started = true;
      begin = time(NULL);
      if (getrusage(RUSAGE_SELF, &beginusage) == -1)
	puts("getrusage error!");
    }

  // stop timer and return time measured so far.
  // if timer was stopped the time returned will be 0.
  TimeElapsed stop()
    {
      if (!started)
	return TimeElapsed(0, 0, 0);

      if (getrusage(RUSAGE_SELF, &endusage) == -1)
	puts("getrusage error!");
      end = time(NULL);
      started = false;

      if (precision)
	{
	  long uusecs = (endusage.ru_utime.tv_sec 
			 - beginusage.ru_utime.tv_sec) * 1000000 
	    + endusage.ru_utime.tv_usec - beginusage.ru_utime.tv_usec;
	  utime += uusecs;

	  long susecs = (endusage.ru_stime.tv_sec 
			 - beginusage.ru_stime.tv_sec) * 1000000 
	    + endusage.ru_stime.tv_usec - beginusage.ru_stime.tv_usec;
	  stime += susecs;
	}
      else
	{
	  long usecs = (endusage.ru_utime.tv_sec 
			- beginusage.ru_utime.tv_sec);
	  utime += usecs;

	  long ssecs = (endusage.ru_stime.tv_sec 
			- beginusage.ru_stime.tv_sec);
	  stime += ssecs;
	}

      rtime += (end - begin);

      return TimeElapsed(utime, stime, rtime);
    }

  // reset the timer, this will reset the time measured to 0 and
  // will leave the timer in the same status (started or stopped).
  void reset()
    {
      utime = stime = rtime = 0;

      if (started)
	{
	  begin = time(NULL);
	  if (getrusage(RUSAGE_SELF, &beginusage) == -1)
	    puts("getrusage error!");
	}
    }

  // return time measured up to this point.
  TimeElapsed getTime()
  {
    if (!started)
      return TimeElapsed(utime, stime, rtime);

    if (getrusage(RUSAGE_SELF, &endusage) == -1)
      puts("getrusage error!");
    end = time(NULL);

    if (precision)
      {
	long uusecs = (endusage.ru_utime.tv_sec 
		       - beginusage.ru_utime.tv_sec) * 1000000 
	  + endusage.ru_utime.tv_usec - beginusage.ru_utime.tv_usec;

	long susecs = (endusage.ru_stime.tv_sec 
		       - beginusage.ru_stime.tv_sec) * 1000000 
	  + endusage.ru_stime.tv_usec - beginusage.ru_stime.tv_usec;

	return TimeElapsed(utime + uusecs, 
			   stime + susecs, 
			   rtime + end - begin);
      }
    else
      {
	long usecs = (endusage.ru_utime.tv_sec 
		      - beginusage.ru_utime.tv_sec);
	
	long ssecs = (endusage.ru_stime.tv_sec 
		      - beginusage.ru_stime.tv_sec);
	
	return TimeElapsed(utime + usecs, 
			   stime + ssecs, 
			   rtime + end - begin);
      }
  }

  bool isStarted()
  {
    return started;
  }
};

inline std::ostream& operator<<(std::ostream& os, TimeElapsed& t)
{
    float userTime = t.getUserTime()/1000000.0;
    float sysTime  = t.getSystemTime()/1000000.0; 
    
    os << "User time was: " << userTime << std::endl
       << "System time was: " << sysTime << std::endl
       << "Real time was: " << t.getRealTime() << std::endl;

    return os;
}

#endif // _TIMER_HPP_