Merge pull request #608 from rudi-c/timer_fix

Revert to using gettimeofday to have measurements in us instead of ticks.

src/core/stats.cpp

@@ -138,41 +138,17 @@ void Stats::dump(bool includeZeros) {
 
     std::sort(pairs.begin(), pairs.end());
 
-    uint64_t ticks_in_main = 0;
-    uint64_t accumulated_stat_timer_ticks = 0;
     for (int i = 0; i < pairs.size(); i++) {
         uint64_t count = *pairs[i].second;
         if (includeZeros || count > 0) {
-            if (startswith(pairs[i].first, "us_") || startswith(pairs[i].first, "_init_us_")) {
+            if (startswith(pairs[i].first, "us_timer_")) {
                 fprintf(stderr, "%s: %lu\n", pairs[i].first.c_str(), (uint64_t)(count / cycles_per_us));
-
-            } else
+            } else {
                 fprintf(stderr, "%s: %lu\n", pairs[i].first.c_str(), count);
-
-            if (startswith(pairs[i].first, "us_timer_"))
-                accumulated_stat_timer_ticks += count;
-
-            if (pairs[i].first == "ticks_in_main")
-                ticks_in_main = count;
+            }
         }
     }
 
-    if (includeZeros || accumulated_stat_timer_ticks > 0)
-        fprintf(stderr, "ticks_all_timers: %lu\n", accumulated_stat_timer_ticks);
-
-#if 0
-    // I want to enable this, but am leaving it disabled for the time
-    // being because it causes test failures due to:
-    //
-    // 1) some tests exit from main from inside catch blocks, without
-    //    going through the logic to stop the timers.
-    // 2) some tests create multiple threads which causes problems
-    //    with our non-per thread stat timers.
-
-    if (ticks_in_main && ticks_in_main != accumulated_stat_timer_ticks) {
-        fprintf(stderr, "WARNING: accumulated stat timer ticks != ticks in main - don't trust timer output.");
-    }
-#endif
     fprintf(stderr, "(End of stats)\n");
 }
 

src/core/util.cpp

@@ -44,7 +44,7 @@ void Timer::restart(const char* newdesc) {
     assert(ended);
 
     desc = newdesc;
-    start_time = getCPUTicks();
+    gettimeofday(&start_time, NULL);
     Timer::level++;
     ended = false;
 }
@@ -54,14 +54,14 @@ void Timer::restart(const char* newdesc, long new_min_usec) {
     restart(newdesc);
 }
 
-uint64_t Timer::end(uint64_t* ended_at) {
+uint64_t Timer::end() {
     if (!ended) {
-        uint64_t end = getCPUTicks();
-        uint64_t duration = end - start_time;
+        timeval end;
+        gettimeofday(&end, NULL);
+        long us = 1000000L * (end.tv_sec - start_time.tv_sec) + (end.tv_usec - start_time.tv_usec);
+
         Timer::level--;
         if (VERBOSITY("time") >= 2 && desc) {
-            uint64_t us = (uint64_t)(duration / Stats::estimateCPUFreq());
-
             if (us > min_usec) {
                 for (int i = 0; i < Timer::level; i++) {
                     putchar(' ');
@@ -78,10 +78,9 @@ uint64_t Timer::end(uint64_t* ended_at) {
                 fflush(stdout);
             }
         }
-        if (ended_at)
-            *ended_at = end;
         ended = true;
-        return duration;
+
+        return us;
     }
     return -1;
 }

src/core/util.h

@@ -36,7 +36,7 @@ inline uint64_t getCPUTicks() {
 class Timer {
 private:
     static int level;
-    uint64_t start_time;
+    timeval start_time;
     const char* desc;
     long min_usec;
     bool ended;
@@ -55,14 +55,12 @@ public:
 
     // returns the duration.  if @ended_at is non-null, it's filled in
     // with the tick the timer stopped at.
-    uint64_t end(uint64_t* ended_at = NULL);
+    uint64_t end();
     uint64_t split(const char* newdesc = NULL) {
         uint64_t rtn = end();
         restart(newdesc);
         return rtn;
     }
-
-    uint64_t getStartTime() const { return start_time; }
 };
 
 #else // DISABLE_TIMERS

src/jit.cpp

@@ -265,12 +265,12 @@ static int main(int argc, char** argv) {
 
     timespec before_ts, after_ts;
 
-    Timer main_time;
+    uint64_t main_time_started_at = getCPUTicks();
     int rtncode = 0;
     {
 #if STAT_TIMERS
         StatTimer timer(Stats::getStatCounter("us_timer_main_toplevel"), 0, true);
-        timer.pushTopLevel(main_time.getStartTime());
+        timer.pushTopLevel(main_time_started_at);
 #endif
 
         int code;
@@ -506,8 +506,8 @@ static int main(int argc, char** argv) {
         _t.split("finishing up");
 
 #if STAT_TIMERS
-        uint64_t main_time_ended_at;
-        uint64_t main_time_duration = main_time.end(&main_time_ended_at);
+        uint64_t main_time_ended_at = getCPUTicks();
+        uint64_t main_time_duration = main_time_ended_at - main_time_started_at;
         static StatCounter mt("ticks_in_main");
         mt.log(main_time_duration);