Add the concept of stattimer "avoidability"

ie roll up all the time into the most "avoidable" reason that we were doing it.
For example, if we are doing something like calling slot_tp_getttro on a builtin
type (very avoidable), roll up all the subsequent time (runtimeCall, etc) into
the slot_tp_getattro timer.  But if we call runtimeCall where we couldn't avoid it
(ex from the interpreter), log that separately.

Not sure how helpful it will be but for this specific investigation it seems to
somewhat work.  The idea of the "avoidability" is definitely pretty specific to
the type of work that you are thinking of doing; the numbers I put in are for
investigating slowpaths.

Also, remove all the timers that we have on specific runtime functions (ex: listMul).
I think we'll need another strategy for those.

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);