Clean up the StatTimer logic

Main change is separating the representation of the timer stack (StatTimer) from
the manipulation of it (ScopedStatTimer).  This makes it easier to keep the different
use cases (top level timers vs non-top-level) separate without having the individual
functions check whether they think they are a top-level timer or not.

src/core/stats.cpp

@@ -26,15 +26,28 @@ namespace pyston {
 
 __thread StatTimer* StatTimer::stack;
 
-StatTimer* StatTimer::swapStack(StatTimer* s, uint64_t at_time) {
+StatTimer* StatTimer::swapStack(StatTimer* s) {
+    uint64_t at_time = getCPUTicks();
+
+    assert(stack);
+    assert(s);
     StatTimer* prev_stack = stack;
-    if (stack) {
-        stack->pause(at_time);
-    }
+    stack->pause(at_time);
     stack = s;
-    if (stack) {
-        stack->resume(at_time);
-    }
+    stack->resume(at_time);
+    assert(prev_stack);
+    return prev_stack;
+}
+
+StatTimer* StatTimer::createStack(StatTimer& timer) {
+    uint64_t at_time = getCPUTicks();
+
+    assert(stack);
+    StatTimer* prev_stack = stack;
+    stack->pause(at_time);
+    stack = NULL;
+
+    timer.pushTopLevel(at_time);
     return prev_stack;
 }
 #endif

src/core/stats.h

@@ -34,13 +34,9 @@ namespace pyston {
 #if STAT_TIMERS
 #define STAT_TIMER(id, name)                                                                                           \
     static uint64_t* _stcounter##id = Stats::getStatCounter(name);                                                     \
-    StatTimer _st##id(_stcounter##id)
-#define STAT_TIMER2(id, name, at_time)                                                                                 \
-    static uint64_t* _stcounter##id = Stats::getStatCounter(name);                                                     \
-    StatTimer _st##id(_stcounter##id, at_time)
+    ScopedStatTimer _st##id(_stcounter##id)
 #else
-#define STAT_TIMER(id, name) StatTimer _st##id(0);
-#define STAT_TIMER2(id, name, at_time) StatTimer _st##id(0);
+#define STAT_TIMER(id, name)
 #endif
 
 #define STAT_TIMER_NAME(id) _st##id
@@ -117,60 +113,56 @@ private:
     // the start time of the current active segment (0 == paused)
     uint64_t _start_time;
 
-    uint64_t _last_pause_time;
-
     StatTimer* _prev;
 
     uint64_t* _statcounter;
 
 public:
-    StatTimer(uint64_t* counter, bool push = true) {
+    StatTimer(uint64_t* counter) : _statcounter(counter) {}
+
+    void pushNonTopLevel() {
         uint64_t at_time = getCPUTicks();
+#ifndef NDEBUG
         _start_time = 0;
-        _statcounter = counter;
-
-        if (!push) {
-            _prev = NULL;
-            return;
-        }
+#endif
 
+        assert(stack);
         _prev = stack;
         stack = this;
-        if (_prev) {
-            _prev->pause(at_time);
-        }
+        _prev->pause(at_time);
         resume(at_time);
     }
 
-    StatTimer(uint64_t* counter, uint64_t at_time) {
+    void popNonTopLevel() {
+        assert(stack == this);
+
+        uint64_t at_time;
+        assert(!isPaused());
+        at_time = getCPUTicks();
+        pause(at_time);
+
+        assert(_prev);
+        stack = _prev;
+        stack->resume(at_time);
+    }
+
+    void pushTopLevel(uint64_t at_time) {
+#ifndef NDEBUG
         _start_time = 0;
-        _statcounter = counter;
+#endif
+        assert(!stack);
         _prev = stack;
         stack = this;
-        if (_prev) {
-            _prev->pause(at_time);
-        }
         resume(at_time);
     }
 
-    ~StatTimer() {
-        assert(stack == this);
-
-        uint64_t at_time;
-        if (!isPaused()) {
-            at_time = getCPUTicks();
-            pause(at_time);
-        } else {
-            // fprintf (stderr, "WARNING: timer was paused.\n");
-            at_time = _last_pause_time;
-        }
-
+    void popTopLevel(uint64_t at_time) {
+        assert(!_prev);
         stack = _prev;
-        if (stack) {
-            stack->resume(at_time);
-        }
+        pause(at_time);
     }
 
+private:
     void pause(uint64_t at_time) {
         assert(!isPaused());
         assert(at_time > _start_time);
@@ -179,26 +171,35 @@ public:
         Stats::log(_statcounter, _duration);
 
         _start_time = 0;
-        _last_pause_time = at_time;
-        // fprintf (stderr, "paused  %d at %lu\n", _statid, at_time);
     }
+
     void resume(uint64_t at_time) {
         assert(isPaused());
         _start_time = at_time;
-        // fprintf (stderr, "resumed %d at %lu\n", _statid, at_time);
     }
 
+public:
+#ifndef NDEBUG
     bool isPaused() const { return _start_time == 0; }
+#endif
 
-    static StatTimer* getStack() { return stack; }
+    // Creates a new stattimer stack from an unstarted top-level timer
+    static StatTimer* createStack(StatTimer& timer);
+    static StatTimer* swapStack(StatTimer* s);
 
-    static StatTimer* swapStack(StatTimer* s, uint64_t at_time);
+    static void assertActive() { ASSERT(stack && !stack->isPaused(), ""); }
+};
+class ScopedStatTimer {
+private:
+    StatTimer timer;
 
-    static void assertActive() { RELEASE_ASSERT(stack && !stack->isPaused(), ""); }
+public:
+    ScopedStatTimer(uint64_t* counter) : timer(counter) { timer.pushNonTopLevel(); }
+    ~ScopedStatTimer() { timer.popNonTopLevel(); }
 };
 #else
 struct StatTimer {
-    StatTimer(int statid, bool push = true) {}
+    StatTimer(int statid) {}
     StatTimer(int statid, uint64_t at_time) {}
     ~StatTimer() {}
     bool isPaused() const { return false; }
@@ -206,8 +207,8 @@ struct StatTimer {
     void pause(uint64_t at_time) {}
     void resume(uint64_t at_time) {}
 
-    static StatTimer* getStack() { return NULL; }
-    static StatTimer* swapStack(StatTimer* s, uint64_t at_time) { return NULL; }
+    static StatTimer* createStack(StatTimer& timer);
+    static StatTimer* swapStack(StatTimer* s);
     static void assertActive() {}
 };
 #endif

src/jit.cpp

@@ -268,7 +268,10 @@ static int main(int argc, char** argv) {
     Timer main_time;
     int rtncode = 0;
     {
-        STAT_TIMER2(t0, "us_timer_main_toplevel", main_time.getStartTime());
+#if STAT_TIMERS
+        StatTimer timer(Stats::getStatCounter("us_timer_main_toplevel"));
+        timer.pushTopLevel(main_time.getStartTime());
+#endif
 
         int code;
         const char* command = NULL;
@@ -502,11 +505,14 @@ static int main(int argc, char** argv) {
         joinRuntime();
         _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);
         static StatCounter mt("ticks_in_main");
         mt.log(main_time_duration);
-        STAT_TIMER_NAME(t0).pause(main_time_ended_at);
+
+        timer.popTopLevel(main_time_ended_at);
+#endif
     }
     Stats::dump(true);
 

src/runtime/builtin_modules/thread.cpp

@@ -63,11 +63,23 @@ static void* thread_start(Box* target, Box* varargs, Box* kwargs) {
     assert(target);
     assert(varargs);
 
+#if STAT_TIMERS
+    // TODO: maybe we should just not log anything for threads...
+    static uint64_t* timer_counter = Stats::getStatCounter("us_timer_thread_start");
+    StatTimer timer(timer_counter);
+    timer.pushTopLevel(getCPUTicks());
+#endif
+
     try {
         runtimeCall(target, ArgPassSpec(0, 0, true, kwargs != NULL), varargs, kwargs, NULL, NULL, NULL);
     } catch (ExcInfo e) {
         e.printExcAndTraceback();
     }
+
+#if STAT_TIMERS
+    timer.popTopLevel(getCPUTicks());
+#endif
+
     return NULL;
 }
 

src/runtime/generator.cpp

@@ -87,8 +87,6 @@ Context* getReturnContextForGeneratorFrame(void* frame_addr) {
 
 void generatorEntry(BoxedGenerator* g) {
     {
-        STAT_TIMER2(t0, "us_timer_generator_toplevel", g->timer_time);
-
         assert(g->cls == generator_cls);
         assert(g->function->cls == function_cls);
 
@@ -110,11 +108,6 @@ void generatorEntry(BoxedGenerator* g) {
         // we returned from the body of the generator. next/send/throw will notify the caller
         g->entryExited = true;
         threading::popGenerator();
-
-#if STAT_TIMERS
-        g->timer_time = getCPUTicks(); // store off the timer that our caller (in g->returnContext) will resume at
-        STAT_TIMER_NAME(t0).pause(g->timer_time);
-#endif
     }
     swapContext(&g->context, g->returnContext, 0);
 }
@@ -138,17 +131,20 @@ static void generatorSendInternal(BoxedGenerator* self, Box* v) {
     self->running = true;
 
 #if STAT_TIMERS
-    // store off the time that the generator will use to initialize its toplevel timer
-    self->timer_time = getCPUTicks();
-    StatTimer* current_timers = StatTimer::swapStack(self->statTimers, self->timer_time);
+    if (!self->prev_stack)
+        self->prev_stack = StatTimer::createStack(self->my_timer);
+    else
+        self->prev_stack = StatTimer::swapStack(self->prev_stack);
 #endif
 
     swapContext(&self->returnContext, self->context, (intptr_t)self);
 
 #if STAT_TIMERS
-    // if the generator exited we use the time that generatorEntry stored in self->timer_time (the same time it paused
-    // its timer at).
-    self->statTimers = StatTimer::swapStack(current_timers, self->entryExited ? self->timer_time : getCPUTicks());
+    self->prev_stack = StatTimer::swapStack(self->prev_stack);
+    if (self->entryExited) {
+        assert(self->prev_stack == &self->my_timer);
+        assert(self->my_timer.isPaused());
+    }
 #endif
 
     self->running = false;
@@ -282,7 +278,9 @@ extern "C" BoxedGenerator* createGenerator(BoxedFunctionBase* function, Box* arg
     return new BoxedGenerator(function, arg1, arg2, arg3, args);
 }
 
-
+#if STAT_TIMERS
+static uint64_t* generator_timer_counter = Stats::getStatCounter("us_timer_generator_toplevel");
+#endif
 extern "C" BoxedGenerator::BoxedGenerator(BoxedFunctionBase* function, Box* arg1, Box* arg2, Box* arg3, Box** args)
     : function(function),
       arg1(arg1),
@@ -294,7 +292,13 @@ extern "C" BoxedGenerator::BoxedGenerator(BoxedFunctionBase* function, Box* arg1
       returnValue(nullptr),
       exception(nullptr, nullptr, nullptr),
       context(nullptr),
-      returnContext(nullptr) {
+      returnContext(nullptr)
+#if STAT_TIMERS
+      ,
+      prev_stack(NULL),
+      my_timer(generator_timer_counter)
+#endif
+{
 
     int numArgs = function->f->num_args;
     if (numArgs > 3) {

src/runtime/objmodel.cpp

@@ -130,7 +130,7 @@ static uint64_t* pylt_timer_counter = Stats::getStatCounter("us_timer_PyLt");
 #endif
 size_t PyHasher::operator()(Box* b) const {
 #if STAT_TIMERS
-    StatTimer _st(pyhasher_timer_counter);
+    ScopedStatTimer _st(pyhasher_timer_counter);
 #endif
     if (b->cls == str_cls) {
         StringHash<char> H;
@@ -143,7 +143,7 @@ size_t PyHasher::operator()(Box* b) const {
 
 bool PyEq::operator()(Box* lhs, Box* rhs) const {
 #if STAT_TIMERS
-    StatTimer _st(pyeq_timer_counter);
+    ScopedStatTimer _st(pyeq_timer_counter);
 #endif
 
     int r = PyObject_RichCompareBool(lhs, rhs, Py_EQ);
@@ -154,7 +154,7 @@ bool PyEq::operator()(Box* lhs, Box* rhs) const {
 
 bool PyLt::operator()(Box* lhs, Box* rhs) const {
 #if STAT_TIMERS
-    StatTimer _st(pylt_timer_counter);
+    ScopedStatTimer _st(pylt_timer_counter);
 #endif
 
     int r = PyObject_RichCompareBool(lhs, rhs, Py_LT);

src/runtime/types.h

@@ -836,8 +836,8 @@ public:
     void* stack_begin;
 
 #if STAT_TIMERS
-    StatTimer* statTimers;
-    uint64_t timer_time;
+    StatTimer* prev_stack;
+    StatTimer my_timer;
 #endif
 
     BoxedGenerator(BoxedFunctionBase* function, Box* arg1, Box* arg2, Box* arg3, Box** args);