Merge pull request #498 from toshok/stat-timers2

put back in the Timer-based stats I removed in the stats-timer branch…

src/codegen/parser.cpp

@@ -983,6 +983,7 @@ AST_Module* parse_string(const char* code) {
 
 AST_Module* parse_file(const char* fn) {
     STAT_TIMER(t0, "us_timer_cpyton_parsing");
+    Timer _t("parsing");
 
     if (ENABLE_PYPA_PARSER) {
         AST_Module* rtn = pypa_parse(fn);
@@ -1003,6 +1004,10 @@ AST_Module* parse_file(const char* fn) {
 
     assert(rtn->type == AST_TYPE::Module);
 
+    long us = _t.end();
+    static StatCounter us_parsing("us_parsing");
+    us_parsing.log(us);
+
     return ast_cast<AST_Module>(rtn);
 }
 
@@ -1068,6 +1073,9 @@ static ParseResult _reparse(const char* fn, const std::string& cache_fn, AST_Mod
 // on the startup time (40ms -> 10ms).
 AST_Module* caching_parse_file(const char* fn) {
     STAT_TIMER(t0, "us_timer_caching_parse_file");
+    static StatCounter us_parsing("us_parsing");
+    Timer _t("parsing");
+    _t.setExitCallback([](uint64_t t) { us_parsing.log(t); });
 
     int code;
     std::string cache_fn = std::string(fn) + "c";

src/codegen/unwinding.cpp

@@ -513,6 +513,7 @@ static const LineInfo* lineInfoForFrame(PythonFrameIteratorImpl& frame_it) {
     return new LineInfo(current_stmt->lineno, current_stmt->col_offset, source->fn, source->getName());
 }
 
+static StatCounter us_gettraceback("us_gettraceback");
 BoxedTraceback* getTraceback() {
     STAT_TIMER(t0, "us_timer_gettraceback");
     if (!ENABLE_FRAME_INTROSPECTION) {
@@ -533,6 +534,8 @@ BoxedTraceback* getTraceback() {
         return new BoxedTraceback();
     }
 
+    Timer _t("getTraceback", 1000);
+
     std::vector<const LineInfo*> entries;
     unwindPythonStack([&](std::unique_ptr<PythonFrameIteratorImpl> frame_iter) {
         const LineInfo* line_info = lineInfoForFrame(*frame_iter.get());
@@ -543,6 +546,9 @@ BoxedTraceback* getTraceback() {
 
     std::reverse(entries.begin(), entries.end());
 
+    long us = _t.end();
+    us_gettraceback.log(us);
+
     return new BoxedTraceback(std::move(entries));
 }
 

src/core/stats.cpp

@@ -22,6 +22,7 @@
 namespace pyston {
 
 #if !DISABLE_STATS
+#if STAT_TIMERS
 extern "C" const char* getStatTimerNameById(int id) {
     return Stats::getStatName(id).c_str();
 }
@@ -116,6 +117,7 @@ StatTimer* StatTimer::swapStack(StatTimer* s, uint64_t at_time) {
     }
     return prev_stack;
 }
+#endif
 
 std::vector<uint64_t>* Stats::counts;
 std::unordered_map<int, std::string>* Stats::names;

src/core/stats.h

@@ -26,12 +26,12 @@
 
 namespace pyston {
 
-#define STAT_ALLOCATIONS 0
-
-
 #define DISABLE_STATS 0
 
-#if !DISABLE_STATS
+#define STAT_ALLOCATIONS 0 && !DISABLE_STATS
+#define STAT_TIMERS 0 && !DISABLE_STATS
+
+#if STAT_TIMERS
 #define STAT_TIMER(id, name)                                                                                           \
     static int _stid##id = Stats::getStatId(name);                                                                     \
     StatTimer _st##id(_stid##id)
@@ -80,6 +80,38 @@ public:
     void log(uint64_t count = 1) { Stats::log(id, count); }
 };
 
+struct StatPerThreadCounter {
+private:
+    int id = 0;
+
+public:
+    StatPerThreadCounter(const std::string& name);
+
+    void log(uint64_t count = 1) { Stats::log(id, count); }
+};
+
+#else
+struct Stats {
+    static void startEstimatingCPUFreq() {}
+    static double estimateCPUFreq() { return 0; }
+    static void setEnabled(bool enabled) {}
+    static void dump(bool includeZeros = true) { printf("(Stats disabled)\n"); }
+    static void clear() {}
+    static void log(int id, int count = 1) {}
+    static int getStatId(const std::string& name) { return 0; }
+    static void endOfInit() {}
+};
+struct StatCounter {
+    StatCounter(const char* name) {}
+    void log(uint64_t count = 1){};
+};
+struct StatPerThreadCounter {
+    StatPerThreadCounter(const char* name) {}
+    void log(uint64_t count = 1){};
+};
+#endif
+
+#if STAT_TIMERS
 class StatTimer {
 private:
     static __thread StatTimer* stack;
@@ -113,32 +145,7 @@ public:
 
     static void assertActive() { RELEASE_ASSERT(stack && !stack->isPaused(), ""); }
 };
-
-struct StatPerThreadCounter {
-private:
-    int id = 0;
-
-public:
-    StatPerThreadCounter(const std::string& name);
-
-    void log(uint64_t count = 1) { Stats::log(id, count); }
-};
-
 #else
-struct Stats {
-    static void startEstimatingCPUFreq() {}
-    static double estimateCPUFreq() { return 0; }
-    static void setEnabled(bool enabled) {}
-    static void dump(bool includeZeros = true) { printf("(Stats disabled)\n"); }
-    static void clear() {}
-    static void log(int id, int count = 1) {}
-    static int getStatId(const std::string& name) { return 0; }
-    static void endOfInit() {}
-};
-struct StatCounter {
-    StatCounter(const char* name) {}
-    void log(uint64_t count = 1){};
-};
 struct StatTimer {
     StatTimer(int statid, bool push = true) {}
     StatTimer(int statid, uint64_t at_time) {}
@@ -152,10 +159,6 @@ struct StatTimer {
     static StatTimer* swapStack(StatTimer* s, uint64_t at_time) { return NULL; }
     static void assertActive() {}
 };
-struct StatPerThreadCounter {
-    StatPerThreadCounter(const char* name) {}
-    void log(uint64_t count = 1){};
-};
 #endif
 }
 

src/gc/collector.cpp

@@ -346,6 +346,8 @@ void runCollection() {
     if (VERBOSITY("gc") >= 2)
         printf("Collection #%d\n", ncollections);
 
+    Timer _t("collecting", /*min_usec=*/10000);
+
     markPhase();
     std::list<Box*, StlCompatAllocator<Box*>> weakly_referenced;
     sweepPhase(weakly_referenced);
@@ -369,6 +371,10 @@ void runCollection() {
     if (VERBOSITY("gc") >= 2)
         printf("Collection #%d done\n\n", ncollections);
 
+    long us = _t.end();
+    static StatCounter sc_us("gc_collections_us");
+    sc_us.log(us);
+
     // dumpHeapStatistics();
 }
 

src/jit.cpp

@@ -369,7 +369,7 @@ static int main(int argc, char** argv) {
         uint64_t main_time_duration = main_time.end(&main_time_ended_at);
         static StatCounter mt("ticks_in_main");
         mt.log(main_time_duration);
-        _stt0.pause(main_time_ended_at);
+        STAT_TIMER_NAME(t0).pause(main_time_ended_at);
     }
     Stats::dump(true);
 

src/runtime/generator.cpp

@@ -111,7 +111,7 @@ void generatorEntry(BoxedGenerator* g) {
         g->entryExited = true;
         threading::popGenerator();
 
-#if !DISABLE_STATS
+#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
@@ -139,7 +139,7 @@ Box* generatorSend(Box* s, Box* v) {
     self->returnValue = v;
     self->running = true;
 
-#if !DISABLE_STATS
+#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);
@@ -147,7 +147,7 @@ Box* generatorSend(Box* s, Box* v) {
 
     swapContext(&self->returnContext, self->context, (intptr_t)self);
 
-#if !DISABLE_STATS
+#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());

src/runtime/objmodel.cpp

@@ -2735,7 +2735,7 @@ static StatCounter slowpath_callfunc_slowpath("slowpath_callfunc_slowpath");
 Box* callFunc(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, ArgPassSpec argspec, Box* arg1, Box* arg2,
               Box* arg3, Box** args, const std::vector<const std::string*>* keyword_names) {
 
-#if !DISABLE_STATS
+#if STAT_TIMERS
     StatTimer::assertActive();
 #endif
     /*

src/runtime/types.h

@@ -873,7 +873,7 @@ public:
     struct Context* context, *returnContext;
     void* stack_begin;
 
-#if !DISABLE_STATS
+#if STAT_TIMERS
     StatTimer* statTimers;
     uint64_t timer_time;
 #endif