Merge pull request #475 from toshok/stat-timers

Stat timers

from_cpython/Include/pyconfig.h

@@ -59,6 +59,9 @@
 #define HAVE_STRUCT_TM_TM_ZONE 1
 #define HAVE_MKTIME 1
 
+#define TIME_WITH_SYS_TIME
+#define HAVE_GETTIMEOFDAY 1
+
 #define PY_FORMAT_LONG_LONG "ll"
 #define PY_FORMAT_SIZE_T "z"
 

minibenchmarks/django-template.py

+from django.template.base import Origin, Template, Context, TemplateDoesNotExist
+from django.conf import settings
+from django.apps import apps
+import time
+
+try:
+    import __pyston__
+    pyston_loaded = True
+except:
+    pyston_loaded = False
+
+template_source = """
+{% extends "admin/base_site.html" %}
+{% load i18n admin_static %}
+
+{% block extrastyle %}{{ block.super }}<link rel="stylesheet" type="text/css" href="{% static "admin/css/dashboard.css" %}" />{% endblock %}
+
+{% block coltype %}colMS{% endblock %}
+
+{% block bodyclass %}{{ block.super }} dashboard{% endblock %}
+
+{% block breadcrumbs %}{% endblock %}
+
+{% block content %}
+<div id="content-main">
+
+{% if app_list %}
+    {% for app in app_list %}
+        <div class="app-{{ app.app_label }} module">
+        <table>
+        <caption>
+            <a href="{{ app.app_url }}" class="section" title="{% blocktrans with name=app.name %}Models in the {{ name }} application{% endblocktrans %}">{{ app.name }}</a>
+        </caption>
+        {% for model in app.models %}
+            <tr class="model-{{ model.object_name|lower }}">
+            {% if model.admin_url %}
+                <th scope="row"><a href="{{ model.admin_url }}">{{ model.name }}</a></th>
+            {% else %}
+                <th scope="row">{{ model.name }}</th>
+            {% endif %}
+
+            {% if model.add_url %}
+                <td><a href="{{ model.add_url }}" class="addlink">{% trans 'Add' %}</a></td>
+            {% else %}
+                <td>&nbsp;</td>
+            {% endif %}
+
+            {% if model.admin_url %}
+                <td><a href="{{ model.admin_url }}" class="changelink">{% trans 'Change' %}</a></td>
+            {% else %}
+                <td>&nbsp;</td>
+            {% endif %}
+            </tr>
+        {% endfor %}
+        </table>
+        </div>
+    {% endfor %}
+{% else %}
+    <p>{% trans "You don't have permission to edit anything." %}</p>
+{% endif %}
+</div>
+{% endblock %}
+
+{% block sidebar %}
+<div id="content-related">
+    <div class="module" id="recent-actions-module">
+        <h2>{% trans 'Recent Actions' %}</h2>
+        <h3>{% trans 'My Actions' %}</h3>
+            {% load log %}
+            {% get_admin_log 10 as admin_log for_user user %}
+            {% if not admin_log %}
+            <p>{% trans 'None available' %}</p>
+            {% else %}
+            <ul class="actionlist">
+            {% for entry in admin_log %}
+            <li class="{% if entry.is_addition %}addlink{% endif %}{% if entry.is_change %}changelink{% endif %}{% if entry.is_deletion %}deletelink{% endif %}">
+                {% if entry.is_deletion or not entry.get_admin_url %}
+                    {{ entry.object_repr }}
+                {% else %}
+                    <a href="{{ entry.get_admin_url }}">{{ entry.object_repr }}</a>
+                {% endif %}
+                <br/>
+                {% if entry.content_type %}
+                    <span class="mini quiet">{% filter capfirst %}{% trans entry.content_type.name %}{% endfilter %}</span>
+                {% else %}
+                    <span class="mini quiet">{% trans 'Unknown content' %}</span>
+                {% endif %}
+            </li>
+            {% endfor %}
+            </ul>
+            {% endif %}
+    </div>
+</div>
+{% endblock %}
+"""
+
+settings.configure()
+
+apps.populate((
+    'django.contrib.admin',
+    'django.contrib.auth',
+    'django.contrib.contenttypes',
+    'django.contrib.sessions',
+    'django.contrib.messages',
+    'django.contrib.staticfiles',
+))
+
+elapsed = 0
+for i in xrange(500):
+    #if pyston_loaded:
+    #    __pyston__.clearStats()
+    start = time.time()
+    template = Template(template_source, None, "admin/index.html")
+    elapsed = time.time() - start
+print "took %4.1fms for last iteration" % (elapsed * 1000.0,)

src/capi/descrobject.cpp

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

src/capi/typeobject.cpp

@@ -58,6 +58,7 @@ static int hackcheck(PyObject* self, setattrofunc func, const char* what) noexce
 }
 
 static PyObject* wrap_setattr(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_setattr");
     setattrofunc func = (setattrofunc)wrapped;
     int res;
     PyObject* name, *value;
@@ -74,6 +75,7 @@ static PyObject* wrap_setattr(PyObject* self, PyObject* args, void* wrapped) noe
 }
 
 static PyObject* wrap_delattr(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_delattr");
     setattrofunc func = (setattrofunc)wrapped;
     int res;
     PyObject* name;
@@ -91,6 +93,7 @@ static PyObject* wrap_delattr(PyObject* self, PyObject* args, void* wrapped) noe
 }
 
 static PyObject* wrap_hashfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_hashfunc");
     hashfunc func = (hashfunc)wrapped;
     long res;
 
@@ -103,12 +106,14 @@ static PyObject* wrap_hashfunc(PyObject* self, PyObject* args, void* wrapped) no
 }
 
 static PyObject* wrap_call(PyObject* self, PyObject* args, void* wrapped, PyObject* kwds) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_call");
     ternaryfunc func = (ternaryfunc)wrapped;
 
     return (*func)(self, args, kwds);
 }
 
 static PyObject* wrap_richcmpfunc(PyObject* self, PyObject* args, void* wrapped, int op) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_richcmpfunc");
     richcmpfunc func = (richcmpfunc)wrapped;
     PyObject* other;
 
@@ -132,6 +137,7 @@ RICHCMP_WRAPPER(gt, Py_GT)
 RICHCMP_WRAPPER(ge, Py_GE)
 
 static PyObject* wrap_next(PyObject* self, PyObject* args, void* wrapped) {
+    STAT_TIMER(t0, "us_timer_wrap_next");
     unaryfunc func = (unaryfunc)wrapped;
     PyObject* res;
 
@@ -144,6 +150,7 @@ static PyObject* wrap_next(PyObject* self, PyObject* args, void* wrapped) {
 }
 
 static PyObject* wrap_descr_get(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_descr_get");
     descrgetfunc func = (descrgetfunc)wrapped;
     PyObject* obj;
     PyObject* type = NULL;
@@ -162,6 +169,7 @@ static PyObject* wrap_descr_get(PyObject* self, PyObject* args, void* wrapped) n
 }
 
 static PyObject* wrap_coercefunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_coercefunc");
     coercion func = (coercion)wrapped;
     PyObject* other, *res;
     int ok;
@@ -188,6 +196,7 @@ static PyObject* wrap_coercefunc(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_ternaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_ternaryfunc");
     ternaryfunc func = (ternaryfunc)wrapped;
     PyObject* other;
     PyObject* third = Py_None;
@@ -200,6 +209,7 @@ static PyObject* wrap_ternaryfunc(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_ternaryfunc_r(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_ternaryfunc_r");
     ternaryfunc func = (ternaryfunc)wrapped;
     PyObject* other;
     PyObject* third = Py_None;
@@ -212,6 +222,7 @@ static PyObject* wrap_ternaryfunc_r(PyObject* self, PyObject* args, void* wrappe
 }
 
 static PyObject* wrap_unaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_unaryfunc");
     unaryfunc func = (unaryfunc)wrapped;
 
     if (!check_num_args(args, 0))
@@ -220,6 +231,7 @@ static PyObject* wrap_unaryfunc(PyObject* self, PyObject* args, void* wrapped) n
 }
 
 static PyObject* wrap_inquirypred(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_inquirypred");
     inquiry func = (inquiry)wrapped;
     int res;
 
@@ -232,6 +244,7 @@ static PyObject* wrap_inquirypred(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrapInquirypred(PyObject* self, PyObject* args, void* wrapped) {
+    STAT_TIMER(t0, "us_timer_wrapInquirypred");
     inquiry func = (inquiry)wrapped;
     int res;
 
@@ -244,6 +257,7 @@ static PyObject* wrapInquirypred(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_binaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_binaryfunc");
     binaryfunc func = (binaryfunc)wrapped;
     PyObject* other;
 
@@ -254,6 +268,7 @@ static PyObject* wrap_binaryfunc(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_binaryfunc_l(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_binaryfunc_l");
     binaryfunc func = (binaryfunc)wrapped;
     PyObject* other;
 
@@ -268,6 +283,7 @@ static PyObject* wrap_binaryfunc_l(PyObject* self, PyObject* args, void* wrapped
 }
 
 static PyObject* wrap_binaryfunc_r(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_binaryfunc_r");
     binaryfunc func = (binaryfunc)wrapped;
     PyObject* other;
 
@@ -300,6 +316,7 @@ static Py_ssize_t getindex(PyObject* self, PyObject* arg) noexcept {
 }
 
 static PyObject* wrap_lenfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_lenfunc");
     lenfunc func = (lenfunc)wrapped;
     Py_ssize_t res;
 
@@ -312,6 +329,7 @@ static PyObject* wrap_lenfunc(PyObject* self, PyObject* args, void* wrapped) noe
 }
 
 static PyObject* wrap_indexargfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_indexargfunc");
     ssizeargfunc func = (ssizeargfunc)wrapped;
     PyObject* o;
     Py_ssize_t i;
@@ -325,6 +343,7 @@ static PyObject* wrap_indexargfunc(PyObject* self, PyObject* args, void* wrapped
 }
 
 static PyObject* wrap_sq_item(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_sq_item");
     ssizeargfunc func = (ssizeargfunc)wrapped;
     PyObject* arg;
     Py_ssize_t i;
@@ -342,6 +361,7 @@ static PyObject* wrap_sq_item(PyObject* self, PyObject* args, void* wrapped) noe
 }
 
 static PyObject* wrap_ssizessizeargfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_ssizessizeargfunc");
     ssizessizeargfunc func = (ssizessizeargfunc)wrapped;
     Py_ssize_t i, j;
 
@@ -351,6 +371,7 @@ static PyObject* wrap_ssizessizeargfunc(PyObject* self, PyObject* args, void* wr
 }
 
 static PyObject* wrap_sq_setitem(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_sq_setitem");
     ssizeobjargproc func = (ssizeobjargproc)wrapped;
     Py_ssize_t i;
     int res;
@@ -369,6 +390,7 @@ static PyObject* wrap_sq_setitem(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_sq_delitem(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_sq_delitem");
     ssizeobjargproc func = (ssizeobjargproc)wrapped;
     Py_ssize_t i;
     int res;
@@ -388,6 +410,7 @@ static PyObject* wrap_sq_delitem(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_ssizessizeobjargproc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_ssizessizeobjargproc");
     ssizessizeobjargproc func = (ssizessizeobjargproc)wrapped;
     Py_ssize_t i, j;
     int res;
@@ -403,6 +426,7 @@ static PyObject* wrap_ssizessizeobjargproc(PyObject* self, PyObject* args, void*
 }
 
 static PyObject* wrap_delslice(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_delslice");
     ssizessizeobjargproc func = (ssizessizeobjargproc)wrapped;
     Py_ssize_t i, j;
     int res;
@@ -418,6 +442,7 @@ static PyObject* wrap_delslice(PyObject* self, PyObject* args, void* wrapped) no
 
 /* XXX objobjproc is a misnomer; should be objargpred */
 static PyObject* wrap_objobjproc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_objobjproc");
     objobjproc func = (objobjproc)wrapped;
     int res;
     PyObject* value;
@@ -433,6 +458,7 @@ static PyObject* wrap_objobjproc(PyObject* self, PyObject* args, void* wrapped)
 }
 
 static PyObject* wrap_objobjargproc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_objobjargproc");
     objobjargproc func = (objobjargproc)wrapped;
     int res;
     PyObject* key, *value;
@@ -447,6 +473,7 @@ static PyObject* wrap_objobjargproc(PyObject* self, PyObject* args, void* wrappe
 }
 
 static PyObject* wrap_delitem(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_delitem");
     objobjargproc func = (objobjargproc)wrapped;
     int res;
     PyObject* key;
@@ -462,6 +489,7 @@ static PyObject* wrap_delitem(PyObject* self, PyObject* args, void* wrapped) noe
 }
 
 static PyObject* wrap_cmpfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_cmpfunc");
     cmpfunc func = (cmpfunc)wrapped;
     int res;
     PyObject* other;
@@ -482,6 +510,7 @@ static PyObject* wrap_cmpfunc(PyObject* self, PyObject* args, void* wrapped) noe
 
 
 static PyObject* wrap_init(PyObject* self, PyObject* args, void* wrapped, PyObject* kwds) noexcept {
+    STAT_TIMER(t0, "us_timer_wrap_init");
     initproc func = (initproc)wrapped;
 
     if (func(self, args, kwds) < 0)

src/capi/types.h

@@ -54,6 +54,7 @@ public:
     }
 
     static Box* __call__(BoxedCApiFunction* self, BoxedTuple* varargs, BoxedDict* kwargs) {
+        STAT_TIMER(t0, "us_timer_boxedcapifunction__call__");
         assert(self->cls == capifunc_cls);
         assert(varargs->cls == tuple_cls);
         assert(kwargs->cls == dict_cls);
@@ -111,6 +112,8 @@ public:
     DEFAULT_CLASS(wrapperobject_cls);
 
     static Box* __call__(BoxedWrapperObject* self, Box* args, Box* kwds) {
+        STAT_TIMER(t0, "us_timer_boxedwrapperobject__call__");
+
         assert(self->cls == wrapperobject_cls);
         assert(args->cls == tuple_cls);
         assert(kwds->cls == dict_cls);

src/codegen/ast_interpreter.cpp

@@ -284,6 +284,8 @@ public:
 Value ASTInterpreter::execute(ASTInterpreter& interpreter, CFGBlock* start_block, AST_stmt* start_at) {
     threading::allowGLReadPreemption();
 
+    STAT_TIMER(t0, "us_timer_astinterpreter_execute");
+
     void* frame_addr = __builtin_frame_address(0);
     RegisterHelper frame_registerer(&interpreter, frame_addr);
 
@@ -540,6 +542,7 @@ Value ASTInterpreter::visit_jump(AST_Jump* node) {
                 arg_array.push_back(it.second);
             }
 
+            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),
@@ -927,6 +930,8 @@ Value ASTInterpreter::visit_print(AST_Print* node) {
     static const std::string newline_str("\n");
     static const std::string space_str(" ");
 
+    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/entry.cpp

@@ -362,7 +362,7 @@ static void handle_sigint(int signum) {
     // For now, just call abort(), so that we get a traceback at least.
     fprintf(stderr, "SIGINT!\n");
     joinRuntime();
-    Stats::dump();
+    Stats::dump(false);
     abort();
 }
 

src/codegen/irgen/hooks.cpp

@@ -182,6 +182,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");
     Timer _t("for compileFunction()", 1000);
 
     assert((entry_descriptor != NULL) + (spec != NULL) == 1);
@@ -315,10 +316,13 @@ void compileAndRunModule(AST_Module* m, BoxedModule* bm) {
         assert(cf->clfunc->versions.size());
     }
 
-    if (cf->is_interpreted)
+    if (cf->is_interpreted) {
+        STAT_TIMER(t0, "us_timer_interpreted_module_toplevel");
         astInterpretFunction(cf, 0, NULL, NULL, NULL, NULL, NULL, NULL, NULL);
-    else
+    } else {
+        STAT_TIMER(t1, "us_timer_jitted_module_toplevel");
         ((void (*)())cf->code)();
+    }
 }
 
 Box* evalOrExec(CLFunction* cl, Box* globals, Box* boxedLocals) {

src/codegen/parser.cpp

@@ -982,7 +982,7 @@ AST_Module* parse_string(const char* code) {
 }
 
 AST_Module* parse_file(const char* fn) {
-    Timer _t("parsing");
+    STAT_TIMER(t0, "us_timer_cpyton_parsing");
 
     if (ENABLE_PYPA_PARSER) {
         AST_Module* rtn = pypa_parse(fn);
@@ -1003,10 +1003,6 @@ 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);
 }
 
@@ -1071,9 +1067,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) {
-    static StatCounter us_parsing("us_parsing");
-    Timer _t("parsing");
-    _t.setExitCallback([](long t) { us_parsing.log(t); });
+    STAT_TIMER(t0, "us_timer_caching_parse_file");
 
     int code;
     std::string cache_fn = std::string(fn) + "c";

src/codegen/unwinding.cpp

@@ -494,6 +494,7 @@ void unwindPythonStack(std::function<bool(std::unique_ptr<PythonFrameIteratorImp
 }
 
 static std::unique_ptr<PythonFrameIteratorImpl> getTopPythonFrame() {
+    STAT_TIMER(t0, "us_timer_getTopPythonFrame");
     std::unique_ptr<PythonFrameIteratorImpl> rtn(nullptr);
     unwindPythonStack([&](std::unique_ptr<PythonFrameIteratorImpl> iter) {
         rtn = std::move(iter);
@@ -512,8 +513,8 @@ 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) {
         static bool printed_warning = false;
         if (!printed_warning) {
@@ -532,8 +533,6 @@ 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());
@@ -544,9 +543,6 @@ 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,9 +22,108 @@
 namespace pyston {
 
 #if !DISABLE_STATS
-std::vector<long>* Stats::counts;
+extern "C" const char* getStatTimerNameById(int id) {
+    return Stats::getStatName(id).c_str();
+}
+
+extern "C" int getStatTimerId() {
+    return StatTimer::getStack()->getId();
+}
+
+extern "C" const char* getStatTimerName() {
+    return getStatTimerNameById(getStatTimerId());
+}
+
+__thread StatTimer* StatTimer::stack;
+StatTimer::StatTimer(int statid, bool push) {
+    uint64_t at_time = getCPUTicks();
+    _duration = 0;
+    _start_time = 0;
+    _statid = statid;
+
+    if (!push) {
+        _prev = NULL;
+        return;
+    }
+
+    _prev = stack;
+    stack = this;
+    if (_prev) {
+        _prev->pause(at_time);
+    }
+    resume(at_time);
+}
+
+StatTimer::StatTimer(int statid, uint64_t at_time) {
+    _duration = 0;
+    _start_time = 0;
+    _statid = statid;
+    _prev = stack;
+    stack = this;
+    if (_prev) {
+        _prev->pause(at_time);
+    }
+    resume(at_time);
+}
+
+StatTimer::~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;
+    }
+
+    stack = _prev;
+    if (stack) {
+        stack->resume(at_time);
+    }
+}
+
+void StatTimer::pause(uint64_t at_time) {
+    assert(!isPaused());
+    assert(at_time > _start_time);
+    auto cur_duration = _duration;
+    _duration = at_time - _start_time;
+    assert(_duration > cur_duration);
+
+    Stats::log(_statid, _duration);
+
+    _duration = 0;
+    _start_time = 0;
+    _last_pause_time = at_time;
+    // fprintf (stderr, "paused  %d at %lu\n", _statid, at_time);
+}
+
+void StatTimer::resume(uint64_t at_time) {
+    assert(isPaused());
+    _start_time = at_time;
+    // fprintf (stderr, "resumed %d at %lu\n", _statid, at_time);
+}
+
+StatTimer* StatTimer::swapStack(StatTimer* s, uint64_t at_time) {
+    StatTimer* prev_stack = stack;
+    if (stack) {
+        stack->pause(at_time);
+    }
+    stack = s;
+    if (stack) {
+        stack->resume(at_time);
+    }
+    return prev_stack;
+}
+
+std::vector<uint64_t>* Stats::counts;
 std::unordered_map<int, std::string>* Stats::names;
 bool Stats::enabled;
+
+timespec Stats::start_ts;
+uint64_t Stats::start_tick;
+
 StatCounter::StatCounter(const std::string& name) : id(Stats::getStatId(name)) {
 }
 
@@ -38,7 +137,7 @@ int Stats::getStatId(const std::string& name) {
     // hacky but easy way of getting around static constructor ordering issues for now:
     static std::unordered_map<int, std::string> names;
     Stats::names = &names;
-    static std::vector<long> counts;
+    static std::vector<uint64_t> counts;
     Stats::counts = &counts;
     static std::unordered_map<std::string, int> made;
 
@@ -52,11 +151,36 @@ int Stats::getStatId(const std::string& name) {
     return rtn;
 }
 
+std::string Stats::getStatName(int id) {
+    return (*names)[id];
+}
+
+void Stats::startEstimatingCPUFreq() {
+    if (!Stats::enabled)
+        return;
+
+    clock_gettime(CLOCK_REALTIME, &Stats::start_ts);
+    Stats::start_tick = getCPUTicks();
+}
+
+// returns our estimate of the MHz of the cpu.  MHz is handy because we're mostly interested in microsoecond-resolution
+// timing.
+double Stats::estimateCPUFreq() {
+    timespec dump_ts;
+    clock_gettime(CLOCK_REALTIME, &dump_ts);
+    uint64_t end_tick = getCPUTicks();
+
+    uint64_t wall_clock_ns = (dump_ts.tv_sec - start_ts.tv_sec) * 1000000000 + (dump_ts.tv_nsec - start_ts.tv_nsec);
+    return (double)(end_tick - Stats::start_tick) * 1000 / wall_clock_ns;
+}
+
 void Stats::dump(bool includeZeros) {
     if (!Stats::enabled)
         return;
 
+    double cycles_per_us = Stats::estimateCPUFreq();
     fprintf(stderr, "Stats:\n");
+    fprintf(stderr, "estimated_cpu_mhz: %5.5f\n", cycles_per_us);
 
     gc::dumpHeapStatistics(0);
 
@@ -69,11 +193,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++) {
-        if (includeZeros || (*counts)[pairs[i].second] > 0)
-            fprintf(stderr, "%s: %ld\n", pairs[i].first.c_str(), (*counts)[pairs[i].second]);
+        if (includeZeros || (*counts)[pairs[i].second] > 0) {
+            if (startswith(pairs[i].first, "us_") || startswith(pairs[i].first, "_init_us_")) {
+                fprintf(stderr, "%s: %lu\n", pairs[i].first.c_str(),
+                        (uint64_t)((*counts)[pairs[i].second] / cycles_per_us));
+
+            } else
+                fprintf(stderr, "%s: %lu\n", pairs[i].first.c_str(), (*counts)[pairs[i].second]);
+
+            if (startswith(pairs[i].first, "us_timer_"))
+                accumulated_stat_timer_ticks += (*counts)[pairs[i].second];
+
+            if (pairs[i].first == "ticks_in_main")
+                ticks_in_main = (*counts)[pairs[i].second];
+        }
     }
 
+    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/stats.h

@@ -22,23 +22,48 @@
 #include <vector>
 
 #include "core/options.h"
+#include "core/util.h"
 
 namespace pyston {
 
+#define STAT_ALLOCATIONS 0
+
+
 #define DISABLE_STATS 0
 
+#if !DISABLE_STATS
+#define STAT_TIMER(id, name)                                                                                           \
+    static int _stid##id = Stats::getStatId(name);                                                                     \
+    StatTimer _st##id(_stid##id)
+#define STAT_TIMER2(id, name, at_time)                                                                                 \
+    static int _stid##id = Stats::getStatId(name);                                                                     \
+    StatTimer _st##id(_stid##id, at_time)
+#else
+#define STAT_TIMER(id, name) StatTimer _st##id(0);
+#define STAT_TIMER2(id, name, at_time) StatTimer _st##id(0);
+#endif
+
+#define STAT_TIMER_NAME(id) _st##id
+
 #if !DISABLE_STATS
 struct Stats {
 private:
-    static std::vector<long>* counts;
+    static std::vector<uint64_t>* counts;
     static std::unordered_map<int, std::string>* names;
     static bool enabled;
 
+    static timespec start_ts;
+    static uint64_t start_tick;
+
 public:
+    static void startEstimatingCPUFreq();
+    static double estimateCPUFreq();
+
     static int getStatId(const std::string& name);
+    static std::string getStatName(int id);
 
     static void setEnabled(bool enabled) { Stats::enabled = enabled; }
-    static void log(int id, int count = 1) { (*counts)[id] += count; }
+    static void log(int id, uint64_t count = 1) { (*counts)[id] += count; }
 
     static void clear() { std::fill(counts->begin(), counts->end(), 0); }
     static void dump(bool includeZeros = true);
@@ -52,7 +77,41 @@ private:
 public:
     StatCounter(const std::string& name);
 
-    void log(int count = 1) { Stats::log(id, count); }
+    void log(uint64_t count = 1) { Stats::log(id, count); }
+};
+
+class StatTimer {
+private:
+    static __thread StatTimer* stack;
+
+    // the accumulated active duration of this timer
+    uint64_t _duration;
+
+    // the start time of the current active segment (0 == paused)
+    uint64_t _start_time;
+
+    uint64_t _last_pause_time;
+
+    StatTimer* _prev;
+
+    int _statid;
+
+public:
+    StatTimer(int statid, bool push = true);
+    StatTimer(int statid, uint64_t at_time);
+    ~StatTimer();
+
+    void pause(uint64_t at_time);
+    void resume(uint64_t at_time);
+
+    bool isPaused() const { return _start_time == 0; }
+    int getId() const { return _statid; }
+
+    static StatTimer* getStack() { return stack; }
+
+    static StatTimer* swapStack(StatTimer* s, uint64_t at_time);
+
+    static void assertActive() { RELEASE_ASSERT(stack && !stack->isPaused(), ""); }
 };
 
 struct StatPerThreadCounter {
@@ -62,24 +121,40 @@ private:
 public:
     StatPerThreadCounter(const std::string& name);
 
-    void log(int count = 1) { Stats::log(id, count); }
+    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() { printf("(Stats disabled)\n"); }
+    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(int count = 1){};
+    void log(uint64_t count = 1){};
+};
+struct StatTimer {
+    StatTimer(int statid, bool push = true) {}
+    StatTimer(int statid, uint64_t at_time) {}
+    ~StatTimer() {}
+    bool isPaused() const { return false; }
+
+    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 void assertActive() {}
 };
 struct StatPerThreadCounter {
     StatPerThreadCounter(const char* name) {}
-    void log(int count = 1){};
+    void log(uint64_t count = 1){};
 };
 #endif
 }

src/core/types.h

@@ -485,13 +485,26 @@ extern "C" PyObject* PystonType_GenericAlloc(BoxedClass* cls, Py_ssize_t nitems)
         return Box::operator new(size, default_cls);                                                                   \
     }
 
+#if STAT_ALLOCATIONS
+#define ALLOC_STATS(cls)                                                                                               \
+    std::string per_name_alloc_name = "alloc." + std::string(cls->tp_name);                                            \
+    std::string per_name_allocsize_name = "allocsize." + std::string(cls->tp_name);                                    \
+    Stats::log(Stats::getStatId(per_name_alloc_name));                                                                 \
+    Stats::log(Stats::getStatId(per_name_allocsize_name), size);
+#else
+#define ALLOC_STATS(cls)
+#endif
+
+
 // The restrictions on when you can use the SIMPLE (ie fast) variant are encoded as
 // asserts in the 1-arg operator new function:
 #define DEFAULT_CLASS_SIMPLE(default_cls)                                                                              \
     void* operator new(size_t size, BoxedClass * cls) __attribute__((visibility("default"))) {                         \
+        ALLOC_STATS(cls);                                                                                              \
         return Box::operator new(size, cls);                                                                           \
     }                                                                                                                  \
     void* operator new(size_t size) __attribute__((visibility("default"))) {                                           \
+        ALLOC_STATS(default_cls);                                                                                      \
         /* In the simple cases, we can inline the following methods and simplify things a lot:                         \
          * - Box::operator new                                                                                         \
          * - cls->tp_alloc                                                                                             \

src/core/util.cpp

@@ -16,6 +16,9 @@
 
 #include <cstdio>
 #include <cstdlib>
+#include <fstream>
+#include <iostream>
+#include <string>
 
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/FormattedStream.h"
@@ -26,6 +29,11 @@
 
 namespace pyston {
 
+uint64_t getCPUTicks() {
+    unsigned int _unused;
+    return __rdtscp(&_unused);
+}
+
 int Timer::level = 0;
 
 Timer::Timer(const char* desc, long min_usec) : min_usec(min_usec), ended(true) {
@@ -36,7 +44,7 @@ void Timer::restart(const char* newdesc) {
     assert(ended);
 
     desc = newdesc;
-    gettimeofday(&start_time, NULL);
+    start_time = getCPUTicks();
     Timer::level++;
     ended = false;
 }
@@ -46,14 +54,14 @@ void Timer::restart(const char* newdesc, long new_min_usec) {
     restart(newdesc);
 }
 
-long 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(' ');
@@ -70,15 +78,17 @@ long Timer::end() {
                 fflush(stdout);
             }
         }
+        if (ended_at)
+            *ended_at = end;
         ended = true;
-        return us;
+        return duration;
     }
     return -1;
 }
 
 Timer::~Timer() {
     if (!ended) {
-        long t = end();
+        uint64_t t = end();
         if (exit_callback)
             exit_callback(t);
     }

src/core/util.h

@@ -24,30 +24,36 @@
 
 namespace pyston {
 
+uint64_t getCPUTicks();
+
 class Timer {
 private:
     static int level;
-    timeval start_time;
+    uint64_t start_time;
     const char* desc;
     long min_usec;
     bool ended;
-    std::function<void(long)> exit_callback;
+    std::function<void(uint64_t)> exit_callback;
 
 public:
     Timer(const char* desc = NULL, long min_usec = -1);
     ~Timer();
 
-    void setExitCallback(std::function<void(long)> _exit_callback) { exit_callback = _exit_callback; }
+    void setExitCallback(std::function<void(uint64_t)> _exit_callback) { exit_callback = _exit_callback; }
 
     void restart(const char* newdesc, long new_min_usec);
     void restart(const char* newdesc = NULL);
 
-    long end();
-    long split(const char* newdesc = NULL) {
-        long rtn = end();
+    // 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* 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; }
 };
 
 bool startswith(const std::string& s, const std::string& pattern);

src/gc/collector.cpp

@@ -339,13 +339,13 @@ void runCollection() {
     static StatCounter sc("gc_collections");
     sc.log();
 
+    STAT_TIMER(t0, "us_timer_gc_collection");
+
     ncollections++;
 
     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,10 +369,6 @@ 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/gc/gc_alloc.h

@@ -28,7 +28,9 @@ namespace pyston {
 
 namespace gc {
 
+static StatCounter gc_alloc_bytes("zzz_gc_alloc_bytes");
 extern "C" inline void* gc_alloc(size_t bytes, GCKind kind_id) {
+    STAT_TIMER(t0, "us_timer_gc_alloc");
     size_t alloc_bytes = bytes + sizeof(GCAllocation);
 
 #ifndef NVALGRIND
@@ -89,8 +91,10 @@ extern "C" inline void* gc_alloc(size_t bytes, GCKind kind_id) {
 
 // if (VERBOSITY()) printf("Allocated %ld bytes at [%p, %p)\n", bytes, r, (char*)r + bytes);
 #endif
-    // printf("Allocated %p\n", r);
 
+#if STAT_ALLOCATIONS
+    gc_alloc_bytes.log(bytes);
+#endif
 
     return r;
 }
@@ -128,6 +132,10 @@ extern "C" inline void* gc_realloc(void* ptr, size_t bytes) {
         alloc->kind_data = bytes;
     }
 
+#if STAT_ALLOCATIONS
+    gc_alloc_bytes.log(bytes);
+#endif
+
     return rtn;
 }
 

src/jit.cpp

@@ -139,11 +139,19 @@ int handleArg(char code) {
 }
 
 static int main(int argc, char** argv) {
+
     Timer _t("for jit startup");
     // llvm::sys::PrintStackTraceOnErrorSignal();
     // llvm::PrettyStackTraceProgram X(argc, argv);
     llvm::llvm_shutdown_obj Y;
 
+    timespec before_ts, after_ts;
+
+    Timer main_time;
+    int rtncode;
+    {
+        STAT_TIMER2(t0, "us_timer_main_toplevel", main_time.getStartTime());
+
         int code;
         const char* command = NULL;
 
@@ -179,6 +187,8 @@ static int main(int argc, char** argv) {
             }
         }
 
+        Stats::startEstimatingCPUFreq();
+
         const char* fn = NULL;
 
         threading::registerMainThread();
@@ -259,7 +269,7 @@ static int main(int argc, char** argv) {
             } catch (ExcInfo e) {
                 int retcode = 1;
                 (void)handle_toplevel_exn(e, &retcode);
-            Stats::dump();
+                Stats::dump(false);
                 return retcode;
             }
         }
@@ -286,7 +296,7 @@ static int main(int argc, char** argv) {
                 int retcode = 1;
                 (void)handle_toplevel_exn(e, &retcode);
                 if (!force_repl) {
-                Stats::dump();
+                    Stats::dump(false);
                     return retcode;
                 }
             }
@@ -336,7 +346,7 @@ static int main(int argc, char** argv) {
                 } catch (ExcInfo e) {
                     int retcode = 0xdeadbeef; // should never be seen
                     if (handle_toplevel_exn(e, &retcode)) {
-                    Stats::dump();
+                        Stats::dump(false);
                         return retcode;
                     }
                 }
@@ -352,10 +362,17 @@ static int main(int argc, char** argv) {
 
         _t.split("joinRuntime");
 
-    int rtncode = joinRuntime();
+        rtncode = joinRuntime();
         _t.split("finishing up");
 
-    Stats::dump();
+        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);
+        _stt0.pause(main_time_ended_at);
+    }
+    Stats::dump(true);
+
 
     return rtncode;
 }

src/runtime/builtin_modules/builtins.cpp

@@ -303,6 +303,7 @@ 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;
@@ -346,6 +347,7 @@ 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();
@@ -358,6 +360,7 @@ 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();
@@ -365,6 +368,7 @@ 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/dict.cpp

@@ -48,6 +48,7 @@ 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));
 
@@ -56,6 +57,7 @@ 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));
 
@@ -65,6 +67,7 @@ Box* dictCopy(BoxedDict* self) {
 }
 
 Box* dictItems(BoxedDict* self) {
+    STAT_TIMER(t0, "us_timer_dictItems");
     BoxedList* rtn = new BoxedList();
 
     rtn->ensure(self->d.size());
@@ -77,6 +80,7 @@ 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) {
@@ -86,6 +90,7 @@ 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();
@@ -182,6 +187,7 @@ 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));
@@ -306,6 +312,7 @@ 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");
@@ -320,6 +327,7 @@ 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

@@ -86,11 +86,13 @@ 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);
 
         threading::pushGenerator(g, g->stack_begin, g->returnContext);
-
         try {
             RegisterHelper context_registerer(g, __builtin_frame_address(0));
 
@@ -108,6 +110,12 @@ 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 !DISABLE_STATS
+        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);
 }
 
@@ -130,7 +138,21 @@ Box* generatorSend(Box* s, Box* v) {
 
     self->returnValue = v;
     self->running = true;
+
+#if !DISABLE_STATS
+    // 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);
+#endif
+
     swapContext(&self->returnContext, self->context, (intptr_t)self);
+
+#if !DISABLE_STATS
+    // 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());
+#endif
+
     self->running = false;
 
     // propagate exception to the caller

src/runtime/list.cpp

@@ -542,6 +542,8 @@ extern "C" Box* listInsert(BoxedList* self, Box* idx, Box* v) {
 }
 
 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/objmodel.cpp

@@ -125,6 +125,7 @@ static Box* (*callattrInternal3)(Box*, const std::string*, LookupScope, CallRewr
        * (*)(Box*, const std::string*, LookupScope, CallRewriteArgs*, ArgPassSpec, Box*, Box*, Box*))callattrInternal;
 
 size_t PyHasher::operator()(Box* b) const {
+    STAT_TIMER(t0, "us_timer_PyHasher");
     if (b->cls == str_cls) {
         StringHash<char> H;
         auto s = static_cast<BoxedString*>(b);
@@ -138,6 +139,8 @@ size_t PyHasher::operator()(Box* b) const {
 }
 
 bool PyEq::operator()(Box* lhs, Box* rhs) const {
+    STAT_TIMER(t0, "us_timer_PyEq");
+
     if (lhs->cls == rhs->cls) {
         if (lhs->cls == str_cls) {
             return static_cast<BoxedString*>(lhs)->s == static_cast<BoxedString*>(rhs)->s;
@@ -151,6 +154,8 @@ bool PyEq::operator()(Box* lhs, Box* rhs) const {
 }
 
 bool PyLt::operator()(Box* lhs, Box* rhs) const {
+    STAT_TIMER(t0, "us_timer_PyLt");
+
     // TODO fix this
     Box* cmp = compareInternal(lhs, rhs, AST_TYPE::Lt, NULL);
     assert(cmp->cls == bool_cls);
@@ -211,6 +216,7 @@ extern "C" void my_assert(bool b) {
 }
 
 extern "C" bool isSubclass(BoxedClass* child, BoxedClass* parent) {
+    STAT_TIMER(t0, "us_timer_isSubclass");
     return PyType_IsSubtype(child, parent);
 }
 
@@ -476,6 +482,7 @@ const char* getNameOfClass(BoxedClass* cls) {
 }
 
 HiddenClass* HiddenClass::getOrMakeChild(const std::string& attr) {
+    STAT_TIMER(t0, "us_timer_hiddenclass_getOrMakeChild");
     assert(type == NORMAL);
 
     auto it = children.find(attr);
@@ -507,6 +514,8 @@ HiddenClass* HiddenClass::getAttrwrapperChild() {
  * del attr from current HiddenClass, maintaining the order of the remaining attrs
  */
 HiddenClass* HiddenClass::delAttrToMakeHC(const std::string& attr) {
+    STAT_TIMER(t0, "us_timer_hiddenclass_delAttrToMakeHC");
+
     assert(type == NORMAL);
     int idx = getOffset(attr);
     assert(idx >= 0);
@@ -655,8 +664,9 @@ Box* Box::getattr(const std::string& attr, GetattrRewriteArgs* rewrite_args) {
 
         Box* key = boxString(attr);
         auto it = d->d.find(key);
-        if (it == d->d.end())
+        if (it == d->d.end()) {
             return NULL;
+        }
         return it->second;
     }
 
@@ -1211,6 +1221,8 @@ Box* getattrInternalEx(Box* obj, const std::string& attr, GetattrRewriteArgs* re
     if (!cls_only) {
         BoxedClass* cls = obj->cls;
         if (obj->cls->tp_getattro && obj->cls->tp_getattro != PyObject_GenericGetAttr) {
+            STAT_TIMER(t0, "us_timer_tp_getattro");
+
             Box* r = obj->cls->tp_getattro(obj, boxString(attr));
             if (!r)
                 throwCAPIException();
@@ -1218,6 +1230,8 @@ Box* getattrInternalEx(Box* obj, const std::string& attr, GetattrRewriteArgs* re
         }
 
         if (obj->cls->tp_getattr) {
+            STAT_TIMER(t0, "us_timer_tp_getattr");
+
             Box* r = obj->cls->tp_getattr(obj, const_cast<char*>(attr.c_str()));
             if (!r)
                 throwCAPIException();
@@ -1242,6 +1256,8 @@ inline Box* getclsattrInternal(Box* obj, const std::string& attr, GetattrRewrite
 }
 
 extern "C" Box* getclsattr(Box* obj, const char* attr) {
+    STAT_TIMER(t0, "us_timer_slowpath_getclsattr");
+
     static StatCounter slowpath_getclsattr("slowpath_getclsattr");
     slowpath_getclsattr.log();
 
@@ -1312,12 +1328,6 @@ Box* processDescriptor(Box* obj, Box* inst, Box* owner) {
 }
 
 
-static Box* (*runtimeCall0)(Box*, ArgPassSpec) = (Box * (*)(Box*, ArgPassSpec))runtimeCall;
-static Box* (*runtimeCall1)(Box*, ArgPassSpec, Box*) = (Box * (*)(Box*, ArgPassSpec, Box*))runtimeCall;
-static Box* (*runtimeCall2)(Box*, ArgPassSpec, Box*, Box*) = (Box * (*)(Box*, ArgPassSpec, Box*, Box*))runtimeCall;
-static Box* (*runtimeCall3)(Box*, ArgPassSpec, Box*, Box*, Box*)
-    = (Box * (*)(Box*, ArgPassSpec, Box*, Box*, Box*))runtimeCall;
-
 Box* getattrInternalGeneric(Box* obj, const std::string& attr, GetattrRewriteArgs* rewrite_args, bool cls_only,
                             bool for_call, Box** bind_obj_out, RewriterVar** r_bind_obj_out) {
     if (for_call) {
@@ -1635,6 +1645,8 @@ Box* getattrInternal(Box* obj, const std::string& attr, GetattrRewriteArgs* rewr
 }
 
 extern "C" Box* getattr(Box* obj, const char* attr) {
+    STAT_TIMER(t0, "us_timer_slowpath_getattr");
+
     static StatCounter slowpath_getattr("slowpath_getattr");
     slowpath_getattr.log();
 
@@ -1845,10 +1857,14 @@ void setattrGeneric(Box* obj, const std::string& attr, Box* val, SetattrRewriteA
 }
 
 extern "C" void setattr(Box* obj, const char* attr, Box* attr_val) {
+    STAT_TIMER(t0, "us_timer_slowpath_setsattr");
+
     static StatCounter slowpath_setattr("slowpath_setattr");
     slowpath_setattr.log();
 
     if (obj->cls->tp_setattr) {
+        STAT_TIMER(t1, "us_timer_tp_setattr");
+
         int rtn = obj->cls->tp_setattr(obj, const_cast<char*>(attr), attr_val);
         if (rtn)
             throwCAPIException();
@@ -1923,6 +1939,7 @@ extern "C" void setattr(Box* obj, const char* attr, Box* attr_val) {
         setattr = processDescriptor(setattr, obj, obj->cls);
         runtimeCallInternal(setattr, NULL, ArgPassSpec(2), boxstr, attr_val, NULL, NULL, NULL);
     } else {
+        STAT_TIMER(t0, "us_timer_tp_setattro");
         int r = tp_setattro(obj, boxstr, attr_val);
         if (r)
             throwCAPIException();
@@ -1935,6 +1952,8 @@ bool isUserDefined(BoxedClass* cls) {
 }
 
 extern "C" bool nonzero(Box* obj) {
+    STAT_TIMER(t0, "us_timer_slowpath_nonzero");
+
     assert(gc::isValidGCObject(obj));
 
     static StatCounter slowpath_nonzero("slowpath_nonzero");
@@ -2009,7 +2028,7 @@ extern "C" bool nonzero(Box* obj) {
         return true;
     }
 
-    Box* r = runtimeCall0(func, ArgPassSpec(0));
+    Box* r = runtimeCallInternal(func, NULL, ArgPassSpec(0), NULL, NULL, NULL, NULL, NULL);
     // I believe this behavior is handled by the slot wrappers in CPython:
     if (r->cls == bool_cls) {
         BoxedBool* b = static_cast<BoxedBool*>(r);
@@ -2025,6 +2044,7 @@ extern "C" bool nonzero(Box* obj) {
 }
 
 extern "C" BoxedString* str(Box* obj) {
+    STAT_TIMER(t0, "us_timer_str");
     static StatCounter slowpath_str("slowpath_str");
     slowpath_str.log();
 
@@ -2046,6 +2066,7 @@ extern "C" BoxedString* str(Box* obj) {
 }
 
 extern "C" Box* strOrUnicode(Box* obj) {
+    STAT_TIMER(t0, "us_timer_strOrUnicode");
     // Like str, but returns unicode objects unchanged.
     if (obj->cls == unicode_cls) {
         return obj;
@@ -2054,6 +2075,7 @@ extern "C" Box* strOrUnicode(Box* obj) {
 }
 
 extern "C" BoxedString* repr(Box* obj) {
+    STAT_TIMER(t0, "us_timer_repr");
     static StatCounter slowpath_repr("slowpath_repr");
     slowpath_repr.log();
 
@@ -2071,6 +2093,7 @@ extern "C" BoxedString* repr(Box* obj) {
 }
 
 extern "C" BoxedString* reprOrNull(Box* obj) {
+    STAT_TIMER(t0, "us_timer_reprOrNull");
     try {
         Box* r = repr(obj);
         assert(r->cls == str_cls); // this should be checked by repr()
@@ -2081,6 +2104,7 @@ extern "C" BoxedString* reprOrNull(Box* obj) {
 }
 
 extern "C" BoxedString* strOrNull(Box* obj) {
+    STAT_TIMER(t0, "us_timer_strOrNull");
     try {
         BoxedString* r = str(obj);
         return static_cast<BoxedString*>(r);
@@ -2090,6 +2114,7 @@ extern "C" BoxedString* strOrNull(Box* obj) {
 }
 
 extern "C" bool exceptionMatches(Box* obj, Box* cls) {
+    STAT_TIMER(t0, "us_timer_exceptionMatches");
     int rtn = PyErr_GivenExceptionMatches(obj, cls);
     RELEASE_ASSERT(rtn >= 0, "");
     return rtn;
@@ -2114,7 +2139,7 @@ extern "C" BoxedInt* hash(Box* obj) {
         raiseExcHelper(TypeError, "unhashable type: '%s'", obj->cls->tp_name);
     }
 
-    Box* rtn = runtimeCall0(hash, ArgPassSpec(0));
+    Box* rtn = runtimeCallInternal(hash, NULL, ArgPassSpec(0), NULL, NULL, NULL, NULL, NULL);
     if (rtn->cls != int_cls) {
         raiseExcHelper(TypeError, "an integer is required");
     }
@@ -2167,6 +2192,8 @@ Box* lenCallInternal(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, Arg
 }
 
 extern "C" BoxedInt* len(Box* obj) {
+    STAT_TIMER(t0, "us_timer_slowpath_len");
+
     static StatCounter slowpath_len("slowpath_len");
     slowpath_len.log();
 
@@ -2174,6 +2201,8 @@ extern "C" BoxedInt* len(Box* obj) {
 }
 
 extern "C" i64 unboxedLen(Box* obj) {
+    STAT_TIMER(t0, "us_timer_slowpath_unboxedLen");
+
     static StatCounter slowpath_unboxedlen("slowpath_unboxedlen");
     slowpath_unboxedlen.log();
 
@@ -2515,6 +2544,8 @@ extern "C" Box* callattrInternal(Box* obj, const std::string* attr, LookupScope
 
 extern "C" Box* callattr(Box* obj, const std::string* attr, CallattrFlags flags, ArgPassSpec argspec, Box* arg1,
                          Box* arg2, Box* arg3, Box** args, const std::vector<const std::string*>* keyword_names) {
+    STAT_TIMER(t0, "us_timer_slowpath_callattr");
+
     ASSERT(gc::isValidGCObject(obj), "%p", obj);
 
     int npassed_args = argspec.totalPassed();
@@ -2704,6 +2735,9 @@ 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
+    StatTimer::assertActive();
+#endif
     /*
      * Procedure:
      * - First match up positional arguments; any extra go to varargs.  error if too many.
@@ -3050,12 +3084,26 @@ Box* callFunc(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, ArgPassSpe
     return res;
 }
 
+static Box* callChosenCF(CompiledFunction* chosen_cf, BoxedClosure* closure, BoxedGenerator* generator, Box* oarg1,
+                         Box* oarg2, Box* oarg3, Box** oargs) {
+    if (closure && generator)
+        return chosen_cf->closure_generator_call(closure, generator, oarg1, oarg2, oarg3, oargs);
+    else if (closure)
+        return chosen_cf->closure_call(closure, oarg1, oarg2, oarg3, oargs);
+    else if (generator)
+        return chosen_cf->generator_call(generator, oarg1, oarg2, oarg3, oargs);
+    else
+        return chosen_cf->call(oarg1, oarg2, oarg3, oargs);
+}
+
 Box* callCLFunc(CLFunction* f, CallRewriteArgs* rewrite_args, int num_output_args, BoxedClosure* closure,
                 BoxedGenerator* generator, Box* globals, Box* oarg1, Box* oarg2, Box* oarg3, Box** oargs) {
     CompiledFunction* chosen_cf = pickVersion(f, num_output_args, oarg1, oarg2, oarg3, oargs);
 
     assert(chosen_cf->is_interpreted == (chosen_cf->code == NULL));
     if (chosen_cf->is_interpreted) {
+        STAT_TIMER(t0, "us_timer_astInterpretFunction");
+
         return astInterpretFunction(chosen_cf, num_output_args, closure, generator, globals, oarg1, oarg2, oarg3,
                                     oargs);
     }
@@ -3084,18 +3132,21 @@ Box* callCLFunc(CLFunction* f, CallRewriteArgs* rewrite_args, int num_output_arg
     }
 
     Box* r;
-    if (closure && generator)
-        r = chosen_cf->closure_generator_call(closure, generator, oarg1, oarg2, oarg3, oargs);
-    else if (closure)
-        r = chosen_cf->closure_call(closure, oarg1, oarg2, oarg3, oargs);
-    else if (generator)
-        r = chosen_cf->generator_call(generator, oarg1, oarg2, oarg3, oargs);
-    else
-        r = chosen_cf->call(oarg1, oarg2, oarg3, oargs);
+    // we duplicate the call to callChosenCf here so we can
+    // distinguish lexically between calls that target jitted python
+    // code and calls that target to builtins.
+    if (f->source) {
+        STAT_TIMER(t0, "us_timer_chosen_cf_body_jitted");
+        r = callChosenCF(chosen_cf, closure, generator, oarg1, oarg2, oarg3, oargs);
+    } else {
+        STAT_TIMER(t0, "us_timer_chosen_cf_body_builtins");
+        r = callChosenCF(chosen_cf, closure, generator, oarg1, oarg2, oarg3, oargs);
+    }
 
     ASSERT(chosen_cf->spec->rtn_type->isFitBy(r->cls), "%s (%p) was supposed to return %s, but gave a %s",
            g.func_addr_registry.getFuncNameAtAddress(chosen_cf->code, true, NULL).c_str(), chosen_cf->code,
            chosen_cf->spec->rtn_type->debugName().c_str(), r->cls->tp_name);
+
     return r;
 }
 
@@ -3225,7 +3276,7 @@ Box* runtimeCallInternal(Box* obj, CallRewriteArgs* rewrite_args, ArgPassSpec ar
             Box** new_args = (Box**)alloca(sizeof(Box*) * (npassed_args + 1 - 3));
             new_args[0] = arg3;
             memcpy(new_args + 1, args, (npassed_args - 3) * sizeof(Box*));
-            Box* rtn = runtimeCall(im->func, ArgPassSpec(argspec.num_args + 1, argspec.num_keywords,
+            Box* rtn = runtimeCallInternal(im->func, NULL, ArgPassSpec(argspec.num_args + 1, argspec.num_keywords,
                                                                        argspec.has_starargs, argspec.has_kwargs),
                                            im->obj, arg1, arg2, new_args, keyword_names);
             return rtn;
@@ -3237,6 +3288,8 @@ Box* runtimeCallInternal(Box* obj, CallRewriteArgs* rewrite_args, ArgPassSpec ar
 
 extern "C" Box* runtimeCall(Box* obj, ArgPassSpec argspec, Box* arg1, Box* arg2, Box* arg3, Box** args,
                             const std::vector<const std::string*>* keyword_names) {
+    STAT_TIMER(t0, "us_timer_slowpath_runtimecall");
+
     int npassed_args = argspec.totalPassed();
 
     static StatCounter slowpath_runtimecall("slowpath_runtimecall");
@@ -3394,6 +3447,8 @@ extern "C" Box* binopInternal(Box* lhs, Box* rhs, int op_type, bool inplace, Bin
 }
 
 extern "C" Box* binop(Box* lhs, Box* rhs, int op_type) {
+    STAT_TIMER(t0, "us_timer_slowpath_binop");
+
     static StatCounter slowpath_binop("slowpath_binop");
     slowpath_binop.log();
     // static StatCounter nopatch_binop("nopatch_binop");
@@ -3430,11 +3485,13 @@ extern "C" Box* binop(Box* lhs, Box* rhs, int op_type) {
 }
 
 extern "C" Box* augbinop(Box* lhs, Box* rhs, int op_type) {
-    static StatCounter slowpath_binop("slowpath_binop");
-    slowpath_binop.log();
-    // static StatCounter nopatch_binop("nopatch_binop");
+    STAT_TIMER(t0, "us_timer_slowpath_augbinop");
 
-    // int id = Stats::getStatId("slowpath_binop_" + *getTypeName(lhs) + op_name + *getTypeName(rhs));
+    static StatCounter slowpath_augbinop("slowpath_augbinop");
+    slowpath_augbinop.log();
+    // static StatCounter nopatch_binop("nopatch_augbinop");
+
+    // int id = Stats::getStatId("slowpath_augbinop_" + *getTypeName(lhs) + op_name + *getTypeName(rhs));
     // Stats::log(id);
 
     std::unique_ptr<Rewriter> rewriter((Rewriter*)NULL);
@@ -3597,6 +3654,8 @@ Box* compareInternal(Box* lhs, Box* rhs, int op_type, CompareRewriteArgs* rewrit
 }
 
 extern "C" Box* compare(Box* lhs, Box* rhs, int op_type) {
+    STAT_TIMER(t0, "us_timer_slowpath_compare");
+
     static StatCounter slowpath_compare("slowpath_compare");
     slowpath_compare.log();
     static StatCounter nopatch_compare("nopatch_compare");
@@ -3622,6 +3681,8 @@ extern "C" Box* compare(Box* lhs, Box* rhs, int op_type) {
 }
 
 extern "C" Box* unaryop(Box* operand, int op_type) {
+    STAT_TIMER(t0, "us_timer_slowpath_unaryop");
+
     static StatCounter slowpath_unaryop("slowpath_unaryop");
     slowpath_unaryop.log();
 
@@ -3631,11 +3692,13 @@ extern "C" Box* unaryop(Box* operand, int op_type) {
 
     ASSERT(attr_func, "%s.%s", getTypeName(operand), op_name.c_str());
 
-    Box* rtn = runtimeCall0(attr_func, ArgPassSpec(0));
+    Box* rtn = runtimeCallInternal(attr_func, NULL, ArgPassSpec(0), NULL, NULL, NULL, NULL, NULL);
     return rtn;
 }
 
 extern "C" Box* getitem(Box* value, Box* slice) {
+    STAT_TIMER(t0, "us_timer_slowpath_getitem");
+
     // This possibly could just be represented as a single callattr; the only tricky part
     // are the error messages.
     // Ex "(1)[1]" and "(1).__getitem__(1)" give different error messages.
@@ -3679,6 +3742,8 @@ extern "C" Box* getitem(Box* value, Box* slice) {
 
 // target[slice] = value
 extern "C" void setitem(Box* target, Box* slice, Box* value) {
+    STAT_TIMER(t0, "us_timer_slowpath_setitem");
+
     static StatCounter slowpath_setitem("slowpath_setitem");
     slowpath_setitem.log();
 
@@ -3711,6 +3776,8 @@ extern "C" void setitem(Box* target, Box* slice, Box* value) {
 
 // del target[start:end:step]
 extern "C" void delitem(Box* target, Box* slice) {
+    STAT_TIMER(t0, "us_timer_slowpath_delitem");
+
     static StatCounter slowpath_delitem("slowpath_delitem");
     slowpath_delitem.log();
 
@@ -3793,7 +3860,7 @@ extern "C" void delattrGeneric(Box* obj, const std::string& attr, DelattrRewrite
 
         if (delAttr != NULL) {
             Box* boxstr = boxString(attr);
-            Box* rtn = runtimeCall2(delAttr, ArgPassSpec(2), clsAttr, obj);
+            Box* rtn = runtimeCallInternal(delAttr, NULL, ArgPassSpec(2), clsAttr, obj, NULL, NULL, NULL);
             return;
         }
     }
@@ -3841,7 +3908,7 @@ extern "C" void delattrInternal(Box* obj, const std::string& attr, DelattrRewrit
     Box* delAttr = typeLookup(obj->cls, delattr_str, NULL);
     if (delAttr != NULL) {
         Box* boxstr = boxString(attr);
-        Box* rtn = runtimeCall2(delAttr, ArgPassSpec(2), obj, boxstr);
+        Box* rtn = runtimeCallInternal(delAttr, NULL, ArgPassSpec(2), obj, boxstr, NULL, NULL, NULL);
         return;
     }
 
@@ -3850,6 +3917,8 @@ extern "C" void delattrInternal(Box* obj, const std::string& attr, DelattrRewrit
 
 // del target.attr
 extern "C" void delattr(Box* obj, const char* attr) {
+    STAT_TIMER(t0, "us_timer_slowpath_delattr");
+
     static StatCounter slowpath_delattr("slowpath_delattr");
     slowpath_delattr.log();
 
@@ -3869,6 +3938,8 @@ extern "C" Box* createBoxedIterWrapper(Box* o) {
 }
 
 extern "C" Box* createBoxedIterWrapperIfNeeded(Box* o) {
+    STAT_TIMER(t0, "us_timer_slowpath_createBoxedIterWrapperIfNeeded");
+
     std::unique_ptr<Rewriter> rewriter(Rewriter::createRewriter(
         __builtin_extract_return_addr(__builtin_return_address(0)), 1, "createBoxedIterWrapperIfNeeded"));
 
@@ -3901,6 +3972,8 @@ extern "C" Box* createBoxedIterWrapperIfNeeded(Box* o) {
 }
 
 extern "C" Box* getPystonIter(Box* o) {
+    STAT_TIMER(t0, "us_timer_slowpath_getPystonIter");
+
     Box* r = getiter(o);
     // assert((typeLookup(r->cls, hasnext_str, NULL) == NULL) == (r->cls->tpp_hasnext == object_cls->tpp_hasnext));
     if (r->cls->tpp_hasnext == object_cls->tpp_hasnext)
@@ -3938,6 +4011,9 @@ static void assertInitNone(Box* obj) {
 }
 
 Box* typeNew(Box* _cls, Box* arg1, Box* arg2, Box** _args) {
+
+    STAT_TIMER(t0, "us_timer_typeNew");
+
     Box* arg3 = _args[0];
 
     if (!isSubclass(_cls->cls, type_cls))
@@ -4391,6 +4467,8 @@ extern "C" void delGlobal(Box* globals, const std::string* name) {
 }
 
 extern "C" Box* getGlobal(Box* globals, const std::string* name) {
+    STAT_TIMER(t0, "us_timer_slowpath_getglobal");
+
     static StatCounter slowpath_getglobal("slowpath_getglobal");
     slowpath_getglobal.log();
     static StatCounter nopatch_getglobal("nopatch_getglobal");
@@ -4485,6 +4563,8 @@ extern "C" Box* getGlobal(Box* globals, const std::string* name) {
 }
 
 extern "C" Box* importFrom(Box* _m, const std::string* name) {
+    STAT_TIMER(t0, "us_timer_importFrom");
+
     Box* r = getattrInternal(_m, *name, NULL);
     if (r)
         return r;
@@ -4493,6 +4573,8 @@ extern "C" Box* importFrom(Box* _m, const std::string* name) {
 }
 
 extern "C" Box* importStar(Box* _from_module, BoxedModule* to_module) {
+    STAT_TIMER(t0, "us_timer_importStar");
+
     // TODO(kmod): it doesn't seem too bad to update this to take custom globals;
     // it looks like mostly a matter of changing the getattr calls to getitem.
     RELEASE_ASSERT(getGlobals() == to_module, "importStar doesn't support custom globals yet");

src/runtime/stacktrace.cpp

@@ -96,6 +96,7 @@ void unwindExc(Box* exc_obj) {
 
 void raiseRaw(const ExcInfo& e) __attribute__((__noreturn__));
 void raiseRaw(const ExcInfo& e) {
+    STAT_TIMER(t0, "us_timer_raiseraw");
     // Should set these to None before getting here:
     assert(e.type);
     assert(e.value);

src/runtime/str.cpp

@@ -1112,6 +1112,7 @@ 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;
@@ -1514,6 +1515,7 @@ failed:
 }
 
 extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) {
+    STAT_TIMER(t0, "us_timer_unicodeHashUnboxed");
     if (self->hash != -1)
         return self->hash;
 
@@ -1524,6 +1526,7 @@ 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

@@ -168,6 +168,7 @@ 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));
     }
@@ -337,6 +338,7 @@ Box* tupleIndex(BoxedTuple* self, Box* elt) {
 }
 
 Box* tupleHash(BoxedTuple* self) {
+    STAT_TIMER(t0, "us_timer_tupleHash");
     assert(isSubclass(self->cls, tuple_cls));
 
     int64_t rtn = 3527539;

src/runtime/types.cpp

@@ -1238,6 +1238,8 @@ 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);
 
@@ -1250,6 +1252,7 @@ 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);
 
@@ -1265,6 +1268,7 @@ 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);
 
@@ -1279,6 +1283,7 @@ 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);
 
@@ -1312,6 +1317,7 @@ 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);
 
@@ -1377,6 +1383,7 @@ 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);
 
@@ -1391,6 +1398,7 @@ 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);
 
@@ -1429,6 +1437,7 @@ public:
     }
 
     static Box* update(Box* _self, Box* _container) {
+        STAT_TIMER(t0, "us_timer_AttrWrapper_update");
         RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
         AttrWrapper* self = static_cast<AttrWrapper*>(_self);
 

src/runtime/types.h

@@ -410,12 +410,37 @@ public:
     size_t size() { return s.size(); }
 
     void* operator new(size_t size, size_t ssize) __attribute__((visibility("default"))) {
+#if STAT_ALLOCATIONS
+        static StatCounter alloc_str("alloc.str");
+        static StatCounter alloc_str1("alloc.str(1)");
+        static StatCounter allocsize_str("allocsize.str");
+
+        if (ssize == 1)
+            alloc_str1.log();
+        else
+            alloc_str.log();
+
+        allocsize_str.log(str_cls->tp_basicsize + ssize + 1);
+#endif
         Box* rtn = static_cast<Box*>(gc_alloc(str_cls->tp_basicsize + ssize + 1, gc::GCKind::PYTHON));
         rtn->cls = str_cls;
         return rtn;
     }
 
     void* operator new(size_t size, BoxedClass* cls, size_t ssize) __attribute__((visibility("default"))) {
+#if STAT_ALLOCATIONS
+        static StatCounter alloc_str("alloc.str");
+        static StatCounter alloc_str1("alloc.str(1)");
+
+        static StatCounter allocsize_str("allocsize.str");
+
+        if (ssize == 1)
+            alloc_str1.log();
+        else
+            alloc_str.log();
+
+        allocsize_str.log(cls->tp_basicsize + ssize + 1);
+#endif
         Box* rtn = static_cast<Box*>(cls->tp_alloc(cls, ssize + 1));
         rtn->cls = cls;
         return rtn;
@@ -517,12 +542,43 @@ public:
     Box** elts;
 
     void* operator new(size_t size, size_t nelts) __attribute__((visibility("default"))) {
+#if STAT_ALLOCATIONS
+        static StatCounter alloc_tuple("alloc.tuple");
+        static StatCounter alloc_tuple0("alloc.tuple(0)");
+
+        static StatCounter allocsize_tuple("allocsize.tuple");
+        static StatCounter allocsize_tuple0("allocsize.tuple(0)");
+
+        if (nelts == 0) {
+            alloc_tuple0.log();
+            allocsize_tuple0.log(_PyObject_VAR_SIZE(tuple_cls, nelts + 1));
+        } else {
+            alloc_tuple.log();
+            allocsize_tuple.log(_PyObject_VAR_SIZE(tuple_cls, nelts + 1));
+        }
+#endif
+
         Box* rtn = static_cast<Box*>(gc_alloc(_PyObject_VAR_SIZE(tuple_cls, nelts + 1), gc::GCKind::PYTHON));
         rtn->cls = tuple_cls;
         return rtn;
     }
 
     void* operator new(size_t size, BoxedClass* cls, size_t nelts) __attribute__((visibility("default"))) {
+#if STAT_ALLOCATIONS
+        static StatCounter alloc_tuple("alloc.tuple");
+        static StatCounter alloc_tuple0("alloc.tuple(0)");
+
+        static StatCounter allocsize_tuple("allocsize.tuple");
+        static StatCounter allocsize_tuple0("allocsize.tuple(0)");
+
+        if (nelts == 0) {
+            alloc_tuple0.log();
+            allocsize_tuple0.log(_PyObject_VAR_SIZE(cls, nelts + 1));
+        } else {
+            alloc_tuple.log();
+            allocsize_tuple.log(_PyObject_VAR_SIZE(cls, nelts + 1));
+        }
+#endif
         Box* rtn = static_cast<Box*>(cls->tp_alloc(cls, nelts));
         rtn->cls = cls;
         return rtn;
@@ -817,6 +873,11 @@ public:
     struct Context* context, *returnContext;
     void* stack_begin;
 
+#if !DISABLE_STATS
+    StatTimer* statTimers;
+    uint64_t timer_time;
+#endif
+
     BoxedGenerator(BoxedFunctionBase* function, Box* arg1, Box* arg2, Box* arg3, Box** args);
 
     DEFAULT_CLASS(generator_cls);