Commit addbe087 authored by Chris Toshok's avatar Chris Toshok

add StatTimer, a lightweight cpu tick timer

Each thread has a stack of timers (which should have automatic scope.)  pushing a timer
onto the stack pauses the currently running one to avoid double counting, and popping a
timer resumes the previous one.

also make sure we pause the current timer, and swap out the current stack of timers when
swapping to/from generator stacks, since otherwise pushes/pops won't line up and we hit
asserts in StatTimer.

Timers and StatTimers accumulate their durations in terms of CPU ticks, which are converted
to microseconds only at Stats::dump() time, calculated with our estimate of CPU frequency.
Needless to say, this only works when there is no CPU stepping/scaling.

There are some additions to the Timer class that allow us to get the start/end time so that
we can sync up StatTimers with them, if both are used in a given piece of code.

getCPUTicks() is only implemented using __rdtscp() at the moment, so won't work on anything
not recent relatively recent x86.

we accumulate total ticks during dumping and output both 'ticks_in_main' and 'ticks_all_timers',
which should be equal.
parent 68e9e5f1
...@@ -18,6 +18,7 @@ ...@@ -18,6 +18,7 @@
namespace pyston { namespace pyston {
Box* BoxedMethodDescriptor::__call__(BoxedMethodDescriptor* self, Box* obj, BoxedTuple* varargs, Box** _args) { 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]); BoxedDict* kwargs = static_cast<BoxedDict*>(_args[0]);
assert(self->cls == method_cls); assert(self->cls == method_cls);
......
...@@ -58,6 +58,7 @@ static int hackcheck(PyObject* self, setattrofunc func, const char* what) noexce ...@@ -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 { static PyObject* wrap_setattr(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_setattr");
setattrofunc func = (setattrofunc)wrapped; setattrofunc func = (setattrofunc)wrapped;
int res; int res;
PyObject* name, *value; PyObject* name, *value;
...@@ -74,6 +75,7 @@ static PyObject* wrap_setattr(PyObject* self, PyObject* args, void* wrapped) noe ...@@ -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 { static PyObject* wrap_delattr(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_delattr");
setattrofunc func = (setattrofunc)wrapped; setattrofunc func = (setattrofunc)wrapped;
int res; int res;
PyObject* name; PyObject* name;
...@@ -91,6 +93,7 @@ static PyObject* wrap_delattr(PyObject* self, PyObject* args, void* wrapped) noe ...@@ -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 { static PyObject* wrap_hashfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_hashfunc");
hashfunc func = (hashfunc)wrapped; hashfunc func = (hashfunc)wrapped;
long res; long res;
...@@ -103,12 +106,14 @@ static PyObject* wrap_hashfunc(PyObject* self, PyObject* args, void* wrapped) no ...@@ -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 { static PyObject* wrap_call(PyObject* self, PyObject* args, void* wrapped, PyObject* kwds) noexcept {
STAT_TIMER(t0, "us_timer_wrap_call");
ternaryfunc func = (ternaryfunc)wrapped; ternaryfunc func = (ternaryfunc)wrapped;
return (*func)(self, args, kwds); return (*func)(self, args, kwds);
} }
static PyObject* wrap_richcmpfunc(PyObject* self, PyObject* args, void* wrapped, int op) noexcept { static PyObject* wrap_richcmpfunc(PyObject* self, PyObject* args, void* wrapped, int op) noexcept {
STAT_TIMER(t0, "us_timer_wrap_richcmpfunc");
richcmpfunc func = (richcmpfunc)wrapped; richcmpfunc func = (richcmpfunc)wrapped;
PyObject* other; PyObject* other;
...@@ -132,6 +137,7 @@ RICHCMP_WRAPPER(gt, Py_GT) ...@@ -132,6 +137,7 @@ RICHCMP_WRAPPER(gt, Py_GT)
RICHCMP_WRAPPER(ge, Py_GE) RICHCMP_WRAPPER(ge, Py_GE)
static PyObject* wrap_next(PyObject* self, PyObject* args, void* wrapped) { static PyObject* wrap_next(PyObject* self, PyObject* args, void* wrapped) {
STAT_TIMER(t0, "us_timer_wrap_next");
unaryfunc func = (unaryfunc)wrapped; unaryfunc func = (unaryfunc)wrapped;
PyObject* res; PyObject* res;
...@@ -144,6 +150,7 @@ static PyObject* wrap_next(PyObject* self, PyObject* args, void* wrapped) { ...@@ -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 { static PyObject* wrap_descr_get(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_descr_get");
descrgetfunc func = (descrgetfunc)wrapped; descrgetfunc func = (descrgetfunc)wrapped;
PyObject* obj; PyObject* obj;
PyObject* type = NULL; PyObject* type = NULL;
...@@ -162,6 +169,7 @@ static PyObject* wrap_descr_get(PyObject* self, PyObject* args, void* wrapped) n ...@@ -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 { static PyObject* wrap_coercefunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_coercefunc");
coercion func = (coercion)wrapped; coercion func = (coercion)wrapped;
PyObject* other, *res; PyObject* other, *res;
int ok; int ok;
...@@ -188,6 +196,7 @@ static PyObject* wrap_coercefunc(PyObject* self, PyObject* args, void* wrapped) ...@@ -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 { static PyObject* wrap_ternaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_ternaryfunc");
ternaryfunc func = (ternaryfunc)wrapped; ternaryfunc func = (ternaryfunc)wrapped;
PyObject* other; PyObject* other;
PyObject* third = Py_None; PyObject* third = Py_None;
...@@ -200,6 +209,7 @@ static PyObject* wrap_ternaryfunc(PyObject* self, PyObject* args, void* wrapped) ...@@ -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 { static PyObject* wrap_ternaryfunc_r(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_ternaryfunc_r");
ternaryfunc func = (ternaryfunc)wrapped; ternaryfunc func = (ternaryfunc)wrapped;
PyObject* other; PyObject* other;
PyObject* third = Py_None; PyObject* third = Py_None;
...@@ -212,6 +222,7 @@ static PyObject* wrap_ternaryfunc_r(PyObject* self, PyObject* args, void* wrappe ...@@ -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 { static PyObject* wrap_unaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_unaryfunc");
unaryfunc func = (unaryfunc)wrapped; unaryfunc func = (unaryfunc)wrapped;
if (!check_num_args(args, 0)) if (!check_num_args(args, 0))
...@@ -220,6 +231,7 @@ static PyObject* wrap_unaryfunc(PyObject* self, PyObject* args, void* wrapped) n ...@@ -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 { static PyObject* wrap_inquirypred(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_inquirypred");
inquiry func = (inquiry)wrapped; inquiry func = (inquiry)wrapped;
int res; int res;
...@@ -232,6 +244,7 @@ static PyObject* wrap_inquirypred(PyObject* self, PyObject* args, void* wrapped) ...@@ -232,6 +244,7 @@ static PyObject* wrap_inquirypred(PyObject* self, PyObject* args, void* wrapped)
} }
static PyObject* wrapInquirypred(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; inquiry func = (inquiry)wrapped;
int res; int res;
...@@ -244,6 +257,7 @@ static PyObject* wrapInquirypred(PyObject* self, PyObject* args, void* wrapped) ...@@ -244,6 +257,7 @@ static PyObject* wrapInquirypred(PyObject* self, PyObject* args, void* wrapped)
} }
static PyObject* wrap_binaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept { static PyObject* wrap_binaryfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_binaryfunc");
binaryfunc func = (binaryfunc)wrapped; binaryfunc func = (binaryfunc)wrapped;
PyObject* other; PyObject* other;
...@@ -254,6 +268,7 @@ static PyObject* wrap_binaryfunc(PyObject* self, PyObject* args, void* wrapped) ...@@ -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 { static PyObject* wrap_binaryfunc_l(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_binaryfunc_l");
binaryfunc func = (binaryfunc)wrapped; binaryfunc func = (binaryfunc)wrapped;
PyObject* other; PyObject* other;
...@@ -268,6 +283,7 @@ static PyObject* wrap_binaryfunc_l(PyObject* self, PyObject* args, void* wrapped ...@@ -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 { static PyObject* wrap_binaryfunc_r(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_binaryfunc_r");
binaryfunc func = (binaryfunc)wrapped; binaryfunc func = (binaryfunc)wrapped;
PyObject* other; PyObject* other;
...@@ -300,6 +316,7 @@ static Py_ssize_t getindex(PyObject* self, PyObject* arg) noexcept { ...@@ -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 { static PyObject* wrap_lenfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_lenfunc");
lenfunc func = (lenfunc)wrapped; lenfunc func = (lenfunc)wrapped;
Py_ssize_t res; Py_ssize_t res;
...@@ -312,6 +329,7 @@ static PyObject* wrap_lenfunc(PyObject* self, PyObject* args, void* wrapped) noe ...@@ -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 { static PyObject* wrap_indexargfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_indexargfunc");
ssizeargfunc func = (ssizeargfunc)wrapped; ssizeargfunc func = (ssizeargfunc)wrapped;
PyObject* o; PyObject* o;
Py_ssize_t i; Py_ssize_t i;
...@@ -325,6 +343,7 @@ static PyObject* wrap_indexargfunc(PyObject* self, PyObject* args, void* wrapped ...@@ -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 { static PyObject* wrap_sq_item(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_sq_item");
ssizeargfunc func = (ssizeargfunc)wrapped; ssizeargfunc func = (ssizeargfunc)wrapped;
PyObject* arg; PyObject* arg;
Py_ssize_t i; Py_ssize_t i;
...@@ -342,6 +361,7 @@ static PyObject* wrap_sq_item(PyObject* self, PyObject* args, void* wrapped) noe ...@@ -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 { static PyObject* wrap_ssizessizeargfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_ssizessizeargfunc");
ssizessizeargfunc func = (ssizessizeargfunc)wrapped; ssizessizeargfunc func = (ssizessizeargfunc)wrapped;
Py_ssize_t i, j; Py_ssize_t i, j;
...@@ -351,6 +371,7 @@ static PyObject* wrap_ssizessizeargfunc(PyObject* self, PyObject* args, void* wr ...@@ -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 { static PyObject* wrap_sq_setitem(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_sq_setitem");
ssizeobjargproc func = (ssizeobjargproc)wrapped; ssizeobjargproc func = (ssizeobjargproc)wrapped;
Py_ssize_t i; Py_ssize_t i;
int res; int res;
...@@ -369,6 +390,7 @@ static PyObject* wrap_sq_setitem(PyObject* self, PyObject* args, void* wrapped) ...@@ -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 { static PyObject* wrap_sq_delitem(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_sq_delitem");
ssizeobjargproc func = (ssizeobjargproc)wrapped; ssizeobjargproc func = (ssizeobjargproc)wrapped;
Py_ssize_t i; Py_ssize_t i;
int res; int res;
...@@ -388,6 +410,7 @@ static PyObject* wrap_sq_delitem(PyObject* self, PyObject* args, void* wrapped) ...@@ -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 { static PyObject* wrap_ssizessizeobjargproc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_ssizessizeobjargproc");
ssizessizeobjargproc func = (ssizessizeobjargproc)wrapped; ssizessizeobjargproc func = (ssizessizeobjargproc)wrapped;
Py_ssize_t i, j; Py_ssize_t i, j;
int res; int res;
...@@ -403,6 +426,7 @@ static PyObject* wrap_ssizessizeobjargproc(PyObject* self, PyObject* args, void* ...@@ -403,6 +426,7 @@ static PyObject* wrap_ssizessizeobjargproc(PyObject* self, PyObject* args, void*
} }
static PyObject* wrap_delslice(PyObject* self, PyObject* args, void* wrapped) noexcept { static PyObject* wrap_delslice(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_delslice");
ssizessizeobjargproc func = (ssizessizeobjargproc)wrapped; ssizessizeobjargproc func = (ssizessizeobjargproc)wrapped;
Py_ssize_t i, j; Py_ssize_t i, j;
int res; int res;
...@@ -418,6 +442,7 @@ static PyObject* wrap_delslice(PyObject* self, PyObject* args, void* wrapped) no ...@@ -418,6 +442,7 @@ static PyObject* wrap_delslice(PyObject* self, PyObject* args, void* wrapped) no
/* XXX objobjproc is a misnomer; should be objargpred */ /* XXX objobjproc is a misnomer; should be objargpred */
static PyObject* wrap_objobjproc(PyObject* self, PyObject* args, void* wrapped) noexcept { static PyObject* wrap_objobjproc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_objobjproc");
objobjproc func = (objobjproc)wrapped; objobjproc func = (objobjproc)wrapped;
int res; int res;
PyObject* value; PyObject* value;
...@@ -433,6 +458,7 @@ static PyObject* wrap_objobjproc(PyObject* self, PyObject* args, void* wrapped) ...@@ -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 { static PyObject* wrap_objobjargproc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_objobjargproc");
objobjargproc func = (objobjargproc)wrapped; objobjargproc func = (objobjargproc)wrapped;
int res; int res;
PyObject* key, *value; PyObject* key, *value;
...@@ -447,6 +473,7 @@ static PyObject* wrap_objobjargproc(PyObject* self, PyObject* args, void* wrappe ...@@ -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 { static PyObject* wrap_delitem(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_delitem");
objobjargproc func = (objobjargproc)wrapped; objobjargproc func = (objobjargproc)wrapped;
int res; int res;
PyObject* key; PyObject* key;
...@@ -462,6 +489,7 @@ static PyObject* wrap_delitem(PyObject* self, PyObject* args, void* wrapped) noe ...@@ -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 { static PyObject* wrap_cmpfunc(PyObject* self, PyObject* args, void* wrapped) noexcept {
STAT_TIMER(t0, "us_timer_wrap_cmpfunc");
cmpfunc func = (cmpfunc)wrapped; cmpfunc func = (cmpfunc)wrapped;
int res; int res;
PyObject* other; PyObject* other;
...@@ -482,6 +510,7 @@ static PyObject* wrap_cmpfunc(PyObject* self, PyObject* args, void* wrapped) noe ...@@ -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 { static PyObject* wrap_init(PyObject* self, PyObject* args, void* wrapped, PyObject* kwds) noexcept {
STAT_TIMER(t0, "us_timer_wrap_init");
initproc func = (initproc)wrapped; initproc func = (initproc)wrapped;
if (func(self, args, kwds) < 0) if (func(self, args, kwds) < 0)
......
...@@ -54,6 +54,7 @@ public: ...@@ -54,6 +54,7 @@ public:
} }
static Box* __call__(BoxedCApiFunction* self, BoxedTuple* varargs, BoxedDict* kwargs) { static Box* __call__(BoxedCApiFunction* self, BoxedTuple* varargs, BoxedDict* kwargs) {
STAT_TIMER(t0, "us_timer_boxedcapifunction__call__");
assert(self->cls == capifunc_cls); assert(self->cls == capifunc_cls);
assert(varargs->cls == tuple_cls); assert(varargs->cls == tuple_cls);
assert(kwargs->cls == dict_cls); assert(kwargs->cls == dict_cls);
...@@ -111,6 +112,8 @@ public: ...@@ -111,6 +112,8 @@ public:
DEFAULT_CLASS(wrapperobject_cls); DEFAULT_CLASS(wrapperobject_cls);
static Box* __call__(BoxedWrapperObject* self, Box* args, Box* kwds) { static Box* __call__(BoxedWrapperObject* self, Box* args, Box* kwds) {
STAT_TIMER(t0, "us_timer_boxedwrapperobject__call__");
assert(self->cls == wrapperobject_cls); assert(self->cls == wrapperobject_cls);
assert(args->cls == tuple_cls); assert(args->cls == tuple_cls);
assert(kwds->cls == dict_cls); assert(kwds->cls == dict_cls);
......
...@@ -284,6 +284,8 @@ public: ...@@ -284,6 +284,8 @@ public:
Value ASTInterpreter::execute(ASTInterpreter& interpreter, CFGBlock* start_block, AST_stmt* start_at) { Value ASTInterpreter::execute(ASTInterpreter& interpreter, CFGBlock* start_block, AST_stmt* start_at) {
threading::allowGLReadPreemption(); threading::allowGLReadPreemption();
STAT_TIMER(t0, "us_timer_astinterpreter_execute");
void* frame_addr = __builtin_frame_address(0); void* frame_addr = __builtin_frame_address(0);
RegisterHelper frame_registerer(&interpreter, frame_addr); RegisterHelper frame_registerer(&interpreter, frame_addr);
...@@ -540,6 +542,7 @@ Value ASTInterpreter::visit_jump(AST_Jump* node) { ...@@ -540,6 +542,7 @@ Value ASTInterpreter::visit_jump(AST_Jump* node) {
arg_array.push_back(it.second); arg_array.push_back(it.second);
} }
STAT_TIMER(t0, "us_timer_astinterpreter_jump_osrexit");
CompiledFunction* partial_func = compilePartialFuncInternal(&exit); CompiledFunction* partial_func = compilePartialFuncInternal(&exit);
auto arg_tuple = getTupleFromArgsArray(&arg_array[0], arg_array.size()); 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), 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) { ...@@ -927,6 +930,8 @@ Value ASTInterpreter::visit_print(AST_Print* node) {
static const std::string newline_str("\n"); static const std::string newline_str("\n");
static const std::string space_str(" "); static const std::string space_str(" ");
STAT_TIMER(t0, "us_timer_visit_print");
Box* dest = node->dest ? visit_expr(node->dest).o : getSysStdout(); Box* dest = node->dest ? visit_expr(node->dest).o : getSysStdout();
int nvals = node->values.size(); int nvals = node->values.size();
assert(nvals <= 1 && "cfg should have lowered it to 0 or 1 values"); assert(nvals <= 1 && "cfg should have lowered it to 0 or 1 values");
......
...@@ -362,7 +362,7 @@ static void handle_sigint(int signum) { ...@@ -362,7 +362,7 @@ static void handle_sigint(int signum) {
// For now, just call abort(), so that we get a traceback at least. // For now, just call abort(), so that we get a traceback at least.
fprintf(stderr, "SIGINT!\n"); fprintf(stderr, "SIGINT!\n");
joinRuntime(); joinRuntime();
Stats::dump(); Stats::dump(false);
abort(); abort();
} }
......
...@@ -182,6 +182,7 @@ static void compileIR(CompiledFunction* cf, EffortLevel effort) { ...@@ -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: // The codegen_lock needs to be held in W mode before calling this function:
CompiledFunction* compileFunction(CLFunction* f, FunctionSpecialization* spec, EffortLevel effort, CompiledFunction* compileFunction(CLFunction* f, FunctionSpecialization* spec, EffortLevel effort,
const OSREntryDescriptor* entry_descriptor) { const OSREntryDescriptor* entry_descriptor) {
STAT_TIMER(t0, "us_timer_compileFunction");
Timer _t("for compileFunction()", 1000); Timer _t("for compileFunction()", 1000);
assert((entry_descriptor != NULL) + (spec != NULL) == 1); assert((entry_descriptor != NULL) + (spec != NULL) == 1);
...@@ -315,10 +316,13 @@ void compileAndRunModule(AST_Module* m, BoxedModule* bm) { ...@@ -315,10 +316,13 @@ void compileAndRunModule(AST_Module* m, BoxedModule* bm) {
assert(cf->clfunc->versions.size()); 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); astInterpretFunction(cf, 0, NULL, NULL, NULL, NULL, NULL, NULL, NULL);
else } else {
STAT_TIMER(t1, "us_timer_jitted_module_toplevel");
((void (*)())cf->code)(); ((void (*)())cf->code)();
}
} }
Box* evalOrExec(CLFunction* cl, Box* globals, Box* boxedLocals) { Box* evalOrExec(CLFunction* cl, Box* globals, Box* boxedLocals) {
......
...@@ -982,7 +982,7 @@ AST_Module* parse_string(const char* code) { ...@@ -982,7 +982,7 @@ AST_Module* parse_string(const char* code) {
} }
AST_Module* parse_file(const char* fn) { AST_Module* parse_file(const char* fn) {
Timer _t("parsing"); STAT_TIMER(t0, "us_timer_cpyton_parsing");
if (ENABLE_PYPA_PARSER) { if (ENABLE_PYPA_PARSER) {
AST_Module* rtn = pypa_parse(fn); AST_Module* rtn = pypa_parse(fn);
...@@ -1003,10 +1003,6 @@ AST_Module* parse_file(const char* fn) { ...@@ -1003,10 +1003,6 @@ AST_Module* parse_file(const char* fn) {
assert(rtn->type == AST_TYPE::Module); 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); return ast_cast<AST_Module>(rtn);
} }
...@@ -1071,9 +1067,7 @@ static ParseResult _reparse(const char* fn, const std::string& cache_fn, AST_Mod ...@@ -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 // it's not a huge deal right now, but this caching version can significantly cut down
// on the startup time (40ms -> 10ms). // on the startup time (40ms -> 10ms).
AST_Module* caching_parse_file(const char* fn) { AST_Module* caching_parse_file(const char* fn) {
static StatCounter us_parsing("us_parsing"); STAT_TIMER(t0, "us_timer_caching_parse_file");
Timer _t("parsing");
_t.setExitCallback([](long t) { us_parsing.log(t); });
int code; int code;
std::string cache_fn = std::string(fn) + "c"; std::string cache_fn = std::string(fn) + "c";
......
...@@ -494,6 +494,7 @@ void unwindPythonStack(std::function<bool(std::unique_ptr<PythonFrameIteratorImp ...@@ -494,6 +494,7 @@ void unwindPythonStack(std::function<bool(std::unique_ptr<PythonFrameIteratorImp
} }
static std::unique_ptr<PythonFrameIteratorImpl> getTopPythonFrame() { static std::unique_ptr<PythonFrameIteratorImpl> getTopPythonFrame() {
STAT_TIMER(t0, "us_timer_getTopPythonFrame");
std::unique_ptr<PythonFrameIteratorImpl> rtn(nullptr); std::unique_ptr<PythonFrameIteratorImpl> rtn(nullptr);
unwindPythonStack([&](std::unique_ptr<PythonFrameIteratorImpl> iter) { unwindPythonStack([&](std::unique_ptr<PythonFrameIteratorImpl> iter) {
rtn = std::move(iter); rtn = std::move(iter);
...@@ -512,8 +513,8 @@ static const LineInfo* lineInfoForFrame(PythonFrameIteratorImpl& frame_it) { ...@@ -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()); return new LineInfo(current_stmt->lineno, current_stmt->col_offset, source->fn, source->getName());
} }
static StatCounter us_gettraceback("us_gettraceback");
BoxedTraceback* getTraceback() { BoxedTraceback* getTraceback() {
STAT_TIMER(t0, "us_timer_gettraceback");
if (!ENABLE_FRAME_INTROSPECTION) { if (!ENABLE_FRAME_INTROSPECTION) {
static bool printed_warning = false; static bool printed_warning = false;
if (!printed_warning) { if (!printed_warning) {
...@@ -532,8 +533,6 @@ BoxedTraceback* getTraceback() { ...@@ -532,8 +533,6 @@ BoxedTraceback* getTraceback() {
return new BoxedTraceback(); return new BoxedTraceback();
} }
Timer _t("getTraceback", 1000);
std::vector<const LineInfo*> entries; std::vector<const LineInfo*> entries;
unwindPythonStack([&](std::unique_ptr<PythonFrameIteratorImpl> frame_iter) { unwindPythonStack([&](std::unique_ptr<PythonFrameIteratorImpl> frame_iter) {
const LineInfo* line_info = lineInfoForFrame(*frame_iter.get()); const LineInfo* line_info = lineInfoForFrame(*frame_iter.get());
...@@ -544,9 +543,6 @@ BoxedTraceback* getTraceback() { ...@@ -544,9 +543,6 @@ BoxedTraceback* getTraceback() {
std::reverse(entries.begin(), entries.end()); std::reverse(entries.begin(), entries.end());
long us = _t.end();
us_gettraceback.log(us);
return new BoxedTraceback(std::move(entries)); return new BoxedTraceback(std::move(entries));
} }
......
...@@ -22,9 +22,108 @@ ...@@ -22,9 +22,108 @@
namespace pyston { namespace pyston {
#if !DISABLE_STATS #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; std::unordered_map<int, std::string>* Stats::names;
bool Stats::enabled; bool Stats::enabled;
timespec Stats::start_ts;
uint64_t Stats::start_tick;
StatCounter::StatCounter(const std::string& name) : id(Stats::getStatId(name)) { StatCounter::StatCounter(const std::string& name) : id(Stats::getStatId(name)) {
} }
...@@ -38,7 +137,7 @@ int Stats::getStatId(const std::string& 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: // hacky but easy way of getting around static constructor ordering issues for now:
static std::unordered_map<int, std::string> names; static std::unordered_map<int, std::string> names;
Stats::names = &names; Stats::names = &names;
static std::vector<long> counts; static std::vector<uint64_t> counts;
Stats::counts = &counts; Stats::counts = &counts;
static std::unordered_map<std::string, int> made; static std::unordered_map<std::string, int> made;
...@@ -52,11 +151,36 @@ int Stats::getStatId(const std::string& name) { ...@@ -52,11 +151,36 @@ int Stats::getStatId(const std::string& name) {
return rtn; 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) { void Stats::dump(bool includeZeros) {
if (!Stats::enabled) if (!Stats::enabled)
return; return;
double cycles_per_us = Stats::estimateCPUFreq();
fprintf(stderr, "Stats:\n"); fprintf(stderr, "Stats:\n");
fprintf(stderr, "estimated_cpu_mhz: %5.5f\n", cycles_per_us);
gc::dumpHeapStatistics(0); gc::dumpHeapStatistics(0);
...@@ -69,11 +193,41 @@ void Stats::dump(bool includeZeros) { ...@@ -69,11 +193,41 @@ void Stats::dump(bool includeZeros) {
std::sort(pairs.begin(), pairs.end()); 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++) { for (int i = 0; i < pairs.size(); i++) {
if (includeZeros || (*counts)[pairs[i].second] > 0) if (includeZeros || (*counts)[pairs[i].second] > 0) {
fprintf(stderr, "%s: %ld\n", pairs[i].first.c_str(), (*counts)[pairs[i].second]); 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"); fprintf(stderr, "(End of stats)\n");
} }
......
...@@ -22,23 +22,48 @@ ...@@ -22,23 +22,48 @@
#include <vector> #include <vector>
#include "core/options.h" #include "core/options.h"
#include "core/util.h"
namespace pyston { namespace pyston {
#define STAT_ALLOCATIONS 0
#define DISABLE_STATS 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 #if !DISABLE_STATS
struct Stats { struct Stats {
private: private:
static std::vector<long>* counts; static std::vector<uint64_t>* counts;
static std::unordered_map<int, std::string>* names; static std::unordered_map<int, std::string>* names;
static bool enabled; static bool enabled;
static timespec start_ts;
static uint64_t start_tick;
public: public:
static void startEstimatingCPUFreq();
static double estimateCPUFreq();
static int getStatId(const std::string& name); static int getStatId(const std::string& name);
static std::string getStatName(int id);
static void setEnabled(bool enabled) { Stats::enabled = enabled; } 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 clear() { std::fill(counts->begin(), counts->end(), 0); }
static void dump(bool includeZeros = true); static void dump(bool includeZeros = true);
...@@ -52,7 +77,41 @@ private: ...@@ -52,7 +77,41 @@ private:
public: public:
StatCounter(const std::string& name); 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 { struct StatPerThreadCounter {
...@@ -62,24 +121,40 @@ private: ...@@ -62,24 +121,40 @@ private:
public: public:
StatPerThreadCounter(const std::string& name); 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 #else
struct Stats { struct Stats {
static void startEstimatingCPUFreq() {}
static double estimateCPUFreq() { return 0; }
static void setEnabled(bool enabled) {} 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 void log(int id, int count = 1) {}
static int getStatId(const std::string& name) { return 0; } static int getStatId(const std::string& name) { return 0; }
static void endOfInit() {} static void endOfInit() {}
}; };
struct StatCounter { struct StatCounter {
StatCounter(const char* name) {} 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 { struct StatPerThreadCounter {
StatPerThreadCounter(const char* name) {} StatPerThreadCounter(const char* name) {}
void log(int count = 1){}; void log(uint64_t count = 1){};
}; };
#endif #endif
} }
......
...@@ -16,6 +16,9 @@ ...@@ -16,6 +16,9 @@
#include <cstdio> #include <cstdio>
#include <cstdlib> #include <cstdlib>
#include <fstream>
#include <iostream>
#include <string>
#include "llvm/Support/FileSystem.h" #include "llvm/Support/FileSystem.h"
#include "llvm/Support/FormattedStream.h" #include "llvm/Support/FormattedStream.h"
...@@ -26,6 +29,11 @@ ...@@ -26,6 +29,11 @@
namespace pyston { namespace pyston {
uint64_t getCPUTicks() {
unsigned int _unused;
return __rdtscp(&_unused);
}
int Timer::level = 0; int Timer::level = 0;
Timer::Timer(const char* desc, long min_usec) : min_usec(min_usec), ended(true) { Timer::Timer(const char* desc, long min_usec) : min_usec(min_usec), ended(true) {
...@@ -36,7 +44,7 @@ void Timer::restart(const char* newdesc) { ...@@ -36,7 +44,7 @@ void Timer::restart(const char* newdesc) {
assert(ended); assert(ended);
desc = newdesc; desc = newdesc;
gettimeofday(&start_time, NULL); start_time = getCPUTicks();
Timer::level++; Timer::level++;
ended = false; ended = false;
} }
...@@ -46,14 +54,14 @@ void Timer::restart(const char* newdesc, long new_min_usec) { ...@@ -46,14 +54,14 @@ void Timer::restart(const char* newdesc, long new_min_usec) {
restart(newdesc); restart(newdesc);
} }
long Timer::end() { uint64_t Timer::end(uint64_t* ended_at) {
if (!ended) { if (!ended) {
timeval end; uint64_t end = getCPUTicks();
gettimeofday(&end, NULL); uint64_t duration = end - start_time;
long us = 1000000L * (end.tv_sec - start_time.tv_sec) + (end.tv_usec - start_time.tv_usec);
Timer::level--; Timer::level--;
if (VERBOSITY("time") >= 2 && desc) { if (VERBOSITY("time") >= 2 && desc) {
uint64_t us = (uint64_t)(duration / Stats::estimateCPUFreq());
if (us > min_usec) { if (us > min_usec) {
for (int i = 0; i < Timer::level; i++) { for (int i = 0; i < Timer::level; i++) {
putchar(' '); putchar(' ');
...@@ -70,15 +78,17 @@ long Timer::end() { ...@@ -70,15 +78,17 @@ long Timer::end() {
fflush(stdout); fflush(stdout);
} }
} }
if (ended_at)
*ended_at = end;
ended = true; ended = true;
return us; return duration;
} }
return -1; return -1;
} }
Timer::~Timer() { Timer::~Timer() {
if (!ended) { if (!ended) {
long t = end(); uint64_t t = end();
if (exit_callback) if (exit_callback)
exit_callback(t); exit_callback(t);
} }
......
...@@ -24,30 +24,36 @@ ...@@ -24,30 +24,36 @@
namespace pyston { namespace pyston {
uint64_t getCPUTicks();
class Timer { class Timer {
private: private:
static int level; static int level;
timeval start_time; uint64_t start_time;
const char* desc; const char* desc;
long min_usec; long min_usec;
bool ended; bool ended;
std::function<void(long)> exit_callback; std::function<void(uint64_t)> exit_callback;
public: public:
Timer(const char* desc = NULL, long min_usec = -1); Timer(const char* desc = NULL, long min_usec = -1);
~Timer(); ~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, long new_min_usec);
void restart(const char* newdesc = NULL); void restart(const char* newdesc = NULL);
long end(); // returns the duration. if @ended_at is non-null, it's filled in
long split(const char* newdesc = NULL) { // with the tick the timer stopped at.
long rtn = end(); uint64_t end(uint64_t* ended_at = NULL);
uint64_t split(const char* newdesc = NULL) {
uint64_t rtn = end();
restart(newdesc); restart(newdesc);
return rtn; return rtn;
} }
uint64_t getStartTime() const { return start_time; }
}; };
bool startswith(const std::string& s, const std::string& pattern); bool startswith(const std::string& s, const std::string& pattern);
......
...@@ -339,13 +339,13 @@ void runCollection() { ...@@ -339,13 +339,13 @@ void runCollection() {
static StatCounter sc("gc_collections"); static StatCounter sc("gc_collections");
sc.log(); sc.log();
STAT_TIMER(t0, "us_timer_gc_collection");
ncollections++; ncollections++;
if (VERBOSITY("gc") >= 2) if (VERBOSITY("gc") >= 2)
printf("Collection #%d\n", ncollections); printf("Collection #%d\n", ncollections);
Timer _t("collecting", /*min_usec=*/10000);
markPhase(); markPhase();
std::list<Box*, StlCompatAllocator<Box*>> weakly_referenced; std::list<Box*, StlCompatAllocator<Box*>> weakly_referenced;
sweepPhase(weakly_referenced); sweepPhase(weakly_referenced);
...@@ -369,10 +369,6 @@ void runCollection() { ...@@ -369,10 +369,6 @@ void runCollection() {
if (VERBOSITY("gc") >= 2) if (VERBOSITY("gc") >= 2)
printf("Collection #%d done\n\n", ncollections); printf("Collection #%d done\n\n", ncollections);
long us = _t.end();
static StatCounter sc_us("gc_collections_us");
sc_us.log(us);
// dumpHeapStatistics(); // dumpHeapStatistics();
} }
......
...@@ -29,6 +29,7 @@ namespace pyston { ...@@ -29,6 +29,7 @@ namespace pyston {
namespace gc { namespace gc {
extern "C" inline void* gc_alloc(size_t bytes, GCKind kind_id) { 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); size_t alloc_bytes = bytes + sizeof(GCAllocation);
#ifndef NVALGRIND #ifndef NVALGRIND
......
...@@ -139,223 +139,240 @@ int handleArg(char code) { ...@@ -139,223 +139,240 @@ int handleArg(char code) {
} }
static int main(int argc, char** argv) { static int main(int argc, char** argv) {
Timer _t("for jit startup"); Timer _t("for jit startup");
// llvm::sys::PrintStackTraceOnErrorSignal(); // llvm::sys::PrintStackTraceOnErrorSignal();
// llvm::PrettyStackTraceProgram X(argc, argv); // llvm::PrettyStackTraceProgram X(argc, argv);
llvm::llvm_shutdown_obj Y; llvm::llvm_shutdown_obj Y;
int code; timespec before_ts, after_ts;
const char* command = NULL;
Timer main_time;
int rtncode;
{
STAT_TIMER2(t0, "us_timer_main_toplevel", main_time.getStartTime());
int code;
const char* command = NULL;
char* env_args = getenv("PYSTON_RUN_ARGS"); char* env_args = getenv("PYSTON_RUN_ARGS");
if (env_args) { if (env_args) {
while (*env_args) { while (*env_args) {
int r = handleArg(*env_args); int r = handleArg(*env_args);
if (r) if (r)
return r; return r;
env_args++; env_args++;
}
} }
}
// Suppress getopt errors so we can throw them ourselves // Suppress getopt errors so we can throw them ourselves
opterr = 0; opterr = 0;
while ((code = getopt(argc, argv, "+:OqdIibpjtrsSvnxEc:FuPT")) != -1) { while ((code = getopt(argc, argv, "+:OqdIibpjtrsSvnxEc:FuPT")) != -1) {
if (code == 'c') { if (code == 'c') {
assert(optarg); assert(optarg);
command = optarg; command = optarg;
// no more option parsing; the rest of our arguments go into sys.argv. // no more option parsing; the rest of our arguments go into sys.argv.
break; break;
} else if (code == ':') { } else if (code == ':') {
fprintf(stderr, "Argument expected for the -%c option\n", optopt); fprintf(stderr, "Argument expected for the -%c option\n", optopt);
return 2; return 2;
} else if (code == '?') { } else if (code == '?') {
fprintf(stderr, "Unknown option: -%c\n", optopt); fprintf(stderr, "Unknown option: -%c\n", optopt);
return 2; return 2;
} else { } else {
int r = handleArg(code); int r = handleArg(code);
if (r) if (r)
return r; return r;
}
} }
}
const char* fn = NULL; Stats::startEstimatingCPUFreq();
threading::registerMainThread(); const char* fn = NULL;
threading::acquireGLRead();
Py_SetProgramName(argv[0]); threading::registerMainThread();
threading::acquireGLRead();
if (unbuffered) { Py_SetProgramName(argv[0]);
setvbuf(stdin, (char*)NULL, _IONBF, BUFSIZ);
setvbuf(stdout, (char*)NULL, _IONBF, BUFSIZ);
setvbuf(stderr, (char*)NULL, _IONBF, BUFSIZ);
}
{ if (unbuffered) {
Timer _t("for initCodegen"); setvbuf(stdin, (char*)NULL, _IONBF, BUFSIZ);
initCodegen(); setvbuf(stdout, (char*)NULL, _IONBF, BUFSIZ);
} setvbuf(stderr, (char*)NULL, _IONBF, BUFSIZ);
}
// Arguments left over after option parsing are of the form: {
// [ script | - ] [ arguments... ] Timer _t("for initCodegen");
// unless we've been already parsed a `-c command` option, in which case only: initCodegen();
// [ arguments...] }
// are parsed.
if (command)
addToSysArgv("-c");
else if (optind != argc) {
addToSysArgv(argv[optind]);
if (strcmp("-", argv[optind]) != 0)
fn = argv[optind];
++optind;
} else
addToSysArgv("");
for (int i = optind; i < argc; i++) {
addToSysArgv(argv[i]);
}
llvm::StringRef module_search_path = Py_GetPath(); // Arguments left over after option parsing are of the form:
while (true) { // [ script | - ] [ arguments... ]
std::pair<llvm::StringRef, llvm::StringRef> split_str = module_search_path.split(DELIM); // unless we've been already parsed a `-c command` option, in which case only:
if (split_str.first == module_search_path) // [ arguments...]
break; // could not find the delimiter // are parsed.
appendToSysPath(split_str.first); if (command)
module_search_path = split_str.second; addToSysArgv("-c");
} else if (optind != argc) {
addToSysArgv(argv[optind]);
if (strcmp("-", argv[optind]) != 0)
fn = argv[optind];
++optind;
} else
addToSysArgv("");
for (int i = optind; i < argc; i++) {
addToSysArgv(argv[i]);
}
if (!fn) { llvm::StringRef module_search_path = Py_GetPath();
// if we are in repl or command mode prepend "" to the path while (true) {
prependToSysPath(""); std::pair<llvm::StringRef, llvm::StringRef> split_str = module_search_path.split(DELIM);
} if (split_str.first == module_search_path)
break; // could not find the delimiter
appendToSysPath(split_str.first);
module_search_path = split_str.second;
}
if (!Py_NoSiteFlag) { if (!fn) {
try { // if we are in repl or command mode prepend "" to the path
std::string module_name = "site"; prependToSysPath("");
importModuleLevel(module_name, None, None, 0);
} catch (ExcInfo e) {
e.printExcAndTraceback();
return 1;
} }
}
// Set encoding for standard streams. This needs to be done after if (!Py_NoSiteFlag) {
// sys.path is properly set up, so that we can import the try {
// encodings module. std::string module_name = "site";
setEncodingAndErrors(); importModuleLevel(module_name, None, None, 0);
} catch (ExcInfo e) {
// end of argument parsing e.printExcAndTraceback();
return 1;
_t.split("to run"); }
BoxedModule* main_module = NULL;
// if the user invoked `pyston -c command`
if (command != NULL) {
try {
main_module = createModule("__main__", "<string>");
AST_Module* m = parse_string(command);
compileAndRunModule(m, main_module);
} catch (ExcInfo e) {
int retcode = 1;
(void)handle_toplevel_exn(e, &retcode);
Stats::dump();
return retcode;
} }
}
if (fn != NULL) { // Set encoding for standard streams. This needs to be done after
llvm::SmallString<128> path; // sys.path is properly set up, so that we can import the
// encodings module.
setEncodingAndErrors();
if (!llvm::sys::path::is_absolute(fn)) { // end of argument parsing
char cwd_buf[1026];
char* cwd = getcwd(cwd_buf, sizeof(cwd_buf)); _t.split("to run");
assert(cwd); BoxedModule* main_module = NULL;
path = cwd;
}
llvm::sys::path::append(path, fn); // if the user invoked `pyston -c command`
llvm::sys::path::remove_filename(path); if (command != NULL) {
prependToSysPath(path.str()); try {
main_module = createModule("__main__", "<string>");
main_module = createModule("__main__", fn); AST_Module* m = parse_string(command);
try { compileAndRunModule(m, main_module);
AST_Module* ast = caching_parse_file(fn); } catch (ExcInfo e) {
compileAndRunModule(ast, main_module); int retcode = 1;
} catch (ExcInfo e) { (void)handle_toplevel_exn(e, &retcode);
int retcode = 1; Stats::dump(false);
(void)handle_toplevel_exn(e, &retcode);
if (!force_repl) {
Stats::dump();
return retcode; return retcode;
} }
} }
}
if (force_repl || !(command || fn)) { if (fn != NULL) {
printf("Pyston v%d.%d (rev " STRINGIFY(GITREV) ")", PYSTON_VERSION_MAJOR, PYSTON_VERSION_MINOR); llvm::SmallString<128> path;
printf(", targeting Python %d.%d.%d\n", PYTHON_VERSION_MAJOR, PYTHON_VERSION_MINOR, PYTHON_VERSION_MICRO);
if (!main_module) { if (!llvm::sys::path::is_absolute(fn)) {
main_module = createModule("__main__", "<stdin>"); char cwd_buf[1026];
} else { char* cwd = getcwd(cwd_buf, sizeof(cwd_buf));
// main_module->fn = "<stdin>"; assert(cwd);
} path = cwd;
}
for (;;) {
char* line = readline(">> ");
if (!line)
break;
add_history(line); llvm::sys::path::append(path, fn);
llvm::sys::path::remove_filename(path);
prependToSysPath(path.str());
main_module = createModule("__main__", fn);
try { try {
AST_Module* m = parse_string(line); AST_Module* ast = caching_parse_file(fn);
compileAndRunModule(ast, main_module);
Timer _t("repl");
if (m->body.size() > 0 && m->body[0]->type == AST_TYPE::Expr) {
AST_Expr* e = ast_cast<AST_Expr>(m->body[0]);
AST_Call* c = new AST_Call();
AST_Name* r = new AST_Name(m->interned_strings->get("repr"), AST_TYPE::Load, 0);
c->func = r;
c->starargs = NULL;
c->kwargs = NULL;
c->args.push_back(e->value);
c->lineno = 0;
AST_Print* p = new AST_Print();
p->dest = NULL;
p->nl = true;
p->values.push_back(c);
p->lineno = 0;
m->body[0] = p;
}
compileAndRunModule(m, main_module);
} catch (ExcInfo e) { } catch (ExcInfo e) {
int retcode = 0xdeadbeef; // should never be seen int retcode = 1;
if (handle_toplevel_exn(e, &retcode)) { (void)handle_toplevel_exn(e, &retcode);
Stats::dump(); if (!force_repl) {
Stats::dump(false);
return retcode; return retcode;
} }
} }
} }
}
threading::finishMainThread(); if (force_repl || !(command || fn)) {
printf("Pyston v%d.%d (rev " STRINGIFY(GITREV) ")", PYSTON_VERSION_MAJOR, PYSTON_VERSION_MINOR);
printf(", targeting Python %d.%d.%d\n", PYTHON_VERSION_MAJOR, PYTHON_VERSION_MINOR, PYTHON_VERSION_MICRO);
if (!main_module) {
main_module = createModule("__main__", "<stdin>");
} else {
// main_module->fn = "<stdin>";
}
for (;;) {
char* line = readline(">> ");
if (!line)
break;
add_history(line);
try {
AST_Module* m = parse_string(line);
Timer _t("repl");
if (m->body.size() > 0 && m->body[0]->type == AST_TYPE::Expr) {
AST_Expr* e = ast_cast<AST_Expr>(m->body[0]);
AST_Call* c = new AST_Call();
AST_Name* r = new AST_Name(m->interned_strings->get("repr"), AST_TYPE::Load, 0);
c->func = r;
c->starargs = NULL;
c->kwargs = NULL;
c->args.push_back(e->value);
c->lineno = 0;
AST_Print* p = new AST_Print();
p->dest = NULL;
p->nl = true;
p->values.push_back(c);
p->lineno = 0;
m->body[0] = p;
}
compileAndRunModule(m, main_module);
} catch (ExcInfo e) {
int retcode = 0xdeadbeef; // should never be seen
if (handle_toplevel_exn(e, &retcode)) {
Stats::dump(false);
return retcode;
}
}
}
}
// Acquire the GIL to make sure we stop the other threads, since we will tear down threading::finishMainThread();
// data structures they are potentially running on.
// Note: we will purposefully not release the GIL on exiting.
threading::promoteGL();
_t.split("joinRuntime"); // Acquire the GIL to make sure we stop the other threads, since we will tear down
// data structures they are potentially running on.
// Note: we will purposefully not release the GIL on exiting.
threading::promoteGL();
int rtncode = joinRuntime(); _t.split("joinRuntime");
_t.split("finishing up");
rtncode = joinRuntime();
_t.split("finishing up");
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);
Stats::dump();
return rtncode; return rtncode;
} }
......
...@@ -303,6 +303,7 @@ extern "C" Box* ord(Box* obj) { ...@@ -303,6 +303,7 @@ extern "C" Box* ord(Box* obj) {
} }
Box* range(Box* start, Box* stop, Box* step) { Box* range(Box* start, Box* stop, Box* step) {
STAT_TIMER(t0, "us_timer_builtin_range");
i64 istart, istop, istep; i64 istart, istop, istep;
if (stop == NULL) { if (stop == NULL) {
istart = 0; istart = 0;
...@@ -346,6 +347,7 @@ Box* notimplementedRepr(Box* self) { ...@@ -346,6 +347,7 @@ Box* notimplementedRepr(Box* self) {
} }
Box* sorted(Box* obj, Box* cmp, Box* key, Box** args) { Box* sorted(Box* obj, Box* cmp, Box* key, Box** args) {
STAT_TIMER(t0, "us_timer_builtin_sorted");
Box* reverse = args[0]; Box* reverse = args[0];
BoxedList* rtn = new BoxedList(); BoxedList* rtn = new BoxedList();
...@@ -358,6 +360,7 @@ Box* sorted(Box* obj, Box* cmp, Box* key, Box** args) { ...@@ -358,6 +360,7 @@ Box* sorted(Box* obj, Box* cmp, Box* key, Box** args) {
} }
Box* isinstance_func(Box* obj, Box* cls) { Box* isinstance_func(Box* obj, Box* cls) {
STAT_TIMER(t0, "us_timer_builtin_isinstance");
int rtn = PyObject_IsInstance(obj, cls); int rtn = PyObject_IsInstance(obj, cls);
if (rtn < 0) if (rtn < 0)
checkAndThrowCAPIException(); checkAndThrowCAPIException();
...@@ -365,6 +368,7 @@ Box* isinstance_func(Box* obj, Box* cls) { ...@@ -365,6 +368,7 @@ Box* isinstance_func(Box* obj, Box* cls) {
} }
Box* issubclass_func(Box* child, Box* parent) { Box* issubclass_func(Box* child, Box* parent) {
STAT_TIMER(t0, "us_timer_builtin_issubclass");
int rtn = PyObject_IsSubclass(child, parent); int rtn = PyObject_IsSubclass(child, parent);
if (rtn < 0) if (rtn < 0)
checkAndThrowCAPIException(); checkAndThrowCAPIException();
......
...@@ -48,6 +48,7 @@ Box* dictRepr(BoxedDict* self) { ...@@ -48,6 +48,7 @@ Box* dictRepr(BoxedDict* self) {
} }
Box* dictClear(BoxedDict* self) { Box* dictClear(BoxedDict* self) {
STAT_TIMER(t0, "us_timer_dictClear");
if (!isSubclass(self->cls, dict_cls)) if (!isSubclass(self->cls, dict_cls))
raiseExcHelper(TypeError, "descriptor 'clear' requires a 'dict' object but received a '%s'", getTypeName(self)); raiseExcHelper(TypeError, "descriptor 'clear' requires a 'dict' object but received a '%s'", getTypeName(self));
...@@ -56,6 +57,7 @@ Box* dictClear(BoxedDict* self) { ...@@ -56,6 +57,7 @@ Box* dictClear(BoxedDict* self) {
} }
Box* dictCopy(BoxedDict* self) { Box* dictCopy(BoxedDict* self) {
STAT_TIMER(t0, "us_timer_dictCopy");
if (!isSubclass(self->cls, dict_cls)) if (!isSubclass(self->cls, dict_cls))
raiseExcHelper(TypeError, "descriptor 'copy' requires a 'dict' object but received a '%s'", getTypeName(self)); raiseExcHelper(TypeError, "descriptor 'copy' requires a 'dict' object but received a '%s'", getTypeName(self));
...@@ -65,6 +67,7 @@ Box* dictCopy(BoxedDict* self) { ...@@ -65,6 +67,7 @@ Box* dictCopy(BoxedDict* self) {
} }
Box* dictItems(BoxedDict* self) { Box* dictItems(BoxedDict* self) {
STAT_TIMER(t0, "us_timer_dictItems");
BoxedList* rtn = new BoxedList(); BoxedList* rtn = new BoxedList();
rtn->ensure(self->d.size()); rtn->ensure(self->d.size());
...@@ -77,6 +80,7 @@ Box* dictItems(BoxedDict* self) { ...@@ -77,6 +80,7 @@ Box* dictItems(BoxedDict* self) {
} }
Box* dictValues(BoxedDict* self) { Box* dictValues(BoxedDict* self) {
STAT_TIMER(t0, "us_timer_dictValues");
BoxedList* rtn = new BoxedList(); BoxedList* rtn = new BoxedList();
rtn->ensure(self->d.size()); rtn->ensure(self->d.size());
for (const auto& p : self->d) { for (const auto& p : self->d) {
...@@ -86,6 +90,7 @@ Box* dictValues(BoxedDict* self) { ...@@ -86,6 +90,7 @@ Box* dictValues(BoxedDict* self) {
} }
Box* dictKeys(BoxedDict* self) { Box* dictKeys(BoxedDict* self) {
STAT_TIMER(t0, "us_timer_dictKeys");
RELEASE_ASSERT(isSubclass(self->cls, dict_cls), ""); RELEASE_ASSERT(isSubclass(self->cls, dict_cls), "");
BoxedList* rtn = new BoxedList(); BoxedList* rtn = new BoxedList();
...@@ -182,6 +187,7 @@ extern "C" int PyDict_Update(PyObject* a, PyObject* b) noexcept { ...@@ -182,6 +187,7 @@ extern "C" int PyDict_Update(PyObject* a, PyObject* b) noexcept {
} }
Box* dictGetitem(BoxedDict* self, Box* k) { Box* dictGetitem(BoxedDict* self, Box* k) {
STAT_TIMER(t0, "us_timer_dictGetitem");
if (!isSubclass(self->cls, dict_cls)) if (!isSubclass(self->cls, dict_cls))
raiseExcHelper(TypeError, "descriptor '__getitem__' requires a 'dict' object but received a '%s'", raiseExcHelper(TypeError, "descriptor '__getitem__' requires a 'dict' object but received a '%s'",
getTypeName(self)); getTypeName(self));
...@@ -306,6 +312,7 @@ extern "C" PyObject* PyDict_GetItemString(PyObject* dict, const char* key) noexc ...@@ -306,6 +312,7 @@ extern "C" PyObject* PyDict_GetItemString(PyObject* dict, const char* key) noexc
} }
Box* dictSetitem(BoxedDict* self, Box* k, Box* v) { Box* dictSetitem(BoxedDict* self, Box* k, Box* v) {
STAT_TIMER(t0, "us_timer_dictSetitem");
// printf("Starting setitem\n"); // printf("Starting setitem\n");
Box*& pos = self->d[k]; Box*& pos = self->d[k];
// printf("Got the pos\n"); // printf("Got the pos\n");
...@@ -320,6 +327,7 @@ Box* dictSetitem(BoxedDict* self, Box* k, Box* v) { ...@@ -320,6 +327,7 @@ Box* dictSetitem(BoxedDict* self, Box* k, Box* v) {
} }
Box* dictDelitem(BoxedDict* self, Box* k) { Box* dictDelitem(BoxedDict* self, Box* k) {
STAT_TIMER(t0, "us_timer_dictDelitem");
if (!isSubclass(self->cls, dict_cls)) if (!isSubclass(self->cls, dict_cls))
raiseExcHelper(TypeError, "descriptor '__delitem__' requires a 'dict' object but received a '%s'", raiseExcHelper(TypeError, "descriptor '__delitem__' requires a 'dict' object but received a '%s'",
getTypeName(self)); getTypeName(self));
......
...@@ -86,28 +86,36 @@ Context* getReturnContextForGeneratorFrame(void* frame_addr) { ...@@ -86,28 +86,36 @@ Context* getReturnContextForGeneratorFrame(void* frame_addr) {
} }
void generatorEntry(BoxedGenerator* g) { void generatorEntry(BoxedGenerator* g) {
assert(g->cls == generator_cls); {
assert(g->function->cls == function_cls); STAT_TIMER2(t0, "us_timer_generator_toplevel", g->timer_time);
threading::pushGenerator(g, g->stack_begin, g->returnContext); assert(g->cls == generator_cls);
assert(g->function->cls == function_cls);
try { threading::pushGenerator(g, g->stack_begin, g->returnContext);
RegisterHelper context_registerer(g, __builtin_frame_address(0)); try {
RegisterHelper context_registerer(g, __builtin_frame_address(0));
// call body of the generator // call body of the generator
BoxedFunctionBase* func = g->function; BoxedFunctionBase* func = g->function;
Box** args = g->args ? &g->args->elts[0] : nullptr; Box** args = g->args ? &g->args->elts[0] : nullptr;
callCLFunc(func->f, nullptr, func->f->numReceivedArgs(), func->closure, g, func->globals, g->arg1, g->arg2, callCLFunc(func->f, nullptr, func->f->numReceivedArgs(), func->closure, g, func->globals, g->arg1, g->arg2,
g->arg3, args); g->arg3, args);
} catch (ExcInfo e) { } catch (ExcInfo e) {
// unhandled exception: propagate the exception to the caller // unhandled exception: propagate the exception to the caller
g->exception = e; g->exception = e;
} }
// we returned from the body of the generator. next/send/throw will notify the caller // we returned from the body of the generator. next/send/throw will notify the caller
g->entryExited = true; g->entryExited = true;
threading::popGenerator(); 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); swapContext(&g->context, g->returnContext, 0);
} }
...@@ -130,7 +138,21 @@ Box* generatorSend(Box* s, Box* v) { ...@@ -130,7 +138,21 @@ Box* generatorSend(Box* s, Box* v) {
self->returnValue = v; self->returnValue = v;
self->running = true; 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); 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; self->running = false;
// propagate exception to the caller // propagate exception to the caller
......
...@@ -542,6 +542,8 @@ extern "C" Box* listInsert(BoxedList* self, Box* idx, Box* v) { ...@@ -542,6 +542,8 @@ extern "C" Box* listInsert(BoxedList* self, Box* idx, Box* v) {
} }
Box* listMul(BoxedList* self, Box* rhs) { Box* listMul(BoxedList* self, Box* rhs) {
STAT_TIMER(t0, "us_timer_listMul");
if (rhs->cls != int_cls) { if (rhs->cls != int_cls) {
raiseExcHelper(TypeError, "can't multiply sequence by non-int of type '%s'", getTypeName(rhs)); raiseExcHelper(TypeError, "can't multiply sequence by non-int of type '%s'", getTypeName(rhs));
} }
......
...@@ -125,6 +125,7 @@ static Box* (*callattrInternal3)(Box*, const std::string*, LookupScope, CallRewr ...@@ -125,6 +125,7 @@ static Box* (*callattrInternal3)(Box*, const std::string*, LookupScope, CallRewr
* (*)(Box*, const std::string*, LookupScope, CallRewriteArgs*, ArgPassSpec, Box*, Box*, Box*))callattrInternal; * (*)(Box*, const std::string*, LookupScope, CallRewriteArgs*, ArgPassSpec, Box*, Box*, Box*))callattrInternal;
size_t PyHasher::operator()(Box* b) const { size_t PyHasher::operator()(Box* b) const {
STAT_TIMER(t0, "us_timer_PyHasher");
if (b->cls == str_cls) { if (b->cls == str_cls) {
StringHash<char> H; StringHash<char> H;
auto s = static_cast<BoxedString*>(b); auto s = static_cast<BoxedString*>(b);
...@@ -138,6 +139,8 @@ size_t PyHasher::operator()(Box* b) const { ...@@ -138,6 +139,8 @@ size_t PyHasher::operator()(Box* b) const {
} }
bool PyEq::operator()(Box* lhs, Box* rhs) const { bool PyEq::operator()(Box* lhs, Box* rhs) const {
STAT_TIMER(t0, "us_timer_PyEq");
if (lhs->cls == rhs->cls) { if (lhs->cls == rhs->cls) {
if (lhs->cls == str_cls) { if (lhs->cls == str_cls) {
return static_cast<BoxedString*>(lhs)->s == static_cast<BoxedString*>(rhs)->s; return static_cast<BoxedString*>(lhs)->s == static_cast<BoxedString*>(rhs)->s;
...@@ -151,6 +154,8 @@ bool PyEq::operator()(Box* lhs, Box* rhs) const { ...@@ -151,6 +154,8 @@ bool PyEq::operator()(Box* lhs, Box* rhs) const {
} }
bool PyLt::operator()(Box* lhs, Box* rhs) const { bool PyLt::operator()(Box* lhs, Box* rhs) const {
STAT_TIMER(t0, "us_timer_PyLt");
// TODO fix this // TODO fix this
Box* cmp = compareInternal(lhs, rhs, AST_TYPE::Lt, NULL); Box* cmp = compareInternal(lhs, rhs, AST_TYPE::Lt, NULL);
assert(cmp->cls == bool_cls); assert(cmp->cls == bool_cls);
...@@ -211,6 +216,7 @@ extern "C" void my_assert(bool b) { ...@@ -211,6 +216,7 @@ extern "C" void my_assert(bool b) {
} }
extern "C" bool isSubclass(BoxedClass* child, BoxedClass* parent) { extern "C" bool isSubclass(BoxedClass* child, BoxedClass* parent) {
STAT_TIMER(t0, "us_timer_isSubclass");
return PyType_IsSubtype(child, parent); return PyType_IsSubtype(child, parent);
} }
...@@ -476,6 +482,7 @@ const char* getNameOfClass(BoxedClass* cls) { ...@@ -476,6 +482,7 @@ const char* getNameOfClass(BoxedClass* cls) {
} }
HiddenClass* HiddenClass::getOrMakeChild(const std::string& attr) { HiddenClass* HiddenClass::getOrMakeChild(const std::string& attr) {
STAT_TIMER(t0, "us_timer_hiddenclass_getOrMakeChild");
assert(type == NORMAL); assert(type == NORMAL);
auto it = children.find(attr); auto it = children.find(attr);
...@@ -507,6 +514,8 @@ HiddenClass* HiddenClass::getAttrwrapperChild() { ...@@ -507,6 +514,8 @@ HiddenClass* HiddenClass::getAttrwrapperChild() {
* del attr from current HiddenClass, maintaining the order of the remaining attrs * del attr from current HiddenClass, maintaining the order of the remaining attrs
*/ */
HiddenClass* HiddenClass::delAttrToMakeHC(const std::string& attr) { HiddenClass* HiddenClass::delAttrToMakeHC(const std::string& attr) {
STAT_TIMER(t0, "us_timer_hiddenclass_delAttrToMakeHC");
assert(type == NORMAL); assert(type == NORMAL);
int idx = getOffset(attr); int idx = getOffset(attr);
assert(idx >= 0); assert(idx >= 0);
...@@ -655,8 +664,9 @@ Box* Box::getattr(const std::string& attr, GetattrRewriteArgs* rewrite_args) { ...@@ -655,8 +664,9 @@ Box* Box::getattr(const std::string& attr, GetattrRewriteArgs* rewrite_args) {
Box* key = boxString(attr); Box* key = boxString(attr);
auto it = d->d.find(key); auto it = d->d.find(key);
if (it == d->d.end()) if (it == d->d.end()) {
return NULL; return NULL;
}
return it->second; return it->second;
} }
...@@ -1211,6 +1221,8 @@ Box* getattrInternalEx(Box* obj, const std::string& attr, GetattrRewriteArgs* re ...@@ -1211,6 +1221,8 @@ Box* getattrInternalEx(Box* obj, const std::string& attr, GetattrRewriteArgs* re
if (!cls_only) { if (!cls_only) {
BoxedClass* cls = obj->cls; BoxedClass* cls = obj->cls;
if (obj->cls->tp_getattro && obj->cls->tp_getattro != PyObject_GenericGetAttr) { 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)); Box* r = obj->cls->tp_getattro(obj, boxString(attr));
if (!r) if (!r)
throwCAPIException(); throwCAPIException();
...@@ -1218,6 +1230,8 @@ Box* getattrInternalEx(Box* obj, const std::string& attr, GetattrRewriteArgs* re ...@@ -1218,6 +1230,8 @@ Box* getattrInternalEx(Box* obj, const std::string& attr, GetattrRewriteArgs* re
} }
if (obj->cls->tp_getattr) { 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())); Box* r = obj->cls->tp_getattr(obj, const_cast<char*>(attr.c_str()));
if (!r) if (!r)
throwCAPIException(); throwCAPIException();
...@@ -1242,6 +1256,8 @@ inline Box* getclsattrInternal(Box* obj, const std::string& attr, GetattrRewrite ...@@ -1242,6 +1256,8 @@ inline Box* getclsattrInternal(Box* obj, const std::string& attr, GetattrRewrite
} }
extern "C" Box* getclsattr(Box* obj, const char* attr) { extern "C" Box* getclsattr(Box* obj, const char* attr) {
STAT_TIMER(t0, "us_timer_slowpath_getclsattr");
static StatCounter slowpath_getclsattr("slowpath_getclsattr"); static StatCounter slowpath_getclsattr("slowpath_getclsattr");
slowpath_getclsattr.log(); slowpath_getclsattr.log();
...@@ -1312,12 +1328,6 @@ Box* processDescriptor(Box* obj, Box* inst, Box* owner) { ...@@ -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, 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) { bool for_call, Box** bind_obj_out, RewriterVar** r_bind_obj_out) {
if (for_call) { if (for_call) {
...@@ -1635,6 +1645,8 @@ Box* getattrInternal(Box* obj, const std::string& attr, GetattrRewriteArgs* rewr ...@@ -1635,6 +1645,8 @@ Box* getattrInternal(Box* obj, const std::string& attr, GetattrRewriteArgs* rewr
} }
extern "C" Box* getattr(Box* obj, const char* attr) { extern "C" Box* getattr(Box* obj, const char* attr) {
STAT_TIMER(t0, "us_timer_slowpath_getattr");
static StatCounter slowpath_getattr("slowpath_getattr"); static StatCounter slowpath_getattr("slowpath_getattr");
slowpath_getattr.log(); slowpath_getattr.log();
...@@ -1845,10 +1857,14 @@ void setattrGeneric(Box* obj, const std::string& attr, Box* val, SetattrRewriteA ...@@ -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) { 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"); static StatCounter slowpath_setattr("slowpath_setattr");
slowpath_setattr.log(); slowpath_setattr.log();
if (obj->cls->tp_setattr) { 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); int rtn = obj->cls->tp_setattr(obj, const_cast<char*>(attr), attr_val);
if (rtn) if (rtn)
throwCAPIException(); throwCAPIException();
...@@ -1923,6 +1939,7 @@ extern "C" void setattr(Box* obj, const char* attr, Box* attr_val) { ...@@ -1923,6 +1939,7 @@ extern "C" void setattr(Box* obj, const char* attr, Box* attr_val) {
setattr = processDescriptor(setattr, obj, obj->cls); setattr = processDescriptor(setattr, obj, obj->cls);
runtimeCallInternal(setattr, NULL, ArgPassSpec(2), boxstr, attr_val, NULL, NULL, NULL); runtimeCallInternal(setattr, NULL, ArgPassSpec(2), boxstr, attr_val, NULL, NULL, NULL);
} else { } else {
STAT_TIMER(t0, "us_timer_tp_setattro");
int r = tp_setattro(obj, boxstr, attr_val); int r = tp_setattro(obj, boxstr, attr_val);
if (r) if (r)
throwCAPIException(); throwCAPIException();
...@@ -1935,6 +1952,8 @@ bool isUserDefined(BoxedClass* cls) { ...@@ -1935,6 +1952,8 @@ bool isUserDefined(BoxedClass* cls) {
} }
extern "C" bool nonzero(Box* obj) { extern "C" bool nonzero(Box* obj) {
STAT_TIMER(t0, "us_timer_slowpath_nonzero");
assert(gc::isValidGCObject(obj)); assert(gc::isValidGCObject(obj));
static StatCounter slowpath_nonzero("slowpath_nonzero"); static StatCounter slowpath_nonzero("slowpath_nonzero");
...@@ -2009,7 +2028,7 @@ extern "C" bool nonzero(Box* obj) { ...@@ -2009,7 +2028,7 @@ extern "C" bool nonzero(Box* obj) {
return true; 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: // I believe this behavior is handled by the slot wrappers in CPython:
if (r->cls == bool_cls) { if (r->cls == bool_cls) {
BoxedBool* b = static_cast<BoxedBool*>(r); BoxedBool* b = static_cast<BoxedBool*>(r);
...@@ -2025,6 +2044,7 @@ extern "C" bool nonzero(Box* obj) { ...@@ -2025,6 +2044,7 @@ extern "C" bool nonzero(Box* obj) {
} }
extern "C" BoxedString* str(Box* obj) { extern "C" BoxedString* str(Box* obj) {
STAT_TIMER(t0, "us_timer_str");
static StatCounter slowpath_str("slowpath_str"); static StatCounter slowpath_str("slowpath_str");
slowpath_str.log(); slowpath_str.log();
...@@ -2046,6 +2066,7 @@ extern "C" BoxedString* str(Box* obj) { ...@@ -2046,6 +2066,7 @@ extern "C" BoxedString* str(Box* obj) {
} }
extern "C" Box* strOrUnicode(Box* obj) { extern "C" Box* strOrUnicode(Box* obj) {
STAT_TIMER(t0, "us_timer_strOrUnicode");
// Like str, but returns unicode objects unchanged. // Like str, but returns unicode objects unchanged.
if (obj->cls == unicode_cls) { if (obj->cls == unicode_cls) {
return obj; return obj;
...@@ -2054,6 +2075,7 @@ extern "C" Box* strOrUnicode(Box* obj) { ...@@ -2054,6 +2075,7 @@ extern "C" Box* strOrUnicode(Box* obj) {
} }
extern "C" BoxedString* repr(Box* obj) { extern "C" BoxedString* repr(Box* obj) {
STAT_TIMER(t0, "us_timer_repr");
static StatCounter slowpath_repr("slowpath_repr"); static StatCounter slowpath_repr("slowpath_repr");
slowpath_repr.log(); slowpath_repr.log();
...@@ -2071,6 +2093,7 @@ extern "C" BoxedString* repr(Box* obj) { ...@@ -2071,6 +2093,7 @@ extern "C" BoxedString* repr(Box* obj) {
} }
extern "C" BoxedString* reprOrNull(Box* obj) { extern "C" BoxedString* reprOrNull(Box* obj) {
STAT_TIMER(t0, "us_timer_reprOrNull");
try { try {
Box* r = repr(obj); Box* r = repr(obj);
assert(r->cls == str_cls); // this should be checked by repr() assert(r->cls == str_cls); // this should be checked by repr()
...@@ -2081,6 +2104,7 @@ extern "C" BoxedString* reprOrNull(Box* obj) { ...@@ -2081,6 +2104,7 @@ extern "C" BoxedString* reprOrNull(Box* obj) {
} }
extern "C" BoxedString* strOrNull(Box* obj) { extern "C" BoxedString* strOrNull(Box* obj) {
STAT_TIMER(t0, "us_timer_strOrNull");
try { try {
BoxedString* r = str(obj); BoxedString* r = str(obj);
return static_cast<BoxedString*>(r); return static_cast<BoxedString*>(r);
...@@ -2090,6 +2114,7 @@ extern "C" BoxedString* strOrNull(Box* obj) { ...@@ -2090,6 +2114,7 @@ extern "C" BoxedString* strOrNull(Box* obj) {
} }
extern "C" bool exceptionMatches(Box* obj, Box* cls) { extern "C" bool exceptionMatches(Box* obj, Box* cls) {
STAT_TIMER(t0, "us_timer_exceptionMatches");
int rtn = PyErr_GivenExceptionMatches(obj, cls); int rtn = PyErr_GivenExceptionMatches(obj, cls);
RELEASE_ASSERT(rtn >= 0, ""); RELEASE_ASSERT(rtn >= 0, "");
return rtn; return rtn;
...@@ -2114,7 +2139,7 @@ extern "C" BoxedInt* hash(Box* obj) { ...@@ -2114,7 +2139,7 @@ extern "C" BoxedInt* hash(Box* obj) {
raiseExcHelper(TypeError, "unhashable type: '%s'", obj->cls->tp_name); 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) { if (rtn->cls != int_cls) {
raiseExcHelper(TypeError, "an integer is required"); raiseExcHelper(TypeError, "an integer is required");
} }
...@@ -2167,6 +2192,8 @@ Box* lenCallInternal(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, Arg ...@@ -2167,6 +2192,8 @@ Box* lenCallInternal(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, Arg
} }
extern "C" BoxedInt* len(Box* obj) { extern "C" BoxedInt* len(Box* obj) {
STAT_TIMER(t0, "us_timer_slowpath_len");
static StatCounter slowpath_len("slowpath_len"); static StatCounter slowpath_len("slowpath_len");
slowpath_len.log(); slowpath_len.log();
...@@ -2174,6 +2201,8 @@ extern "C" BoxedInt* len(Box* obj) { ...@@ -2174,6 +2201,8 @@ extern "C" BoxedInt* len(Box* obj) {
} }
extern "C" i64 unboxedLen(Box* obj) { extern "C" i64 unboxedLen(Box* obj) {
STAT_TIMER(t0, "us_timer_slowpath_unboxedLen");
static StatCounter slowpath_unboxedlen("slowpath_unboxedlen"); static StatCounter slowpath_unboxedlen("slowpath_unboxedlen");
slowpath_unboxedlen.log(); slowpath_unboxedlen.log();
...@@ -2515,6 +2544,8 @@ extern "C" Box* callattrInternal(Box* obj, const std::string* attr, LookupScope ...@@ -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, 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) { 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); ASSERT(gc::isValidGCObject(obj), "%p", obj);
int npassed_args = argspec.totalPassed(); int npassed_args = argspec.totalPassed();
...@@ -2704,6 +2735,9 @@ static StatCounter slowpath_callfunc_slowpath("slowpath_callfunc_slowpath"); ...@@ -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* callFunc(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, ArgPassSpec argspec, Box* arg1, Box* arg2,
Box* arg3, Box** args, const std::vector<const std::string*>* keyword_names) { Box* arg3, Box** args, const std::vector<const std::string*>* keyword_names) {
#if !DISABLE_STATS
StatTimer::assertActive();
#endif
/* /*
* Procedure: * Procedure:
* - First match up positional arguments; any extra go to varargs. error if too many. * - 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 ...@@ -3050,12 +3084,26 @@ Box* callFunc(BoxedFunctionBase* func, CallRewriteArgs* rewrite_args, ArgPassSpe
return res; 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, 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) { BoxedGenerator* generator, Box* globals, Box* oarg1, Box* oarg2, Box* oarg3, Box** oargs) {
CompiledFunction* chosen_cf = pickVersion(f, num_output_args, oarg1, oarg2, oarg3, oargs); CompiledFunction* chosen_cf = pickVersion(f, num_output_args, oarg1, oarg2, oarg3, oargs);
assert(chosen_cf->is_interpreted == (chosen_cf->code == NULL)); assert(chosen_cf->is_interpreted == (chosen_cf->code == NULL));
if (chosen_cf->is_interpreted) { if (chosen_cf->is_interpreted) {
STAT_TIMER(t0, "us_timer_astInterpretFunction");
return astInterpretFunction(chosen_cf, num_output_args, closure, generator, globals, oarg1, oarg2, oarg3, return astInterpretFunction(chosen_cf, num_output_args, closure, generator, globals, oarg1, oarg2, oarg3,
oargs); oargs);
} }
...@@ -3084,18 +3132,21 @@ Box* callCLFunc(CLFunction* f, CallRewriteArgs* rewrite_args, int num_output_arg ...@@ -3084,18 +3132,21 @@ Box* callCLFunc(CLFunction* f, CallRewriteArgs* rewrite_args, int num_output_arg
} }
Box* r; Box* r;
if (closure && generator) // we duplicate the call to callChosenCf here so we can
r = chosen_cf->closure_generator_call(closure, generator, oarg1, oarg2, oarg3, oargs); // distinguish lexically between calls that target jitted python
else if (closure) // code and calls that target to builtins.
r = chosen_cf->closure_call(closure, oarg1, oarg2, oarg3, oargs); if (f->source) {
else if (generator) STAT_TIMER(t0, "us_timer_chosen_cf_body_jitted");
r = chosen_cf->generator_call(generator, oarg1, oarg2, oarg3, oargs); r = callChosenCF(chosen_cf, closure, generator, oarg1, oarg2, oarg3, oargs);
else } else {
r = chosen_cf->call(oarg1, oarg2, oarg3, oargs); 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", 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, 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); chosen_cf->spec->rtn_type->debugName().c_str(), r->cls->tp_name);
return r; return r;
} }
...@@ -3225,9 +3276,9 @@ Box* runtimeCallInternal(Box* obj, CallRewriteArgs* rewrite_args, ArgPassSpec ar ...@@ -3225,9 +3276,9 @@ Box* runtimeCallInternal(Box* obj, CallRewriteArgs* rewrite_args, ArgPassSpec ar
Box** new_args = (Box**)alloca(sizeof(Box*) * (npassed_args + 1 - 3)); Box** new_args = (Box**)alloca(sizeof(Box*) * (npassed_args + 1 - 3));
new_args[0] = arg3; new_args[0] = arg3;
memcpy(new_args + 1, args, (npassed_args - 3) * sizeof(Box*)); 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), argspec.has_starargs, argspec.has_kwargs),
im->obj, arg1, arg2, new_args, keyword_names); im->obj, arg1, arg2, new_args, keyword_names);
return rtn; return rtn;
} }
} }
...@@ -3237,6 +3288,8 @@ Box* runtimeCallInternal(Box* obj, CallRewriteArgs* rewrite_args, ArgPassSpec ar ...@@ -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, extern "C" Box* runtimeCall(Box* obj, ArgPassSpec argspec, Box* arg1, Box* arg2, Box* arg3, Box** args,
const std::vector<const std::string*>* keyword_names) { const std::vector<const std::string*>* keyword_names) {
STAT_TIMER(t0, "us_timer_slowpath_runtimecall");
int npassed_args = argspec.totalPassed(); int npassed_args = argspec.totalPassed();
static StatCounter slowpath_runtimecall("slowpath_runtimecall"); static StatCounter slowpath_runtimecall("slowpath_runtimecall");
...@@ -3394,6 +3447,8 @@ extern "C" Box* binopInternal(Box* lhs, Box* rhs, int op_type, bool inplace, Bin ...@@ -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) { extern "C" Box* binop(Box* lhs, Box* rhs, int op_type) {
STAT_TIMER(t0, "us_timer_slowpath_binop");
static StatCounter slowpath_binop("slowpath_binop"); static StatCounter slowpath_binop("slowpath_binop");
slowpath_binop.log(); slowpath_binop.log();
// static StatCounter nopatch_binop("nopatch_binop"); // static StatCounter nopatch_binop("nopatch_binop");
...@@ -3430,11 +3485,13 @@ extern "C" Box* binop(Box* lhs, Box* rhs, int op_type) { ...@@ -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) { extern "C" Box* augbinop(Box* lhs, Box* rhs, int op_type) {
static StatCounter slowpath_binop("slowpath_binop"); STAT_TIMER(t0, "us_timer_slowpath_augbinop");
slowpath_binop.log();
// static StatCounter nopatch_binop("nopatch_binop");
// 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); // Stats::log(id);
std::unique_ptr<Rewriter> rewriter((Rewriter*)NULL); std::unique_ptr<Rewriter> rewriter((Rewriter*)NULL);
...@@ -3597,6 +3654,8 @@ Box* compareInternal(Box* lhs, Box* rhs, int op_type, CompareRewriteArgs* rewrit ...@@ -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) { extern "C" Box* compare(Box* lhs, Box* rhs, int op_type) {
STAT_TIMER(t0, "us_timer_slowpath_compare");
static StatCounter slowpath_compare("slowpath_compare"); static StatCounter slowpath_compare("slowpath_compare");
slowpath_compare.log(); slowpath_compare.log();
static StatCounter nopatch_compare("nopatch_compare"); static StatCounter nopatch_compare("nopatch_compare");
...@@ -3622,6 +3681,8 @@ extern "C" Box* compare(Box* lhs, Box* rhs, int op_type) { ...@@ -3622,6 +3681,8 @@ extern "C" Box* compare(Box* lhs, Box* rhs, int op_type) {
} }
extern "C" Box* unaryop(Box* operand, 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"); static StatCounter slowpath_unaryop("slowpath_unaryop");
slowpath_unaryop.log(); slowpath_unaryop.log();
...@@ -3631,11 +3692,13 @@ extern "C" Box* unaryop(Box* operand, int op_type) { ...@@ -3631,11 +3692,13 @@ extern "C" Box* unaryop(Box* operand, int op_type) {
ASSERT(attr_func, "%s.%s", getTypeName(operand), op_name.c_str()); 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; return rtn;
} }
extern "C" Box* getitem(Box* value, Box* slice) { 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 // This possibly could just be represented as a single callattr; the only tricky part
// are the error messages. // are the error messages.
// Ex "(1)[1]" and "(1).__getitem__(1)" give different 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) { ...@@ -3679,6 +3742,8 @@ extern "C" Box* getitem(Box* value, Box* slice) {
// target[slice] = value // target[slice] = value
extern "C" void setitem(Box* target, Box* slice, Box* value) { extern "C" void setitem(Box* target, Box* slice, Box* value) {
STAT_TIMER(t0, "us_timer_slowpath_setitem");
static StatCounter slowpath_setitem("slowpath_setitem"); static StatCounter slowpath_setitem("slowpath_setitem");
slowpath_setitem.log(); slowpath_setitem.log();
...@@ -3711,6 +3776,8 @@ extern "C" void setitem(Box* target, Box* slice, Box* value) { ...@@ -3711,6 +3776,8 @@ extern "C" void setitem(Box* target, Box* slice, Box* value) {
// del target[start:end:step] // del target[start:end:step]
extern "C" void delitem(Box* target, Box* slice) { extern "C" void delitem(Box* target, Box* slice) {
STAT_TIMER(t0, "us_timer_slowpath_delitem");
static StatCounter slowpath_delitem("slowpath_delitem"); static StatCounter slowpath_delitem("slowpath_delitem");
slowpath_delitem.log(); slowpath_delitem.log();
...@@ -3793,7 +3860,7 @@ extern "C" void delattrGeneric(Box* obj, const std::string& attr, DelattrRewrite ...@@ -3793,7 +3860,7 @@ extern "C" void delattrGeneric(Box* obj, const std::string& attr, DelattrRewrite
if (delAttr != NULL) { if (delAttr != NULL) {
Box* boxstr = boxString(attr); 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; return;
} }
} }
...@@ -3841,7 +3908,7 @@ extern "C" void delattrInternal(Box* obj, const std::string& attr, DelattrRewrit ...@@ -3841,7 +3908,7 @@ extern "C" void delattrInternal(Box* obj, const std::string& attr, DelattrRewrit
Box* delAttr = typeLookup(obj->cls, delattr_str, NULL); Box* delAttr = typeLookup(obj->cls, delattr_str, NULL);
if (delAttr != NULL) { if (delAttr != NULL) {
Box* boxstr = boxString(attr); 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; return;
} }
...@@ -3850,6 +3917,8 @@ extern "C" void delattrInternal(Box* obj, const std::string& attr, DelattrRewrit ...@@ -3850,6 +3917,8 @@ extern "C" void delattrInternal(Box* obj, const std::string& attr, DelattrRewrit
// del target.attr // del target.attr
extern "C" void delattr(Box* obj, const char* attr) { extern "C" void delattr(Box* obj, const char* attr) {
STAT_TIMER(t0, "us_timer_slowpath_delattr");
static StatCounter slowpath_delattr("slowpath_delattr"); static StatCounter slowpath_delattr("slowpath_delattr");
slowpath_delattr.log(); slowpath_delattr.log();
...@@ -3869,6 +3938,8 @@ extern "C" Box* createBoxedIterWrapper(Box* o) { ...@@ -3869,6 +3938,8 @@ extern "C" Box* createBoxedIterWrapper(Box* o) {
} }
extern "C" Box* createBoxedIterWrapperIfNeeded(Box* o) { extern "C" Box* createBoxedIterWrapperIfNeeded(Box* o) {
STAT_TIMER(t0, "us_timer_slowpath_createBoxedIterWrapperIfNeeded");
std::unique_ptr<Rewriter> rewriter(Rewriter::createRewriter( std::unique_ptr<Rewriter> rewriter(Rewriter::createRewriter(
__builtin_extract_return_addr(__builtin_return_address(0)), 1, "createBoxedIterWrapperIfNeeded")); __builtin_extract_return_addr(__builtin_return_address(0)), 1, "createBoxedIterWrapperIfNeeded"));
...@@ -3901,6 +3972,8 @@ extern "C" Box* createBoxedIterWrapperIfNeeded(Box* o) { ...@@ -3901,6 +3972,8 @@ extern "C" Box* createBoxedIterWrapperIfNeeded(Box* o) {
} }
extern "C" Box* getPystonIter(Box* o) { extern "C" Box* getPystonIter(Box* o) {
STAT_TIMER(t0, "us_timer_slowpath_getPystonIter");
Box* r = getiter(o); Box* r = getiter(o);
// assert((typeLookup(r->cls, hasnext_str, NULL) == NULL) == (r->cls->tpp_hasnext == object_cls->tpp_hasnext)); // 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) if (r->cls->tpp_hasnext == object_cls->tpp_hasnext)
...@@ -3938,6 +4011,9 @@ static void assertInitNone(Box* obj) { ...@@ -3938,6 +4011,9 @@ static void assertInitNone(Box* obj) {
} }
Box* typeNew(Box* _cls, Box* arg1, Box* arg2, Box** _args) { Box* typeNew(Box* _cls, Box* arg1, Box* arg2, Box** _args) {
STAT_TIMER(t0, "us_timer_typeNew");
Box* arg3 = _args[0]; Box* arg3 = _args[0];
if (!isSubclass(_cls->cls, type_cls)) if (!isSubclass(_cls->cls, type_cls))
...@@ -4391,6 +4467,8 @@ extern "C" void delGlobal(Box* globals, const std::string* name) { ...@@ -4391,6 +4467,8 @@ extern "C" void delGlobal(Box* globals, const std::string* name) {
} }
extern "C" Box* getGlobal(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"); static StatCounter slowpath_getglobal("slowpath_getglobal");
slowpath_getglobal.log(); slowpath_getglobal.log();
static StatCounter nopatch_getglobal("nopatch_getglobal"); static StatCounter nopatch_getglobal("nopatch_getglobal");
...@@ -4485,6 +4563,8 @@ extern "C" Box* getGlobal(Box* globals, const std::string* name) { ...@@ -4485,6 +4563,8 @@ extern "C" Box* getGlobal(Box* globals, const std::string* name) {
} }
extern "C" Box* importFrom(Box* _m, 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); Box* r = getattrInternal(_m, *name, NULL);
if (r) if (r)
return r; return r;
...@@ -4493,6 +4573,8 @@ extern "C" Box* importFrom(Box* _m, const std::string* name) { ...@@ -4493,6 +4573,8 @@ extern "C" Box* importFrom(Box* _m, const std::string* name) {
} }
extern "C" Box* importStar(Box* _from_module, BoxedModule* to_module) { 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; // 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. // 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"); RELEASE_ASSERT(getGlobals() == to_module, "importStar doesn't support custom globals yet");
......
...@@ -96,6 +96,7 @@ void unwindExc(Box* exc_obj) { ...@@ -96,6 +96,7 @@ void unwindExc(Box* exc_obj) {
void raiseRaw(const ExcInfo& e) __attribute__((__noreturn__)); void raiseRaw(const ExcInfo& e) __attribute__((__noreturn__));
void raiseRaw(const ExcInfo& e) { void raiseRaw(const ExcInfo& e) {
STAT_TIMER(t0, "us_timer_raiseraw");
// Should set these to None before getting here: // Should set these to None before getting here:
assert(e.type); assert(e.type);
assert(e.value); assert(e.value);
......
...@@ -1112,6 +1112,7 @@ extern "C" Box* strMod(BoxedString* lhs, Box* rhs) { ...@@ -1112,6 +1112,7 @@ extern "C" Box* strMod(BoxedString* lhs, Box* rhs) {
} }
extern "C" Box* strMul(BoxedString* lhs, Box* rhs) { extern "C" Box* strMul(BoxedString* lhs, Box* rhs) {
STAT_TIMER(t0, "us_timer_strMul");
assert(isSubclass(lhs->cls, str_cls)); assert(isSubclass(lhs->cls, str_cls));
int n; int n;
...@@ -1514,6 +1515,7 @@ failed: ...@@ -1514,6 +1515,7 @@ failed:
} }
extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) { extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) {
STAT_TIMER(t0, "us_timer_unicodeHashUnboxed");
if (self->hash != -1) if (self->hash != -1)
return self->hash; return self->hash;
...@@ -1524,6 +1526,7 @@ extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) { ...@@ -1524,6 +1526,7 @@ extern "C" size_t unicodeHashUnboxed(PyUnicodeObject* self) {
} }
extern "C" Box* strHash(BoxedString* self) { extern "C" Box* strHash(BoxedString* self) {
STAT_TIMER(t0, "us_timer_strHash");
assert(isSubclass(self->cls, str_cls)); assert(isSubclass(self->cls, str_cls));
StringHash<char> H; StringHash<char> H;
......
...@@ -168,6 +168,7 @@ Box* tupleAdd(BoxedTuple* self, Box* rhs) { ...@@ -168,6 +168,7 @@ Box* tupleAdd(BoxedTuple* self, Box* rhs) {
} }
Box* tupleMul(BoxedTuple* self, Box* rhs) { Box* tupleMul(BoxedTuple* self, Box* rhs) {
STAT_TIMER(t0, "us_timer_tupleMul");
if (rhs->cls != int_cls) { if (rhs->cls != int_cls) {
raiseExcHelper(TypeError, "can't multiply sequence by non-int of type '%s'", getTypeName(rhs)); raiseExcHelper(TypeError, "can't multiply sequence by non-int of type '%s'", getTypeName(rhs));
} }
...@@ -337,6 +338,7 @@ Box* tupleIndex(BoxedTuple* self, Box* elt) { ...@@ -337,6 +338,7 @@ Box* tupleIndex(BoxedTuple* self, Box* elt) {
} }
Box* tupleHash(BoxedTuple* self) { Box* tupleHash(BoxedTuple* self) {
STAT_TIMER(t0, "us_timer_tupleHash");
assert(isSubclass(self->cls, tuple_cls)); assert(isSubclass(self->cls, tuple_cls));
int64_t rtn = 3527539; int64_t rtn = 3527539;
......
...@@ -1238,6 +1238,8 @@ public: ...@@ -1238,6 +1238,8 @@ public:
} }
static Box* setitem(Box* _self, Box* _key, Box* value) { static Box* setitem(Box* _self, Box* _key, Box* value) {
STAT_TIMER(t0, "us_timer_AttrWrapper_setitem");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1250,6 +1252,7 @@ public: ...@@ -1250,6 +1252,7 @@ public:
} }
static Box* setdefault(Box* _self, Box* _key, Box* value) { static Box* setdefault(Box* _self, Box* _key, Box* value) {
STAT_TIMER(t0, "us_timer_AttrWrapper_setdefault");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1265,6 +1268,7 @@ public: ...@@ -1265,6 +1268,7 @@ public:
} }
static Box* get(Box* _self, Box* _key, Box* def) { static Box* get(Box* _self, Box* _key, Box* def) {
STAT_TIMER(t0, "us_timer_AttrWrapper_get");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1279,6 +1283,7 @@ public: ...@@ -1279,6 +1283,7 @@ public:
} }
static Box* getitem(Box* _self, Box* _key) { static Box* getitem(Box* _self, Box* _key) {
STAT_TIMER(t0, "us_timer_AttrWrapper_getitem");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1312,6 +1317,7 @@ public: ...@@ -1312,6 +1317,7 @@ public:
} }
static Box* delitem(Box* _self, Box* _key) { static Box* delitem(Box* _self, Box* _key) {
STAT_TIMER(t0, "us_timer_AttrWrapper_delitem");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1377,6 +1383,7 @@ public: ...@@ -1377,6 +1383,7 @@ public:
} }
static Box* values(Box* _self) { static Box* values(Box* _self) {
STAT_TIMER(t0, "us_timer_AttrWrapper_values");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1391,6 +1398,7 @@ public: ...@@ -1391,6 +1398,7 @@ public:
} }
static Box* items(Box* _self) { static Box* items(Box* _self) {
STAT_TIMER(t0, "us_timer_AttrWrapper_items");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
...@@ -1429,6 +1437,7 @@ public: ...@@ -1429,6 +1437,7 @@ public:
} }
static Box* update(Box* _self, Box* _container) { static Box* update(Box* _self, Box* _container) {
STAT_TIMER(t0, "us_timer_AttrWrapper_update");
RELEASE_ASSERT(_self->cls == attrwrapper_cls, ""); RELEASE_ASSERT(_self->cls == attrwrapper_cls, "");
AttrWrapper* self = static_cast<AttrWrapper*>(_self); AttrWrapper* self = static_cast<AttrWrapper*>(_self);
......
...@@ -817,6 +817,11 @@ public: ...@@ -817,6 +817,11 @@ public:
struct Context* context, *returnContext; struct Context* context, *returnContext;
void* stack_begin; void* stack_begin;
#if !DISABLE_STATS
StatTimer* statTimers;
uint64_t timer_time;
#endif
BoxedGenerator(BoxedFunctionBase* function, Box* arg1, Box* arg2, Box* arg3, Box** args); BoxedGenerator(BoxedFunctionBase* function, Box* arg1, Box* arg2, Box* arg3, Box** args);
DEFAULT_CLASS(generator_cls); DEFAULT_CLASS(generator_cls);
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment