Thread: Weird Times I'm getting

  1. #1
    Registered User
    Join Date
    Jul 2008
    Posts
    52

    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_
    Last edited by afflictedd2; 07-22-2008 at 12:30 PM.

  2. #2
    Cat without Hat CornedBee's Avatar
    Join Date
    Apr 2003
    Posts
    8,895
    1) Is it a multi-core system? If you're keeping both cores busy, your time counts double.

    2+3) Time spent sleeping or waiting for some external resource isn't counted. In particular, if the client MySQL library is waiting on a socket for a reply from the server, that time won't count.
    All the buzzt!
    CornedBee

    "There is not now, nor has there ever been, nor will there ever be, any programming language in which it is the least bit difficult to write bad code."
    - Flon's Law

  3. #3
    Registered User
    Join Date
    Oct 2007
    Posts
    32
    It's not answer your question, but anyway...
    Instead of adding timer's code to your program you can run
    time <your_program> [<args...>]

  4. #4
    Registered User
    Join Date
    Jul 2008
    Posts
    52
    It's a core duo system.

    I also tried the time function provided by the operating system. When the engine is MyISAM it seems to work much better than InnoDB and BDB engine. These are the weird results I'm getting:

    InnoDB
    35.007u 5.594s 1:41.46 40.0% 0+0k 0+0io 88pf+0w

    User time and System time don't add up close to the elapsed time which is like 1:41.46 minutes (only 40% of the CPU is used of this elapsed time), and there is no shared memory, no input/output, and only 88 page faults.. where is the rest of this time being spent X\

    I get very similar results for BDB but with about 2:40 minutes and with very little CPU usage like 16 %.

    Anyone has some suggestions on what could be happening?

    Thanks,

    Ed

  5. #5
    Kernel hacker
    Join Date
    Jul 2007
    Location
    Farncombe, Surrey, England
    Posts
    15,677
    The "rest" of the time is spent waiting, for example waiting for the disk to deliver data beign read or accepts data being written (or if your database is on a different machine, the time it takes to get across the network + the processing time of the SQL database).

    If the system isn't doing real work on your behalf, the time is not accounted on your process, so time spent waiting (but in your case, perhaps waiting for MySQL to say "Done that"), that time is just "wall-clock time" (or time elapsed), not CPU-time which is what time measures.

    --
    Mats
    Compilers can produce warnings - make the compiler programmers happy: Use them!
    Please don't PM me for help - and no, I don't do help over instant messengers.

  6. #6
    Registered User
    Join Date
    Jul 2008
    Posts
    52
    Why is it not reported as I/O though?

  7. #7
    Kernel hacker
    Join Date
    Jul 2007
    Location
    Farncombe, Surrey, England
    Posts
    15,677
    Quote Originally Posted by afflictedd2 View Post
    Why is it not reported as I/O though?
    Because the I/O isn't done in your process?

    --
    Mats
    Compilers can produce warnings - make the compiler programmers happy: Use them!
    Please don't PM me for help - and no, I don't do help over instant messengers.

  8. #8
    Registered User
    Join Date
    Jul 2008
    Posts
    52
    Hmmm okay.

    Thank you all for your help.

  9. #9
    Kernel hacker
    Join Date
    Jul 2007
    Location
    Farncombe, Surrey, England
    Posts
    15,677
    By the way, can you describe:
    1. What your benchmark is actually doing [in general terms at least - e.g. create 1000 records in a database].
    2. What the system setup is: For example, is you actual database on the same machine, or on a different server?

    I think, but I'm not 100% sure, that I/O only counts DISK I/O performed by the application [or technically, performed by the OS and the filesystem driver(s) on behalf of the application]. It does not count for example network I/O done by the application. I'm sure there is a way to measure network activity too (the name netstat comes to mind, but I haven't done that myself for a very long time, so I can't say if that's the right thing or not).

    --
    Mats
    Compilers can produce warnings - make the compiler programmers happy: Use them!
    Please don't PM me for help - and no, I don't do help over instant messengers.

Popular pages Recent additions subscribe to a feed

Similar Threads

  1. Times function for rational numbers
    By CaliJoe in forum C++ Programming
    Replies: 1
    Last Post: 05-01-2009, 04:09 PM
  2. Something about probablility
    By mike_g in forum A Brief History of Cprogramming.com
    Replies: 116
    Last Post: 03-13-2008, 05:33 PM
  3. arrays with elements
    By bradleyd in forum C Programming
    Replies: 5
    Last Post: 04-10-2007, 12:00 PM
  4. how can I re-sort a map
    By indigo0086 in forum C++ Programming
    Replies: 8
    Last Post: 06-01-2006, 06:21 AM
  5. Fastest STL container?
    By Shakti in forum C++ Programming
    Replies: 18
    Last Post: 02-17-2006, 02:07 AM