Rewrite time measurement code

Introduce and use a new Time class designed after
QTime, from Qt framework. Should be a more clear and
self documented code.

As an added benefit we now use 64 bits internally to get
millisecs from system time. This avoids to wrap around
to 0 every 2^32 milliseconds, which is 49.71 days.

No functional change.

Signed-off-by: Marco Costalba <mcostalba@gmail.com>

diff --git a/src/benchmark.cpp b/src/benchmark.cpp
index ba05ac7fb8af7561bfd425e8dc1f4cdcfe738f16..4735729add884116f27a981bf7736e55b1d2eb75 100644 (file)
--- a/src/benchmark.cpp
+++ b/src/benchmark.cpp
@@ -61,7 +61,6 @@ void benchmark(int argc, char* argv[]) {
 
   vector<string> fens;
   Search::LimitsType limits;
-  int time;
   int64_t nodes = 0;
 
   // Assign default values to missing arguments
@@ -104,7 +103,7 @@ void benchmark(int argc, char* argv[]) {
   else
       fens.assign(Defaults, Defaults + 16);
 
-  time = system_time();
+  Time time = Time::current_time();
 
   for (size_t i = 0; i < fens.size(); i++)
   {
@@ -125,10 +124,10 @@ void benchmark(int argc, char* argv[]) {
       }
   }
 
-  time = system_time() - time;
+  int e = time.elapsed();
 
   cerr << "\n==========================="
-       << "\nTotal time (ms) : " << time
+       << "\nTotal time (ms) : " << e
        << "\nNodes searched  : " << nodes
-       << "\nNodes/second    : " << int(nodes / (time / 1000.0)) << endl;
+       << "\nNodes/second    : " << int(nodes / (e / 1000.0)) << endl;
 }

diff --git a/src/book.cpp b/src/book.cpp
index 1dd5aa6dadb4675cec1be733b3fb5380cdaab8cf..1baafbbaabb618f87c2b425a09f3a844fcf3f182 100644 (file)
--- a/src/book.cpp
+++ b/src/book.cpp
@@ -342,7 +342,7 @@ namespace {
 
 Book::Book() : size(0) {
 
-  for (int i = abs(system_time() % 10000); i > 0; i--)
+  for (int i = Time::current_time().msec() % 10000; i > 0; i--)
       RKiss.rand<unsigned>(); // Make random number generation less deterministic
 }
 

diff --git a/src/misc.cpp b/src/misc.cpp
index a3b1b0324c8ee20357fb515294696d9b9befb240..99deedcc6a66f5e8d99086fa2baa2c4ccf59a2a9 100644 (file)
--- a/src/misc.cpp
+++ b/src/misc.cpp
@@ -19,15 +19,11 @@
 
 #if defined(_WIN32) || defined(_WIN64)
 
-#define _CRT_SECURE_NO_DEPRECATE
 #define NOMINMAX // disable macros min() and max()
 #include <windows.h>
-#include <sys/timeb.h>
 
 #else
 
-#  include <sys/time.h>
-#  include <sys/types.h>
 #  include <unistd.h>
 #  if defined(__hpux)
 #     include <sys/pstat.h>
@@ -77,12 +73,12 @@ const string engine_info(bool to_uci) {
       s << "Stockfish " << Tag
         << setfill('0') << " " << year.substr(2)
         << setw(2) << (1 + months.find(month) / 4)
-        << setw(2) << day << cpu64 << popcnt;
+        << setw(2) << day;
   }
   else
-      s << "Stockfish " << Version << cpu64 << popcnt;
+      s << "Stockfish " << Version;
 
-  s << (to_uci ? "\nid author ": " by ")
+  s << cpu64 << popcnt << (to_uci ? "\nid author ": " by ")
     << "Tord Romstad, Marco Costalba and Joona Kiiski";
 
   return s.str();
@@ -109,22 +105,6 @@ void dbg_print() {
 }
 
 
-/// system_time() returns the current system time, measured in milliseconds
-
-int system_time() {
-
-#if defined(_WIN32) || defined(_WIN64)
-  struct _timeb t;
-  _ftime(&t);
-  return int(t.time * 1000 + t.millitm);
-#else
-  struct timeval t;
-  gettimeofday(&t, NULL);
-  return t.tv_sec * 1000 + t.tv_usec / 1000;
-#endif
-}
-
-
 /// cpu_count() tries to detect the number of CPU cores
 
 int cpu_count() {

diff --git a/src/misc.h b/src/misc.h
index 0569e46826373ccafa96f8cdf64cab9053ffcfcb..cda0ef591192c9852e422447a3a3f57ef91bb1c6 100644 (file)
--- a/src/misc.h
+++ b/src/misc.h
@@ -27,7 +27,6 @@
 #include "types.h"
 
 extern const std::string engine_info(bool to_uci = false);
-extern int system_time();
 extern int cpu_count();
 extern void timed_wait(WaitCondition&, Lock&, int);
 extern void prefetch(char* addr);
@@ -42,9 +41,23 @@ extern Move move_from_uci(const Position& pos, const std::string& str);
 extern const std::string move_to_uci(Move m, bool chess960);
 extern const std::string move_to_san(Position& pos, Move m);
 
+
 struct Log : public std::ofstream {
   Log(const std::string& f = "log.txt") : std::ofstream(f.c_str(), std::ios::out | std::ios::app) {}
  ~Log() { if (is_open()) close(); }
 };
 
+
+class Time {
+public:
+  void restart() { system_time(&t); }
+  uint64_t msec() const { return time_to_msec(t); }
+  int elapsed() const { return int(current_time().msec() - time_to_msec(t)); }
+
+  static Time current_time() { Time t; t.restart(); return t; }
+
+private:
+  my_time_t t;
+};
+
 #endif // !defined(MISC_H_INCLUDED)

diff --git a/src/search.cpp b/src/search.cpp
index 40f14a509d2e0bc940023354897f15a9a0f14530..f71b54bc7d0fa6e22dc539b3b25f48d53c2ac666 100644 (file)
--- a/src/search.cpp
+++ b/src/search.cpp
@@ -117,6 +117,7 @@ namespace {
 
   size_t MultiPV, UCIMultiPV, PVIdx;
   TimeManager TimeMgr;
+  Time SearchTime;
   int BestMoveChanges;
   int SkillLevel;
   bool SkillLevelEnabled, Chess960;
@@ -138,7 +139,6 @@ namespace {
   bool connected_threat(const Position& pos, Move m, Move threat);
   Value refine_eval(const TTEntry* tte, Value defaultEval, int ply);
   Move do_skill_level();
-  int elapsed_time(bool reset = false);
   string score_to_uci(Value v, Value alpha = -VALUE_INFINITE, Value beta = VALUE_INFINITE);
   void pv_info_to_log(Position& pos, int depth, Value score, int time, Move pv[]);
   void pv_info_to_uci(const Position& pos, int depth, Value alpha, Value beta);
@@ -251,7 +251,7 @@ void Search::think() {
 
   Position& pos = RootPosition;
   Chess960 = pos.is_chess960();
-  elapsed_time(true);
+  SearchTime.restart();
   TimeMgr.init(Limits, pos.startpos_ply_counter());
   TT.new_search();
   H.clear();
@@ -325,7 +325,7 @@ void Search::think() {
 
   if (Options["Use Search Log"])
   {
-      int e = elapsed_time();
+      int e = SearchTime.elapsed();
 
       Log log(Options["Search Log Filename"]);
       log << "Nodes: "          << pos.nodes_searched()
@@ -433,7 +433,7 @@ namespace {
 
                 // Send full PV info to GUI if we are going to leave the loop or
                 // if we have a fail high/low and we are deep in the search.
-                if ((bestValue > alpha && bestValue < beta) || elapsed_time() > 2000)
+                if ((bestValue > alpha && bestValue < beta) || SearchTime.elapsed() > 2000)
                     pv_info_to_uci(pos, depth, alpha, beta);
 
                 // In case of failing high/low increase aspiration window and
@@ -464,7 +464,7 @@ namespace {
             skillBest = do_skill_level();
 
         if (!Signals.stop && Options["Use Search Log"])
-             pv_info_to_log(pos, depth, bestValue, elapsed_time(), &RootMoves[0].pv[0]);
+             pv_info_to_log(pos, depth, bestValue, SearchTime.elapsed(), &RootMoves[0].pv[0]);
 
         // Filter out startup noise when monitoring best move stability
         if (depth > 2 && BestMoveChanges)
@@ -482,14 +482,14 @@ namespace {
             // Stop search if most of available time is already consumed. We
             // probably don't have enough time to search the first move at the
             // next iteration anyway.
-            if (elapsed_time() > (TimeMgr.available_time() * 62) / 100)
+            if (SearchTime.elapsed() > (TimeMgr.available_time() * 62) / 100)
                 stop = true;
 
             // Stop search early if one move seems to be much better than others
             if (    depth >= 12
                 && !stop
                 && (   (bestMoveNeverChanged &&  pos.captured_piece_type())
-                    || elapsed_time() > (TimeMgr.available_time() * 40) / 100))
+                    || SearchTime.elapsed() > (TimeMgr.available_time() * 40) / 100))
             {
                 Value rBeta = bestValue - EasyMoveMargin;
                 (ss+1)->excludedMove = RootMoves[0].pv[0];
@@ -858,7 +858,7 @@ split_point_start: // At split points actual search starts from here
       {
           Signals.firstRootMove = (moveCount == 1);
 
-          if (pos.thread() == 0 && elapsed_time() > 2000)
+          if (pos.thread() == 0 && SearchTime.elapsed() > 2000)
               cout << "info depth " << depth / ONE_PLY
                    << " currmove " << move_to_uci(move, Chess960)
                    << " currmovenumber " << moveCount + PVIdx << endl;
@@ -1524,20 +1524,6 @@ split_point_start: // At split points actual search starts from here
   }
 
 
-  // current_search_time() returns the number of milliseconds which have passed
-  // since the beginning of the current search.
-
-  int elapsed_time(bool reset) {
-
-    static int searchStartTime;
-
-    if (reset)
-        searchStartTime = system_time();
-
-    return system_time() - searchStartTime;
-  }
-
-
   // score_to_uci() converts a value to a string suitable for use with the UCI
   // protocol specifications:
   //
@@ -1566,7 +1552,7 @@ split_point_start: // At split points actual search starts from here
 
   void pv_info_to_uci(const Position& pos, int depth, Value alpha, Value beta) {
 
-    int t = elapsed_time();
+    int t = SearchTime.elapsed();
     int selDepth = 0;
 
     for (int i = 0; i < Threads.size(); i++)
@@ -1698,7 +1684,7 @@ split_point_start: // At split points actual search starts from here
     static RKISS rk;
 
     // PRNG sequence should be not deterministic
-    for (int i = abs(system_time() % 50); i > 0; i--)
+    for (int i = Time::current_time().msec() % 50; i > 0; i--)
         rk.rand<unsigned>();
 
     // RootMoves are already sorted by score in descending order
@@ -1902,18 +1888,18 @@ void Thread::idle_loop(SplitPoint* sp_master) {
 
 void check_time() {
 
-  static int lastInfoTime;
-  int e = elapsed_time();
+  static Time lastInfoTime = Time::current_time();
 
-  if (system_time() - lastInfoTime >= 1000 || !lastInfoTime)
+  if (lastInfoTime.elapsed() >= 1000)
   {
-      lastInfoTime = system_time();
+      lastInfoTime.restart();
       dbg_print();
   }
 
   if (Limits.ponder)
       return;
 
+  int e = SearchTime.elapsed();
   bool stillAtFirstMove =    Signals.firstRootMove
                          && !Signals.failedLowAtRoot
                          &&  e > TimeMgr.available_time();

diff --git a/src/types.h b/src/types.h
index 6c9c425ea743659fd591a5d32c207276d8f2835a..d907006ca4afb19fe7af338f48b5f24b1152881e 100644 (file)
--- a/src/types.h
+++ b/src/types.h
@@ -44,6 +44,7 @@
 #pragma warning(disable: 4127) // Conditional expression is constant
 #pragma warning(disable: 4146) // Unary minus operator applied to unsigned type
 #pragma warning(disable: 4800) // Forcing value to bool 'true' or 'false'
+#pragma warning(disable: 4996) // Function _ftime() may be unsafe
 
 // MSVC does not support <inttypes.h>
 typedef   signed __int8    int8_t;
@@ -59,6 +60,20 @@ typedef unsigned __int64 uint64_t;
 #  include <inttypes.h>
 #endif
 
+#if defined(_WIN32) || defined(_WIN64)
+#  include <sys/timeb.h>
+typedef _timeb my_time_t;
+
+inline void system_time(my_time_t* t) { _ftime(t); }
+inline uint64_t time_to_msec(const my_time_t& t) { return t.time * 1000 + t.millitm; }
+#else
+#  include <sys/time.h>
+typedef timeval my_time_t;
+
+inline void system_time(my_time_t* t) { gettimeofday(t, NULL); }
+inline uint64_t time_to_msec(const my_time_t& t) { return t.tv_sec * 1000 + t.tv_usec / 1000; }
+#endif
+
 #if defined(_WIN64)
 #  include <intrin.h> // MSVC popcnt and bsfq instrinsics
 #  define IS_64BIT

diff --git a/src/uci.cpp b/src/uci.cpp
index c44c23fa12af2b505a72f762f4b7a979daaa53f3..3a42ac5fda950e67c53755250dc0a12559602570 100644 (file)
--- a/src/uci.cpp
+++ b/src/uci.cpp
@@ -243,19 +243,19 @@ namespace {
 
   void perft(Position& pos, istringstream& is) {
 
-    int depth, time;
+    int depth;
 
     if (!(is >> depth))
         return;
 
-    time = system_time();
+    Time time = Time::current_time();
 
     int64_t n = Search::perft(pos, depth * ONE_PLY);
 
-    time = system_time() - time;
+    int e = time.elapsed();
 
     std::cout << "\nNodes " << n
-              << "\nTime (ms) " << time
-              << "\nNodes/second " << int(n / (time / 1000.0)) << std::endl;
+              << "\nTime (ms) " << e
+              << "\nNodes/second " << int(n / (e / 1000.0)) << std::endl;
   }
 }