Merge pull request #623 from kmod/stats

Playing with stattimers

src/capi/descrobject.cpp

@@ -18,7 +18,7 @@
 namespace pyston {
 
 Box* BoxedMethodDescriptor::__call__(BoxedMethodDescriptor* self, Box* obj, BoxedTuple* varargs, Box** _args) {
-    STAT_TIMER(t0, "us_timer_boxedmethoddescriptor__call__");
+    STAT_TIMER(t0, "us_timer_boxedmethoddescriptor__call__", 10);
     BoxedDict* kwargs = static_cast<BoxedDict*>(_args[0]);
 
     assert(self->cls == method_cls);

src/capi/types.h

@@ -56,7 +56,7 @@ public:
     }
 
     static Box* __call__(BoxedCApiFunction* self, BoxedTuple* varargs, BoxedDict* kwargs) {
-        STAT_TIMER(t0, "us_timer_boxedcapifunction__call__");
+        STAT_TIMER(t0, "us_timer_boxedcapifunction__call__", (self->cls->is_user_defined ? 10 : 20));
         assert(self->cls == capifunc_cls);
         assert(varargs->cls == tuple_cls);
         assert(kwargs->cls == dict_cls);
@@ -164,7 +164,7 @@ public:
     DEFAULT_CLASS(wrapperobject_cls);
 
     static Box* __call__(BoxedWrapperObject* self, Box* args, Box* kwds) {
-        STAT_TIMER(t0, "us_timer_boxedwrapperobject__call__");
+        STAT_TIMER(t0, "us_timer_boxedwrapperobject__call__", (self->cls->is_user_defined ? 1 : 2));
 
         assert(self->cls == wrapperobject_cls);
         assert(args->cls == tuple_cls);

src/codegen/ast_interpreter.cpp

@@ -386,7 +386,7 @@ Value ASTInterpreter::executeInner(ASTInterpreter& interpreter, CFGBlock* start_
 }
 
 Value ASTInterpreter::execute(ASTInterpreter& interpreter, CFGBlock* start_block, AST_stmt* start_at) {
-    STAT_TIMER(t0, "us_timer_astinterpreter_execute");
+    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_astinterpreter_execute");
 
     RegisterHelper frame_registerer;
 
@@ -605,7 +605,7 @@ Value ASTInterpreter::visit_jump(AST_Jump* node) {
                 arg_array.push_back(it.second);
             }
 
-            STAT_TIMER(t0, "us_timer_astinterpreter_jump_osrexit");
+            UNAVOIDABLE_STAT_TIMER(t0, "us_timer_astinterpreter_jump_osrexit");
             CompiledFunction* partial_func = compilePartialFuncInternal(&exit);
             auto arg_tuple = getTupleFromArgsArray(&arg_array[0], arg_array.size());
             Box* r = partial_func->call(std::get<0>(arg_tuple), std::get<1>(arg_tuple), std::get<2>(arg_tuple),
@@ -1007,8 +1007,6 @@ Value ASTInterpreter::visit_print(AST_Print* node) {
     static BoxedString* newline_str = static_cast<BoxedString*>(PyString_InternFromString("\n"));
     static BoxedString* space_str = static_cast<BoxedString*>(PyString_InternFromString(" "));
 
-    STAT_TIMER(t0, "us_timer_visit_print");
-
     Box* dest = node->dest ? visit_expr(node->dest).o : getSysStdout();
     int nvals = node->values.size();
     assert(nvals <= 1 && "cfg should have lowered it to 0 or 1 values");

src/codegen/irgen/hooks.cpp

@@ -177,7 +177,7 @@ static void compileIR(CompiledFunction* cf, EffortLevel effort) {
 // The codegen_lock needs to be held in W mode before calling this function:
 CompiledFunction* compileFunction(CLFunction* f, FunctionSpecialization* spec, EffortLevel effort,
                                   const OSREntryDescriptor* entry_descriptor) {
-    STAT_TIMER(t0, "us_timer_compileFunction");
+    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_compileFunction");
     Timer _t("for compileFunction()", 1000);
 
     assert((entry_descriptor != NULL) + (spec != NULL) == 1);
@@ -329,10 +329,10 @@ void compileAndRunModule(AST_Module* m, BoxedModule* bm) {
     }
 
     if (cf->is_interpreted) {
-        STAT_TIMER(t0, "us_timer_interpreted_module_toplevel");
+        UNAVOIDABLE_STAT_TIMER(t0, "us_timer_interpreted_module_toplevel");
         astInterpretFunction(cf, 0, NULL, NULL, NULL, NULL, NULL, NULL, NULL);
     } else {
-        STAT_TIMER(t1, "us_timer_jitted_module_toplevel");
+        UNAVOIDABLE_STAT_TIMER(t1, "us_timer_jitted_module_toplevel");
         ((void (*)())cf->code)();
     }
 }

src/codegen/parser.cpp

@@ -995,7 +995,7 @@ AST_Module* parse_string(const char* code) {
 }
 
 AST_Module* parse_file(const char* fn) {
-    STAT_TIMER(t0, "us_timer_cpyton_parsing");
+    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_cpyton_parsing");
     Timer _t("parsing");
 
     if (ENABLE_PYPA_PARSER) {
@@ -1095,7 +1095,7 @@ static ParseResult _reparse(const char* fn, const std::string& cache_fn, AST_Mod
 // it's not a huge deal right now, but this caching version can significantly cut down
 // on the startup time (40ms -> 10ms).
 AST_Module* caching_parse_file(const char* fn) {
-    STAT_TIMER(t0, "us_timer_caching_parse_file");
+    UNAVOIDABLE_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); });

src/codegen/unwinding.cpp

@@ -692,7 +692,7 @@ template <typename Func> void unwindPythonStack(Func func) {
 }
 
 static std::unique_ptr<PythonFrameIteratorImpl> getTopPythonFrame() {
-    STAT_TIMER(t0, "us_timer_getTopPythonFrame");
+    STAT_TIMER(t0, "us_timer_getTopPythonFrame", 10);
     std::unique_ptr<PythonFrameIteratorImpl> rtn(nullptr);
     unwindPythonStack([&](PythonFrameIteratorImpl* iter) {
         rtn = std::unique_ptr<PythonFrameIteratorImpl>(new PythonFrameIteratorImpl(*iter));
@@ -733,7 +733,7 @@ static std::unique_ptr<PythonFrameIteratorImpl> getTopPythonFrame() {
 //
 static StatCounter us_gettraceback("us_gettraceback");
 BoxedTraceback* getTraceback() {
-    STAT_TIMER(t0, "us_timer_gettraceback");
+    STAT_TIMER(t0, "us_timer_gettraceback", 20);
     if (!ENABLE_FRAME_INTROSPECTION) {
         static bool printed_warning = false;
         if (!printed_warning) {

src/core/stats.h

@@ -38,11 +38,15 @@ namespace pyston {
 #define EXPENSIVE_STAT_TIMERS (0 && STAT_TIMERS)
 
 #if STAT_TIMERS
-#define STAT_TIMER(id, name)                                                                                           \
+#define STAT_TIMER(id, name, avoidability)                                                                             \
     static uint64_t* _stcounter##id = Stats::getStatCounter(name);                                                     \
-    ScopedStatTimer _st##id(_stcounter##id)
+    ScopedStatTimer _st##id(_stcounter##id, avoidability)
+#define UNAVOIDABLE_STAT_TIMER(id, name)                                                                               \
+    static uint64_t* _stcounter##id = Stats::getStatCounter(name);                                                     \
+    ScopedStatTimer _st##id(_stcounter##id, 0, true)
 #else
-#define STAT_TIMER(id, name)
+#define STAT_TIMER(id, name, avoidability)
+#define UNAVOIDABLE_STAT_TIMER(id, name)
 #endif
 
 #define STAT_TIMER_NAME(id) _st##id
@@ -122,34 +126,43 @@ private:
     StatTimer* _prev;
 
     uint64_t* _statcounter;
+    int avoidability;
+    bool reset_avoidability;
 
 public:
-    StatTimer(uint64_t* counter) : _statcounter(counter) {}
+    StatTimer(uint64_t* counter, int avoidability, bool reset_avoidability = false)
+        : _statcounter(counter), avoidability(avoidability), reset_avoidability(reset_avoidability) {}
 
     void pushNonTopLevel() {
-        uint64_t at_time = getCPUTicks();
 #ifndef NDEBUG
         _start_time = 0;
 #endif
 
         assert(stack);
         _prev = stack;
-        stack = this;
-        _prev->pause(at_time);
-        resume(at_time);
-    }
 
-    void popNonTopLevel() {
-        assert(stack == this);
+        if (reset_avoidability || avoidability >= _prev->avoidability) {
+            uint64_t at_time = getCPUTicks();
 
-        uint64_t at_time;
-        assert(!isPaused());
-        at_time = getCPUTicks();
-        pause(at_time);
+            stack = this;
+            _prev->pause(at_time);
+            resume(at_time);
+        }
+    }
 
-        assert(_prev);
-        stack = _prev;
-        stack->resume(at_time);
+    void popNonTopLevel() {
+        if (reset_avoidability || avoidability >= _prev->avoidability) {
+            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) {
@@ -200,7 +213,10 @@ private:
     StatTimer timer;
 
 public:
-    ScopedStatTimer(uint64_t* counter) : timer(counter) { timer.pushNonTopLevel(); }
+    ScopedStatTimer(uint64_t* counter, int avoidability, bool reset_avoidability = false)
+        : timer(counter, avoidability, reset_avoidability) {
+        timer.pushNonTopLevel();
+    }
     ~ScopedStatTimer() { timer.popNonTopLevel(); }
 };
 #else

src/gc/collector.cpp

@@ -400,7 +400,7 @@ void runCollection() {
     static StatCounter sc("gc_collections");
     sc.log();
 
-    STAT_TIMER(t0, "us_timer_gc_collection");
+    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_gc_collection");
 
     ncollections++;
 

src/jit.cpp

@@ -269,7 +269,7 @@ static int main(int argc, char** argv) {
     int rtncode = 0;
     {
 #if STAT_TIMERS
-        StatTimer timer(Stats::getStatCounter("us_timer_main_toplevel"));
+        StatTimer timer(Stats::getStatCounter("us_timer_main_toplevel"), 0, true);
         timer.pushTopLevel(main_time.getStartTime());
 #endif
 

src/runtime/builtin_modules/builtins.cpp

@@ -306,7 +306,6 @@ extern "C" Box* ord(Box* obj) {
 }
 
 Box* range(Box* start, Box* stop, Box* step) {
-    STAT_TIMER(t0, "us_timer_builtin_range");
     i64 istart, istop, istep;
     if (stop == NULL) {
         istart = 0;
@@ -350,7 +349,6 @@ Box* notimplementedRepr(Box* self) {
 }
 
 Box* sorted(Box* obj, Box* cmp, Box* key, Box** args) {
-    STAT_TIMER(t0, "us_timer_builtin_sorted");
     Box* reverse = args[0];
 
     BoxedList* rtn = new BoxedList();
@@ -363,7 +361,6 @@ Box* sorted(Box* obj, Box* cmp, Box* key, Box** args) {
 }
 
 Box* isinstance_func(Box* obj, Box* cls) {
-    STAT_TIMER(t0, "us_timer_builtin_isinstance");
     int rtn = PyObject_IsInstance(obj, cls);
     if (rtn < 0)
         checkAndThrowCAPIException();
@@ -371,7 +368,6 @@ Box* isinstance_func(Box* obj, Box* cls) {
 }
 
 Box* issubclass_func(Box* child, Box* parent) {
-    STAT_TIMER(t0, "us_timer_builtin_issubclass");
     int rtn = PyObject_IsSubclass(child, parent);
     if (rtn < 0)
         checkAndThrowCAPIException();

src/runtime/builtin_modules/thread.cpp

@@ -66,7 +66,7 @@ static void* thread_start(Box* target, Box* varargs, Box* kwargs) {
 #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);
+    StatTimer timer(timer_counter, 0, true);
     timer.pushTopLevel(getCPUTicks());
 #endif
 

src/runtime/dict.cpp

@@ -49,7 +49,6 @@ Box* dictRepr(BoxedDict* self) {
 }
 
 Box* dictClear(BoxedDict* self) {
-    STAT_TIMER(t0, "us_timer_dictClear");
     if (!isSubclass(self->cls, dict_cls))
         raiseExcHelper(TypeError, "descriptor 'clear' requires a 'dict' object but received a '%s'", getTypeName(self));
 
@@ -58,7 +57,6 @@ Box* dictClear(BoxedDict* self) {
 }
 
 Box* dictCopy(BoxedDict* self) {
-    STAT_TIMER(t0, "us_timer_dictCopy");
     if (!isSubclass(self->cls, dict_cls))
         raiseExcHelper(TypeError, "descriptor 'copy' requires a 'dict' object but received a '%s'", getTypeName(self));
 
@@ -68,7 +66,6 @@ Box* dictCopy(BoxedDict* self) {
 }
 
 Box* dictItems(BoxedDict* self) {
-    STAT_TIMER(t0, "us_timer_dictItems");
     BoxedList* rtn = new BoxedList();
 
     rtn->ensure(self->d.size());
@@ -81,7 +78,6 @@ Box* dictItems(BoxedDict* self) {
 }
 
 Box* dictValues(BoxedDict* self) {
-    STAT_TIMER(t0, "us_timer_dictValues");
     BoxedList* rtn = new BoxedList();
     rtn->ensure(self->d.size());
     for (const auto& p : self->d) {
@@ -91,7 +87,6 @@ Box* dictValues(BoxedDict* self) {
 }
 
 Box* dictKeys(BoxedDict* self) {
-    STAT_TIMER(t0, "us_timer_dictKeys");
     RELEASE_ASSERT(isSubclass(self->cls, dict_cls), "");
 
     BoxedList* rtn = new BoxedList();
@@ -188,7 +183,6 @@ extern "C" int PyDict_Update(PyObject* a, PyObject* b) noexcept {
 }
 
 Box* dictGetitem(BoxedDict* self, Box* k) {
-    STAT_TIMER(t0, "us_timer_dictGetitem");
     if (!isSubclass(self->cls, dict_cls))
         raiseExcHelper(TypeError, "descriptor '__getitem__' requires a 'dict' object but received a '%s'",
                        getTypeName(self));
@@ -320,7 +314,6 @@ extern "C" PyObject* PyDict_GetItemString(PyObject* dict, const char* key) noexc
 }
 
 Box* dictSetitem(BoxedDict* self, Box* k, Box* v) {
-    STAT_TIMER(t0, "us_timer_dictSetitem");
     // printf("Starting setitem\n");
     Box*& pos = self->d[k];
     // printf("Got the pos\n");
@@ -335,7 +328,6 @@ Box* dictSetitem(BoxedDict* self, Box* k, Box* v) {
 }
 
 Box* dictDelitem(BoxedDict* self, Box* k) {
-    STAT_TIMER(t0, "us_timer_dictDelitem");
     if (!isSubclass(self->cls, dict_cls))
         raiseExcHelper(TypeError, "descriptor '__delitem__' requires a 'dict' object but received a '%s'",
                        getTypeName(self));

src/runtime/generator.cpp

@@ -302,7 +302,7 @@ extern "C" BoxedGenerator::BoxedGenerator(BoxedFunctionBase* function, Box* arg1
 #if STAT_TIMERS
       ,
       prev_stack(NULL),
-      my_timer(generator_timer_counter)
+      my_timer(generator_timer_counter, 0, true)
 #endif
 {
 

src/runtime/list.cpp

@@ -561,8 +561,6 @@ extern "C" int PyList_Insert(PyObject* op, Py_ssize_t where, PyObject* newitem)
 }
 
 Box* listMul(BoxedList* self, Box* rhs) {
-    STAT_TIMER(t0, "us_timer_listMul");
-
     if (rhs->cls != int_cls) {
         raiseExcHelper(TypeError, "can't multiply sequence by non-int of type '%s'", getTypeName(rhs));
     }

src/runtime/str.cpp

@@ -1141,7 +1141,6 @@ extern "C" Box* strMod(BoxedString* lhs, Box* rhs) {
 }
 
 extern "C" Box* strMul(BoxedString* lhs, Box* rhs) {
-    STAT_TIMER(t0, "us_timer_strMul");
     assert(isSubclass(lhs->cls, str_cls));
 
     int n;
@@ -1526,7 +1525,6 @@ failed:
 }
 
 extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) {
-    STAT_TIMER(t0, "us_timer_unicodeHashUnboxed");
     if (self->hash != -1)
         return self->hash;
 
@@ -1537,7 +1535,6 @@ extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) {
 }
 
 extern "C" Box* strHash(BoxedString* self) {
-    STAT_TIMER(t0, "us_timer_strHash");
     assert(isSubclass(self->cls, str_cls));
 
     StringHash<char> H;

src/runtime/tuple.cpp

@@ -169,7 +169,6 @@ Box* tupleAdd(BoxedTuple* self, Box* rhs) {
 }
 
 Box* tupleMul(BoxedTuple* self, Box* rhs) {
-    STAT_TIMER(t0, "us_timer_tupleMul");
     if (rhs->cls != int_cls) {
         raiseExcHelper(TypeError, "can't multiply sequence by non-int of type '%s'", getTypeName(rhs));
     }

src/runtime/types.cpp

@@ -1419,8 +1419,6 @@ public:
     }
 
     static Box* setitem(Box* _self, Box* _key, Box* value) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_setitem");
-
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1433,7 +1431,6 @@ public:
     }
 
     static Box* setdefault(Box* _self, Box* _key, Box* value) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_setdefault");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1449,7 +1446,6 @@ public:
     }
 
     static Box* get(Box* _self, Box* _key, Box* def) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_get");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1464,7 +1460,6 @@ public:
     }
 
     static Box* getitem(Box* _self, Box* _key) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_getitem");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1498,7 +1493,6 @@ public:
     }
 
     static Box* delitem(Box* _self, Box* _key) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_delitem");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1564,7 +1558,6 @@ public:
     }
 
     static Box* values(Box* _self) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_values");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1579,7 +1572,6 @@ public:
     }
 
     static Box* items(Box* _self) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_items");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 
@@ -1649,7 +1641,6 @@ public:
     }
 
     static Box* update(Box* _self, BoxedTuple* args, BoxedDict* kwargs) {
-        STAT_TIMER(t0, "us_timer_AttrWrapper_update");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);