Change mert/Timer.

- Add a high resolution timing function to measure the
  wall-clock time by gettimeofday().

- Now the Timer class use getrusage() to measure the elapsed
  CPU time as KenLM does.

- Revive Timer::restart().

- Add Timer::ToString() for reporting the detail statistics
  as well as for debugging.

- Add a simple unit test for Timer.

mert/Jamfile

@@ -44,6 +44,7 @@ exe pro : pro.cpp mert_lib ..//boost_program_options ;
 alias programs : mert extractor evaluator pro ;
 
 unit-test data_test : DataTest.cpp mert_lib ..//boost_unit_test_framework ;
+unit-test timer_test : TimerTest.cpp mert_lib ..//boost_unit_test_framework ;
 unit-test util_test : UtilTest.cpp mert_lib ..//boost_unit_test_framework ;
 
 install legacy : programs : <location>. ;

mert/Timer.cpp

@@ -1,16 +1,63 @@
 #include "Timer.h"
 #include "Util.h"
+#include <cstdio>
 
-double Timer::elapsed_time() const
-{
-  time_t now;
-  time(&now);
-  return difftime(now, m_start_time);
+#if !defined(_WIN32) && !defined(_WIN64)
+#include <sys/resource.h>
+#include <sys/time.h>
+#endif
+
+namespace {
+
+#if !defined(_WIN32) && !defined(_WIN64)
+uint64_t GetMicroSeconds(const struct timeval& tv) {
+  return static_cast<uint64_t>(tv.tv_sec) * 1000000 + tv.tv_usec;
 }
 
-double Timer::get_elapsed_time() const
-{
-  return elapsed_time();
+uint64_t GetTimeOfDayMicroSeconds() {
+  struct timeval tv;
+  gettimeofday(&tv, NULL);
+  return static_cast<uint64_t>(tv.tv_sec) * 1000000 + tv.tv_usec;
+}
+#endif
+
+} // namespace
+
+Timer::CPUTime Timer::GetCPUTimeMicroSeconds() const {
+#if !defined(_WIN32) && !defined(_WIN64)
+  struct rusage usage;
+  if (getrusage(RUSAGE_SELF, &usage)) {
+    TRACE_ERR("Error occurred: getrusage().\n");
+    exit(1);
+  }
+  CPUTime t;
+  t.user_time = GetMicroSeconds(usage.ru_utime);
+  t.sys_time = GetMicroSeconds(usage.ru_stime);
+  return t;
+#else  // Windows
+  // Not implemented yet.
+  // TODO: implement the Windows version using native APIs.
+  CPUTime t;
+  return t;
+#endif
+}
+
+double Timer::get_elapsed_cpu_time() const {
+  return static_cast<double>(get_elapsed_cpu_time_microseconds()) * 1e-6;
+}
+
+uint64_t Timer::get_elapsed_cpu_time_microseconds() const {
+  const CPUTime e = GetCPUTimeMicroSeconds();
+  return (e.user_time - m_start_time.user_time) +
+      (e.sys_time - m_start_time.sys_time);
+}
+
+double Timer::get_elapsed_wall_time() const {
+  return static_cast<double>(get_elapsed_wall_time_microseconds()) * 1e-6;
+}
+
+uint64_t Timer::get_elapsed_wall_time_microseconds() const {
+  return GetTimeOfDayMicroSeconds() - m_wall;
 }
 
 void Timer::start(const char* msg)
@@ -19,14 +66,41 @@ void Timer::start(const char* msg)
   if (msg) TRACE_ERR( msg << std::endl);
   if (m_is_running) return;
   m_is_running = true;
+  m_wall = GetTimeOfDayMicroSeconds();
+  m_start_time = GetCPUTimeMicroSeconds();
+}
 
-  // Set the start time;
-  time(&m_start_time);
+void Timer::restart(const char* msg)
+{
+  if (msg) {
+    TRACE_ERR(msg << std::endl);
+  }
+  m_wall = GetTimeOfDayMicroSeconds();
+  m_start_time = GetCPUTimeMicroSeconds();
 }
 
 void Timer::check(const char* msg)
 {
   // Print an optional message, something like "Checking timer t";
   if (msg) TRACE_ERR( msg << " : ");
-  TRACE_ERR( "[" << (m_is_running ? elapsed_time() : 0) << "] seconds\n");
+
+  if (m_is_running) {
+    TRACE_ERR("[Wall " << get_elapsed_wall_time()
+              << " CPU " << get_elapsed_cpu_time() << "] seconds.\n");
+  } else {
+    TRACE_ERR("WARNING: the timer is not running.\n");
+  }
+}
+
+std::string Timer::ToString() const {
+  std::string res;
+  char tmp[64];
+  const double wall = get_elapsed_wall_time();
+  const CPUTime e = GetCPUTimeMicroSeconds();
+  const double utime = (e.user_time - m_start_time.user_time) * 1e-6;
+  const double stime = (e.sys_time - m_start_time.sys_time) * 1e-6;
+  std::snprintf(tmp, sizeof(tmp), "wall %f user %f sec. sys %f sec. total %f sec.",
+                wall, utime, stime, utime + stime);
+  res.append(tmp);
+  return res;
 }

mert/Timer.h

@@ -1,32 +1,38 @@
 #ifndef MERT_TIMER_H_
 #define MERT_TIMER_H_
 
-#include <ctime>
-#include <iostream>
-#include <iomanip>
+#include <ostream>
+#include <string>
+#include <stdint.h>
 
 class Timer
 {
  private:
-  bool m_is_running;
-  time_t m_start_time;
+  // Time values are stored in microseconds.
+  struct CPUTime {
+    uint64_t user_time;                 // user CPU time
+    uint64_t sys_time;                  // system CPU time
 
-  /**
-   * Return the total time that the timer has been in the "running"
-   * state since it was first "started" or last "restarted".  For
-   * "short" time periods (less than an hour), the actual cpu time
-   * used is reported instead of the elapsed time.
-   * TODO in seconds?
-   */
-  double elapsed_time() const;
+    CPUTime() : user_time(0), sys_time(0) { }
+  };
+
+  CPUTime GetCPUTimeMicroSeconds() const;
+
+  bool m_is_running;
+  uint64_t m_wall;                      // wall-clock time in microseconds
+  CPUTime m_start_time;
 
  public:
   /**
    * 'm_is_running' is initially false. A timer needs to be explicitly started
    * using 'start'.
    */
-  Timer() : m_is_running(false), m_start_time(0) { }
-  ~Timer() { }
+  Timer()
+      : m_is_running(false),
+        m_wall(0),
+        m_start_time() {}
+
+  ~Timer() {}
 
   /**
    * Start a timer.  If it is already running, let it continue running.
@@ -34,6 +40,12 @@ class Timer
    */
   void start(const char* msg = 0);
 
+  /**
+   * Restart the timer iff the timer is already running.
+   * if the timer is not running, just start the timer.
+   */
+  void restart(const char* msg = 0);
+
   /**
    * Print out an optional message followed by the current timer timing.
    */
@@ -44,13 +56,32 @@ class Timer
   bool is_running() const { return m_is_running; }
 
   /**
-   * Return the total time that the timer has been in the "running"
-   * state since it was first "started" or last "restarted".  For
-   * "short" time periods (less than an hour), the actual cpu time
+   * Return the total time in seconds that the timer has been in the
+   * "running" state since it was first "started" or last "restarted".
+   * For "short" time periods (less than an hour), the actual cpu time
    * used is reported instead of the elapsed time.
-   * This function is the public version of elapsed_time()
    */
-  double get_elapsed_time() const;
+  double get_elapsed_cpu_time() const;
+
+  /**
+   * Return the total time in microseconds.
+   */
+  uint64_t get_elapsed_cpu_time_microseconds() const;
+
+  /**
+   * Get elapsed wall-clock time in seconds.
+   */
+  double get_elapsed_wall_time() const;
+
+  /**
+   * Get elapsed wall-clock time in microseconds.
+   */
+  uint64_t get_elapsed_wall_time_microseconds() const;
+
+  /**
+   * Return a string that has the user CPU time, system time, and total time.
+   */
+  std::string ToString() const;
 };
 
 /**
@@ -58,9 +89,12 @@ class Timer
  * for an ostream 'os' and a timer 't'.  For example, "cout << t" will
  * print out the total amount of time 't' has been "running".
  */
-inline std::ostream& operator<<(std::ostream& os, const Timer& t)
-{
-  os << (t.is_running() ? t.get_elapsed_time() : 0);
+inline std::ostream& operator<<(std::ostream& os, const Timer& t) {
+  if (t.is_running()) {
+    os << t.ToString();
+  } else {
+    os << "timer is not running.";
+  }
   return os;
 }
 

mert/TimerTest.cpp

@@ -0,0 +1,27 @@
+#include "Timer.h"
+
+#define BOOST_TEST_MODULE TimerTest
+#include <boost/test/unit_test.hpp>
+
+#include <string>
+#include <iostream>
+
+BOOST_AUTO_TEST_CASE(timer_basic_test) {
+  Timer timer;
+  timer.start();
+  BOOST_REQUIRE(timer.is_running());
+  BOOST_REQUIRE(timer.get_elapsed_cpu_time() > 0.0);
+  BOOST_REQUIRE(timer.get_elapsed_cpu_time_microseconds() > 0);
+  BOOST_REQUIRE(timer.get_elapsed_wall_time() > 0.0);
+  BOOST_REQUIRE(timer.get_elapsed_wall_time_microseconds() > 0);
+
+  timer.restart();
+  BOOST_REQUIRE(timer.is_running());
+  BOOST_REQUIRE(timer.get_elapsed_cpu_time() > 0.0);
+  BOOST_REQUIRE(timer.get_elapsed_cpu_time_microseconds() > 0);
+  BOOST_REQUIRE(timer.get_elapsed_wall_time() > 0.0);
+  BOOST_REQUIRE(timer.get_elapsed_wall_time_microseconds() > 0);
+
+  const std::string s = timer.ToString();
+  BOOST_REQUIRE(!s.empty());
+}

mert/Util.cpp

@@ -84,5 +84,5 @@ void PrintUserTime(const std::string &message)
 
 double GetUserTime()
 {
-  return g_timer.get_elapsed_time();
+  return g_timer.get_elapsed_cpu_time();
 }