Solving User Time Greater Than Real Time Problem

[FrostScYthe]

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

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

   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_

 

[FrostScYthe]

I analyzed this further, and I don't know if maybe someone knows what could be happening. With the previous program I was sending a query inserting rows to a table in MySQL, row by row (each row gets an insert query), and on the latest version I created an insert query with 500 rows. There is no major difference in inserting row by row in the MyISAM table type, but when doing that with InnoDB or Berkeley DB the times shoot up awfully high. Could this be attributed to the fact that InnoDB and BDB are transactional?

?