Merge pull request #628 from kmod/perf3

rewrite wrapperdescriptors

src/asm_writing/icinfo.h

@@ -80,6 +80,8 @@ public:
 
     const ICInfo* getICInfo() { return ic; }
 
+    const char* debugName() { return debug_name; }
+
     friend class ICInfo;
 };
 

src/asm_writing/rewriter.h

@@ -371,6 +371,9 @@ private:
                 failed = true;
                 return;
             }
+            for (RewriterVar* arg : args) {
+                arg->uses.push_back(actions.size());
+            }
             assert(!added_changing_action);
             last_guard_action = (int)actions.size();
         }
@@ -388,6 +391,12 @@ private:
         return done_guarding;
     }
 
+    // Move the original IC args back into their original registers:
+    void restoreArgs();
+    // Assert that our original args are correctly placed in case we need to
+    // bail out of the IC:
+    void assertArgsInPlace();
+
     // Allocates a register.  dest must be of type Register or AnyReg
     // If otherThan is a register, guaranteed to not use that register.
     assembler::Register allocReg(Location dest, Location otherThan = Location::any());
@@ -414,7 +423,7 @@ private:
 
     void _trap();
     void _loadConst(RewriterVar* result, int64_t val);
-    void _call(RewriterVar* result, bool can_call_into_python, void* func_addr, const RewriterVar::SmallVector& args,
+    void _call(RewriterVar* result, bool has_side_effects, void* func_addr, const RewriterVar::SmallVector& args,
                const RewriterVar::SmallVector& args_xmm);
     void _add(RewriterVar* result, RewriterVar* a, int64_t b, Location dest);
     int _allocate(RewriterVar* result, int n);
@@ -448,6 +457,11 @@ private:
                 assert(p.second->locations.count(p.first) == 1);
             }
         }
+        if (!done_guarding) {
+            for (RewriterVar* arg : args) {
+                assert(!arg->locations.empty());
+            }
+        }
 #endif
     }
 
@@ -474,19 +488,23 @@ public:
 
     TypeRecorder* getTypeRecorder();
 
+    const char* debugName() { return rewrite->debugName(); }
+
     void trap();
     RewriterVar* loadConst(int64_t val, Location loc = Location::any());
-    // can_call_into_python: whether this call could result in arbitrary Python code being called.
-    // This causes some extra bookkeeping to prevent, ex this patchpoint to be rewritten when
-    // entered recursively.  Setting to false disables this for slightly better performance, but
-    // it's not huge so if in doubt just pass "true".
-    RewriterVar* call(bool can_call_into_python, void* func_addr, const RewriterVar::SmallVector& args,
+    // has_side_effects: whether this call could have "side effects".  the exact side effects we've
+    // been concerned about have changed over time, so it's better to err on the side of saying "true",
+    // but currently you can only set it to false if 1) you will not call into Python code, which basically
+    // can have any sorts of side effects, but in particular could result in the IC being reentrant, and
+    // 2) does not have any side-effects that would be user-visible if we bailed out from the middle of the
+    // inline cache.  (Extra allocations don't count even though they're potentially visible if you look
+    // hard enough.)
+    RewriterVar* call(bool has_side_effects, void* func_addr, const RewriterVar::SmallVector& args,
                       const RewriterVar::SmallVector& args_xmm = RewriterVar::SmallVector());
-    RewriterVar* call(bool can_call_into_python, void* func_addr);
-    RewriterVar* call(bool can_call_into_python, void* func_addr, RewriterVar* arg0);
-    RewriterVar* call(bool can_call_into_python, void* func_addr, RewriterVar* arg0, RewriterVar* arg1);
-    RewriterVar* call(bool can_call_into_python, void* func_addr, RewriterVar* arg0, RewriterVar* arg1,
-                      RewriterVar* arg2);
+    RewriterVar* call(bool has_side_effects, void* func_addr);
+    RewriterVar* call(bool has_side_effects, void* func_addr, RewriterVar* arg0);
+    RewriterVar* call(bool has_side_effects, void* func_addr, RewriterVar* arg0, RewriterVar* arg1);
+    RewriterVar* call(bool has_side_effects, void* func_addr, RewriterVar* arg0, RewriterVar* arg1, RewriterVar* arg2);
     RewriterVar* add(RewriterVar* a, int64_t b, Location dest);
     // Allocates n pointer-sized stack slots:
     RewriterVar* allocate(int n);

src/codegen/ast_interpreter.cpp

@@ -278,6 +278,7 @@ ASTInterpreter::ASTInterpreter(CompiledFunction* compiled_function)
       generator(0),
       edgecount(0),
       frame_info(ExcInfo(NULL, NULL, NULL)),
+      globals(0),
       frame_addr(0) {
 
     CLFunction* f = compiled_function->clfunc;
@@ -386,7 +387,7 @@ Value ASTInterpreter::executeInner(ASTInterpreter& interpreter, CFGBlock* start_
 }
 
 Value ASTInterpreter::execute(ASTInterpreter& interpreter, CFGBlock* start_block, AST_stmt* start_at) {
-    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_astinterpreter_execute");
+    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_in_interpreter");
 
     RegisterHelper frame_registerer;
 
@@ -605,7 +606,7 @@ Value ASTInterpreter::visit_jump(AST_Jump* node) {
                 arg_array.push_back(it.second);
             }
 
-            UNAVOIDABLE_STAT_TIMER(t0, "us_timer_astinterpreter_jump_osrexit");
+            UNAVOIDABLE_STAT_TIMER(t0, "us_timer_in_jitted_code");
             CompiledFunction* partial_func = compilePartialFuncInternal(&exit);
             auto arg_tuple = getTupleFromArgsArray(&arg_array[0], arg_array.size());
             Box* r = partial_func->call(std::get<0>(arg_tuple), std::get<1>(arg_tuple), std::get<2>(arg_tuple),
@@ -1295,7 +1296,7 @@ const void* interpreter_instr_addr = (void*)&ASTInterpreter::executeInner;
 
 Box* astInterpretFunction(CompiledFunction* cf, int nargs, Box* closure, Box* generator, Box* globals, Box* arg1,
                           Box* arg2, Box* arg3, Box** args) {
-    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_astInterpretFunction");
+    UNAVOIDABLE_STAT_TIMER(t0, "us_timer_in_interpreter");
 
     assert((!globals) == cf->clfunc->source->scoping->areGlobalsFromModule());
     bool can_reopt = ENABLE_REOPT && !FORCE_INTERPRETER && (globals == NULL);

src/codegen/entry.cpp

@@ -362,6 +362,15 @@ static void handle_sigprof(int signum) {
     sigprof_pending++;
 }
 
+//#define INVESTIGATE_STAT_TIMER "us_timer_in_jitted_code"
+#ifdef INVESTIGATE_STAT_TIMER
+static uint64_t* stat_counter = Stats::getStatCounter(INVESTIGATE_STAT_TIMER);
+static void handle_sigprof_investigate_stattimer(int signum) {
+    if (StatTimer::getCurrentCounter() == stat_counter)
+        raise(SIGTRAP);
+}
+#endif
+
 static void handle_sigint(int signum) {
     assert(signum == SIGINT);
     // TODO: this should set a flag saying a KeyboardInterrupt is pending.
@@ -475,6 +484,14 @@ void initCodegen() {
     setitimer(ITIMER_PROF, &prof_timer, NULL);
 #endif
 
+#ifdef INVESTIGATE_STAT_TIMER
+    struct itimerval prof_timer;
+    prof_timer.it_value.tv_sec = prof_timer.it_interval.tv_sec = 0;
+    prof_timer.it_value.tv_usec = prof_timer.it_interval.tv_usec = 1000;
+    signal(SIGPROF, handle_sigprof_investigate_stattimer);
+    setitimer(ITIMER_PROF, &prof_timer, NULL);
+#endif
+
     // There are some parts of llvm that are only configurable through command line args,
     // so construct a fake argc/argv pair and pass it to the llvm command line machinery:
     std::vector<const char*> llvm_args = { "fake_name" };

src/codegen/parser.cpp

@@ -1159,6 +1159,7 @@ AST_Module* caching_parse_file(const char* fn) {
             if (strncmp(&file_data[0], getMagic(), MAGIC_STRING_LENGTH) != 0) {
                 if (VERBOSITY() || tries == MAX_TRIES) {
                     fprintf(stderr, "Warning: corrupt or non-Pyston .pyc file found; ignoring\n");
+                    fprintf(stderr, "%d %d %d %d\n", file_data[0], file_data[1], file_data[2], file_data[3]);
                 }
                 good = false;
             }

src/core/stats.cpp

@@ -50,6 +50,12 @@ StatTimer* StatTimer::createStack(StatTimer& timer) {
     timer.pushTopLevel(at_time);
     return prev_stack;
 }
+
+uint64_t* StatTimer::getCurrentCounter() {
+    if (stack)
+        return stack->_statcounter;
+    return NULL;
+}
 #endif
 
 std::unordered_map<uint64_t*, std::string>* Stats::names;

src/core/stats.h

@@ -206,6 +206,8 @@ public:
     static StatTimer* createStack(StatTimer& timer);
     static StatTimer* swapStack(StatTimer* s);
 
+    static uint64_t* getCurrentCounter();
+
     static void assertActive() { ASSERT(stack && !stack->isPaused(), ""); }
 };
 class ScopedStatTimer {

src/core/threading.cpp

@@ -167,8 +167,10 @@ static void pushThreadState(ThreadStateInternal* thread_state, ucontext_t* conte
 #endif
 
     assert(stack_low < stack_high);
+    GC_TRACE_LOG("Visiting other thread's stack\n");
     cur_visitor->visitPotentialRange((void**)stack_low, (void**)stack_high);
 
+    GC_TRACE_LOG("Visiting other thread's threadstate + generator stacks\n");
     thread_state->accept(cur_visitor);
 }
 
@@ -195,8 +197,12 @@ static void visitLocalStack(gc::GCVisitor* v) {
 #endif
 
     assert(stack_low < stack_high);
+
+    GC_TRACE_LOG("Visiting current stack from %p to %p\n", stack_low, stack_high);
+
     v->visitPotentialRange((void**)stack_low, (void**)stack_high);
 
+    GC_TRACE_LOG("Visiting current thread's threadstate + generator stacks\n");
     current_internal_thread_state->accept(v);
 }
 

src/gc/collector.cpp

@@ -35,8 +35,6 @@
 //#undef VERBOSITY
 //#define VERBOSITY(x) 2
 
-#define DEBUG_MARK_PHASE 0
-
 #ifndef NDEBUG
 #define DEBUG 1
 #else
@@ -46,11 +44,8 @@
 namespace pyston {
 namespace gc {
 
-#if DEBUG_MARK_PHASE
+#if TRACE_GC_MARKING
 FILE* trace_fp;
-#define TRACE_LOG(...) fprintf(trace_fp, __VA_ARGS__)
-#else
-#define TRACE_LOG(...)
 #endif
 
 class TraceStack {
@@ -100,7 +95,7 @@ public:
     }
 
     void push(void* p) {
-        TRACE_LOG("Pushing %p\n", p);
+        GC_TRACE_LOG("Pushing %p\n", p);
         GCAllocation* al = GCAllocation::fromUserData(p);
         if (isMarked(al))
             return;
@@ -271,11 +266,19 @@ void GCVisitor::visitPotentialRange(void* const* start, void* const* end) {
     assert((uintptr_t)end % sizeof(void*) == 0);
 
     while (start < end) {
+#if TRACE_GC_MARKING
+        if (global_heap.getAllocationFromInteriorPointer(*start)) {
+            GC_TRACE_LOG("Found conservative reference to %p from %p\n", *start, start);
+        }
+#endif
+
         visitPotential(*start);
         start++;
     }
 }
 
+static int ncollections = 0;
+
 void markPhase() {
 #ifndef NVALGRIND
     // Have valgrind close its eyes while we do the conservative stack and data scanning,
@@ -283,31 +286,37 @@ void markPhase() {
     VALGRIND_DISABLE_ERROR_REPORTING;
 #endif
 
-#if DEBUG_MARK_PHASE
+#if TRACE_GC_MARKING
+#if 1 // separate log file per collection
+    char tracefn_buf[80];
+    snprintf(tracefn_buf, sizeof(tracefn_buf), "gc_trace_%03d.txt", ncollections);
+    trace_fp = fopen(tracefn_buf, "w");
+#else // overwrite previous log file with each collection
     trace_fp = fopen("gc_trace.txt", "w");
 #endif
-    TRACE_LOG("Starting collection\n");
+#endif
+    GC_TRACE_LOG("Starting collection %d\n", ncollections);
 
-    TRACE_LOG("Looking at roots\n");
+    GC_TRACE_LOG("Looking at roots\n");
     TraceStack stack(roots);
     GCVisitor visitor(&stack);
 
-    TRACE_LOG("Looking at the stack\n");
+    GC_TRACE_LOG("Looking at the stack\n");
     threading::visitAllStacks(&visitor);
 
-    TRACE_LOG("Looking at root handles\n");
+    GC_TRACE_LOG("Looking at root handles\n");
     for (auto h : *getRootHandles()) {
         visitor.visit(h->value);
     }
 
-    TRACE_LOG("Looking at potential root ranges\n");
+    GC_TRACE_LOG("Looking at potential root ranges\n");
     for (auto& e : potential_root_ranges) {
         visitor.visitPotentialRange((void* const*)e.first, (void* const*)e.second);
     }
 
     // if (VERBOSITY()) printf("Found %d roots\n", stack.size());
     while (void* p = stack.pop()) {
-        TRACE_LOG("Looking at heap object %p\n", p);
+        GC_TRACE_LOG("Looking at heap object %p\n", p);
         assert(((intptr_t)p) % 8 == 0);
         GCAllocation* al = GCAllocation::fromUserData(p);
 
@@ -356,7 +365,7 @@ void markPhase() {
         }
     }
 
-#if DEBUG_MARK_PHASE
+#if TRACE_GC_MARKING
     fclose(trace_fp);
     trace_fp = NULL;
 #endif
@@ -383,7 +392,6 @@ void disableGC() {
     gc_enabled = false;
 }
 
-static int ncollections = 0;
 static bool should_not_reenter_gc = false;
 
 void startGCUnexpectedRegion() {

src/gc/collector.h

@@ -22,6 +22,14 @@
 namespace pyston {
 namespace gc {
 
+#define TRACE_GC_MARKING 0
+#if TRACE_GC_MARKING
+extern FILE* trace_fp;
+#define GC_TRACE_LOG(...) fprintf(pyston::gc::trace_fp, __VA_ARGS__)
+#else
+#define GC_TRACE_LOG(...)
+#endif
+
 // Mark this gc-allocated object as being a root, even if there are no visible references to it.
 // (Note: this marks the gc allocation itself, not the pointer that points to one.  For that, use
 // a GCRootHandle)

src/gc/gc_alloc.h

@@ -48,7 +48,7 @@ extern "C" inline void* gc_alloc(size_t bytes, GCKind kind_id) {
     // This stat timer is quite expensive, not just because this function is extremely hot,
     // but also because it tends to increase the size of this function enough that we can't
     // inline it, which is especially useful for this function.
-    ScopedStatTimer gc_alloc_stattimer(gc_alloc_stattimer_counter);
+    ScopedStatTimer gc_alloc_stattimer(gc_alloc_stattimer_counter, 15);
 #endif
     size_t alloc_bytes = bytes + sizeof(GCAllocation);
 

src/runtime/generator.cpp

@@ -118,6 +118,8 @@ Box* generatorIter(Box* s) {
 
 // called from both generatorHasNext and generatorSend/generatorNext (but only if generatorHasNext hasn't been called)
 static void generatorSendInternal(BoxedGenerator* self, Box* v) {
+    STAT_TIMER(t0, "us_timer_generator_switching", 0);
+
     if (self->running)
         raiseExcHelper(ValueError, "generator already executing");
 
@@ -260,6 +262,8 @@ Box* generatorHasnext(Box* s) {
 
 
 extern "C" Box* yield(BoxedGenerator* obj, Box* value) {
+    STAT_TIMER(t0, "us_timer_generator_switching", 0);
+
     assert(obj->cls == generator_cls);
     BoxedGenerator* self = static_cast<BoxedGenerator*>(obj);
     self->returnValue = value;

src/runtime/ics.h

@@ -78,7 +78,7 @@ public:
 
 class BinopIC : public RuntimeIC {
 public:
-    BinopIC() : RuntimeIC((void*)binop, 2, 160) {}
+    BinopIC() : RuntimeIC((void*)binop, 2, 240) {}
 
     Box* call(Box* lhs, Box* rhs, int op_type) { return (Box*)call_ptr(lhs, rhs, op_type); }
 };

src/runtime/iterators.cpp

@@ -39,6 +39,8 @@ public:
     }
 
     void next() override {
+        STAT_TIMER(t0, "us_timer_iteratorgeneric_next", 0);
+
         assert(iterator);
         Box* hasnext = iterator->hasnextOrNullIC();
         if (hasnext) {

src/runtime/objmodel.cpp

@@ -128,7 +128,7 @@ static uint64_t* pylt_timer_counter = Stats::getStatCounter("us_timer_PyLt");
 #endif
 size_t PyHasher::operator()(Box* b) const {
 #if EXPENSIVE_STAT_TIMERS
-    ScopedStatTimer _st(pyhasher_timer_counter);
+    ScopedStatTimer _st(pyhasher_timer_counter, 10);
 #endif
     if (b->cls == str_cls) {
         StringHash<char> H;
@@ -141,7 +141,7 @@ size_t PyHasher::operator()(Box* b) const {
 
 bool PyEq::operator()(Box* lhs, Box* rhs) const {
 #if EXPENSIVE_STAT_TIMERS
-    ScopedStatTimer _st(pyeq_timer_counter);
+    ScopedStatTimer _st(pyeq_timer_counter, 10);
 #endif
 
     int r = PyObject_RichCompareBool(lhs, rhs, Py_EQ);
@@ -152,7 +152,7 @@ bool PyEq::operator()(Box* lhs, Box* rhs) const {
 
 bool PyLt::operator()(Box* lhs, Box* rhs) const {
 #if EXPENSIVE_STAT_TIMERS
-    ScopedStatTimer _st(pylt_timer_counter);
+    ScopedStatTimer _st(pylt_timer_counter, 10);
 #endif
 
     int r = PyObject_RichCompareBool(lhs, rhs, Py_LT);
@@ -984,7 +984,7 @@ Box* typeLookup(BoxedClass* cls, llvm::StringRef attr, GetattrRewriteArgs* rewri
 
 bool isNondataDescriptorInstanceSpecialCase(Box* descr) {
     return descr->cls == function_cls || descr->cls == instancemethod_cls || descr->cls == staticmethod_cls
-           || descr->cls == classmethod_cls;
+           || descr->cls == classmethod_cls || descr->cls == wrapperdescr_cls;
 }
 
 Box* nondataDescriptorInstanceSpecialCases(GetattrRewriteArgs* rewrite_args, Box* obj, Box* descr, RewriterVar* r_descr,
@@ -1058,7 +1058,7 @@ Box* nondataDescriptorInstanceSpecialCases(GetattrRewriteArgs* rewrite_args, Box
         if (!for_call) {
             if (rewrite_args) {
                 rewrite_args->out_rtn
-                    = rewrite_args->rewriter->call(true, (void*)boxInstanceMethod, r_im_self, r_im_func, r_im_class);
+                    = rewrite_args->rewriter->call(false, (void*)boxInstanceMethod, r_im_self, r_im_func, r_im_class);
                 rewrite_args->out_success = true;
             }
             return boxInstanceMethod(im_self, im_func, im_class);
@@ -1071,12 +1071,7 @@ Box* nondataDescriptorInstanceSpecialCases(GetattrRewriteArgs* rewrite_args, Box
             }
             return im_func;
         }
-    }
-
-    else if (descr->cls == staticmethod_cls) {
-        static StatCounter slowpath("slowpath_staticmethod_get");
-        slowpath.log();
-
+    } else if (descr->cls == staticmethod_cls) {
         BoxedStaticmethod* sm = static_cast<BoxedStaticmethod*>(descr);
         if (sm->sm_callable == NULL) {
             raiseExcHelper(RuntimeError, "uninitialized staticmethod object");
@@ -1090,6 +1085,23 @@ Box* nondataDescriptorInstanceSpecialCases(GetattrRewriteArgs* rewrite_args, Box
         }
 
         return sm->sm_callable;
+    } else if (descr->cls == wrapperdescr_cls) {
+        BoxedWrapperDescriptor* self = static_cast<BoxedWrapperDescriptor*>(descr);
+        Box* inst = obj;
+        Box* owner = obj->cls;
+
+        Box* r = BoxedWrapperDescriptor::__get__(self, inst, owner);
+
+        if (rewrite_args) {
+            // TODO: inline this?
+            RewriterVar* r_rtn = rewrite_args->rewriter->call(
+                /* has_side_effects= */ false, (void*)&BoxedWrapperDescriptor::__get__, r_descr, rewrite_args->obj,
+                r_descr->getAttr(offsetof(Box, cls), Location::forArg(2)));
+
+            rewrite_args->out_success = true;
+            rewrite_args->out_rtn = r_rtn;
+        }
+        return r;
     }
 
     return NULL;
@@ -1120,14 +1132,13 @@ Box* descriptorClsSpecialCases(GetattrRewriteArgs* rewrite_args, BoxedClass* cls
         return descr;
     }
 
-    // Special case: member descriptor
-    if (descr->cls == member_descriptor_cls) {
+    // These classes are descriptors, but only have special behavior when involved
+    // in instance lookups
+    if (descr->cls == member_descriptor_cls || descr->cls == wrapperdescr_cls) {
         if (rewrite_args)
             r_descr->addAttrGuard(BOX_CLS_OFFSET, (uint64_t)descr->cls);
 
         if (rewrite_args) {
-            // Actually just return val (it's a descriptor but only
-            // has special behaviour for instance lookups - see below)
             rewrite_args->out_rtn = r_descr;
             rewrite_args->out_success = true;
         }
@@ -1332,7 +1343,7 @@ Box* dataDescriptorInstanceSpecialCases(GetattrRewriteArgs* rewrite_args, llvm::
 
             RewriterVar* r_closure = r_descr->getAttr(offsetof(BoxedGetsetDescriptor, closure));
             rewrite_args->out_rtn = rewrite_args->rewriter->call(
-                /* can_call_into_python */ true, (void*)getset_descr->get, rewrite_args->obj, r_closure);
+                /* has_side_effects */ true, (void*)getset_descr->get, rewrite_args->obj, r_closure);
 
             if (descr->cls == capi_getset_cls)
                 // TODO I think we are supposed to check the return value?
@@ -1896,7 +1907,7 @@ bool dataDescriptorSetSpecialCases(Box* obj, Box* val, Box* descr, SetattrRewrit
             args.push_back(r_val);
             args.push_back(r_closure);
             rewrite_args->rewriter->call(
-                /* can_call_into_python */ true, (void*)getset_descr->set, args);
+                /* has_side_effects */ true, (void*)getset_descr->set, args);
 
             if (descr->cls == capi_getset_cls)
                 // TODO I think we are supposed to check the return value?
@@ -2021,7 +2032,7 @@ void setattrGeneric(Box* obj, BoxedString* attr, Box* val, SetattrRewriteArgs* r
 }
 
 extern "C" void setattr(Box* obj, BoxedString* attr, Box* attr_val) {
-    STAT_TIMER(t0, "us_timer_slowpath_setsattr", 10);
+    STAT_TIMER(t0, "us_timer_slowpath_setattr", 10);
 
     static StatCounter slowpath_setattr("slowpath_setattr");
     slowpath_setattr.log();
@@ -3415,10 +3426,10 @@ Box* callCLFunc(CLFunction* f, CallRewriteArgs* rewrite_args, int num_output_arg
     // distinguish lexically between calls that target jitted python
     // code and calls that target to builtins.
     if (f->source) {
-        UNAVOIDABLE_STAT_TIMER(t0, "us_timer_chosen_cf_body_jitted");
+        UNAVOIDABLE_STAT_TIMER(t0, "us_timer_in_jitted_code");
         r = callChosenCF(chosen_cf, closure, generator, oarg1, oarg2, oarg3, oargs);
     } else {
-        UNAVOIDABLE_STAT_TIMER(t0, "us_timer_chosen_cf_body_builtins");
+        UNAVOIDABLE_STAT_TIMER(t0, "us_timer_in_builtins");
         r = callChosenCF(chosen_cf, closure, generator, oarg1, oarg2, oarg3, oargs);
     }
 
@@ -3584,6 +3595,13 @@ extern "C" Box* runtimeCall(Box* obj, ArgPassSpec argspec, Box* arg1, Box* arg2,
         __builtin_extract_return_addr(__builtin_return_address(0)), num_orig_args, "runtimeCall"));
     Box* rtn;
 
+#if 0 && STAT_TIMERS
+    static uint64_t* st_id = Stats::getStatCounter("us_timer_slowpath_runtimecall_patchable");
+    static uint64_t* st_id_nopatch = Stats::getStatCounter("us_timer_slowpath_runtimecall_nopatch");
+    bool havepatch = (bool)getICInfo(__builtin_extract_return_addr(__builtin_return_address(0)));
+    ScopedStatTimer st(havepatch ? st_id : st_id_nopatch, 10);
+#endif
+
     if (rewriter.get()) {
         // TODO feel weird about doing this; it either isn't necessary
         // or this kind of thing is necessary in a lot more places
@@ -3731,6 +3749,13 @@ extern "C" Box* binopInternal(Box* lhs, Box* rhs, int op_type, bool inplace, Bin
 
 extern "C" Box* binop(Box* lhs, Box* rhs, int op_type) {
     STAT_TIMER(t0, "us_timer_slowpath_binop", 10);
+    bool can_patchpoint = !isUserDefined(lhs->cls) && !isUserDefined(rhs->cls);
+#if 0
+    static uint64_t* st_id = Stats::getStatCounter("us_timer_slowpath_binop_patchable");
+    static uint64_t* st_id_nopatch = Stats::getStatCounter("us_timer_slowpath_binop_nopatch");
+    bool havepatch = (bool)getICInfo(__builtin_extract_return_addr(__builtin_return_address(0)));
+    ScopedStatTimer st((havepatch && can_patchpoint)? st_id : st_id_nopatch, 10);
+#endif
 
     static StatCounter slowpath_binop("slowpath_binop");
     slowpath_binop.log();
@@ -3744,7 +3769,6 @@ extern "C" Box* binop(Box* lhs, Box* rhs, int op_type) {
     // resolving it one way right now (ex, using the value from lhs.__add__) means that later
     // we'll resolve it the same way, even for the same argument types.
     // TODO implement full resolving semantics inside the rewrite?
-    bool can_patchpoint = !isUserDefined(lhs->cls) && !isUserDefined(rhs->cls);
     if (can_patchpoint)
         rewriter.reset(
             Rewriter::createRewriter(__builtin_extract_return_addr(__builtin_return_address(0)), 3, "binop"));

tools/tester.py

@@ -365,21 +365,29 @@ def determine_test_result(fn, opts, code, out, stderr, elapsed):
                 if opts.expected == "statfail":
                     r += ("(expected statfailure)",)
                     break
-                elif KEEP_GOING:
-                    failed.append(fn)
-                    return r + ("\033[31mFailed statcheck\033[0m",)
                 else:
+                    msg = ()
                     m = re.match("""stats\[['"]([\w_]+)['"]]""", l)
                     if m:
                         statname = m.group(1)
-                        raise Exception((l, statname, stats[statname]))
+                        msg = (l, statname, stats[statname])
 
                     m = re.search("""noninit_count\(['"]([\w_]+)['"]\)""", l)
-                    if m:
+                    if m and not msg:
                         statname = m.group(1)
-                        raise Exception((l, statname, noninit_count(statname)))
-
-                    raise Exception((l, stats))
+                        msg = (l, statname, noninit_count(statname))
+
+                    if not msg:
+                        msg = (l, stats)
+
+                    elif KEEP_GOING:
+                        failed.append(fn)
+                        if VERBOSE:
+                            return r + ("\033[31mFailed statcheck\033[0m\n%s" % (msg,),)
+                        else:
+                            return r + ("\033[31mFailed statcheck\033[0m",)
+                    else:
+                        raise Exception(msg)
         else:
             # only can get here if all statchecks passed
             if opts.expected == "statfail":
@@ -387,7 +395,7 @@ def determine_test_result(fn, opts, code, out, stderr, elapsed):
                     failed.append(fn)
                     return r + ("\033[31mUnexpected statcheck success\033[0m",)
                 else:
-                    raise Exception(("Unexpected statcheck success!", statchecks, stats))
+                    raise Exception(("Unexpected statcheck success!", opts.statchecks, stats))
     else:
         r += ("(ignoring stats)",)