Merge pull request #639 from kmod/tick_timers2

change timers back to ticks

src/core/stats.cpp

@@ -138,17 +138,41 @@ 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_timer_")) {
+            if (startswith(pairs[i].first, "us_") || startswith(pairs[i].first, "_init_us_")) {
                 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;
-    gettimeofday(&start_time, NULL);
+    start_time = getCPUTicks();
     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 Timer::end(uint64_t* ended_at) {
     if (!ended) {
-        timeval end;
-        gettimeofday(&end, NULL);
-        long us = 1000000L * (end.tv_sec - start_time.tv_sec) + (end.tv_usec - start_time.tv_usec);
-
+        uint64_t end = getCPUTicks();
+        uint64_t duration = end - start_time;
         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,9 +78,10 @@ uint64_t Timer::end() {
                 fflush(stdout);
             }
         }
+        if (ended_at)
+            *ended_at = end;
         ended = true;
-
-        return us;
+        return duration;
     }
     return -1;
 }

src/core/util.h

@@ -36,7 +36,7 @@ inline uint64_t getCPUTicks() {
 class Timer {
 private:
     static int level;
-    timeval start_time;
+    uint64_t start_time;
     const char* desc;
     long min_usec;
     bool ended;
@@ -55,12 +55,14 @@ 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 end(uint64_t* ended_at = NULL);
     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;
 
-    uint64_t main_time_started_at = getCPUTicks();
+    Timer main_time;
     int rtncode = 0;
     {
 #if STAT_TIMERS
         StatTimer timer(Stats::getStatCounter("us_timer_main_toplevel"), 0, true);
-        timer.pushTopLevel(main_time_started_at);
+        timer.pushTopLevel(main_time.getStartTime());
 #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 = getCPUTicks();
-        uint64_t main_time_duration = main_time_ended_at - main_time_started_at;
+        uint64_t main_time_ended_at;
+        uint64_t main_time_duration = main_time.end(&main_time_ended_at);
         static StatCounter mt("ticks_in_main");
         mt.log(main_time_duration);