Merge pull request #614 from toshok/exception-stats-by-python-line

add per-python line exception stats

src/asm_writing/rewriter.cpp

@@ -17,6 +17,7 @@
 #include <vector>
 
 #include "asm_writing/icinfo.h"
+#include "codegen/unwinding.h"
 #include "core/common.h"
 #include "core/stats.h"
 
@@ -1446,6 +1447,64 @@ Rewriter::Rewriter(ICSlotRewrite* rewrite, int num_args, const std::vector<int>&
     }
 }
 
+#define IC_ATTEMPTS_NAME "ic_attempts"
+#define IC_ATTEMPTS_NOPATCH_NAME "ic_attempts_nopatch"
+#define IC_ATTEMPTS_SKIPPED_NAME "ic_attempts_skipped"
+#define IC_ATTEMPTS_SKIPPED_MEGAMORPHIC_NAME "ic_attempts_skipped_megamorphic"
+#define IC_ATTEMPTS_STARTED_NAME "ic_attempts_started"
+
+static StatCounter ic_attempts(IC_ATTEMPTS_NAME);
+static StatCounter ic_attempts_nopatch(IC_ATTEMPTS_NOPATCH_NAME);
+static StatCounter ic_attempts_skipped(IC_ATTEMPTS_SKIPPED_NAME);
+static StatCounter ic_attempts_skipped_megamorphic(IC_ATTEMPTS_SKIPPED_MEGAMORPHIC_NAME);
+static StatCounter ic_attempts_started(IC_ATTEMPTS_STARTED_NAME);
+
+static inline void log_ic_attempts(const char* debug_name) {
+    ic_attempts.log();
+#if STAT_ICS
+    StatCounter per_type_count(std::string(IC_ATTEMPTS_NAME) + "." + debug_name);
+    per_type_count.log();
+#endif
+}
+
+static inline void log_ic_attempts_nopatch(const char* debug_name) {
+    ic_attempts_nopatch.log();
+#if STAT_ICS
+    StatCounter per_type_count(std::string(IC_ATTEMPTS_NOPATCH_NAME) + "." + debug_name);
+    per_type_count.log();
+#endif
+}
+
+static inline void log_ic_attempts_skipped(const char* debug_name) {
+    ic_attempts_skipped.log();
+#if STAT_ICS
+    std::string stat_name = std::string(IC_ATTEMPTS_SKIPPED_NAME) + "." + debug_name;
+    Stats::log(Stats::getStatCounter(stat_name));
+#if STAT_ICS_LOCATION
+    logByCurrentPythonLine(stat_name);
+#endif
+#endif
+}
+
+static inline void log_ic_attempts_skipped_megamorphic(const char* debug_name) {
+    ic_attempts_skipped_megamorphic.log();
+#if STAT_ICS
+    std::string stat_name = std::string(IC_ATTEMPTS_SKIPPED_MEGAMORPHIC_NAME) + "." + debug_name;
+    Stats::log(Stats::getStatCounter(stat_name));
+#if STAT_ICS_LOCATION
+    logByCurrentPythonLine(stat_name);
+#endif
+#endif
+}
+
+static inline void log_ic_attempts_started(const char* debug_name) {
+    ic_attempts_started.log();
+#if STAT_ICS
+    StatCounter per_type_count(std::string(IC_ATTEMPTS_STARTED_NAME) + "." + debug_name);
+    per_type_count.log();
+#endif
+}
+
 Rewriter* Rewriter::createRewriter(void* rtn_addr, int num_args, const char* debug_name) {
     ICInfo* ic = NULL;
 
@@ -1457,28 +1516,22 @@ Rewriter* Rewriter::createRewriter(void* rtn_addr, int num_args, const char* deb
         assert(!getICInfo(rtn_addr));
     }
 
-    static StatCounter ic_attempts("ic_attempts");
-    static StatCounter ic_attempts_nopatch("ic_attempts_nopatch");
-    static StatCounter ic_attempts_skipped("ic_attempts_skipped");
-    static StatCounter ic_attempts_skipped_megamorphic("ic_attempts_skipped_megamorphic");
-    static StatCounter ic_attempts_started("ic_attempts_started");
-
-    ic_attempts.log();
+    log_ic_attempts(debug_name);
 
     if (!ic) {
-        ic_attempts_nopatch.log();
+        log_ic_attempts_nopatch(debug_name);
         return NULL;
     }
 
     if (!ic->shouldAttempt()) {
-        ic_attempts_skipped.log();
+        log_ic_attempts_skipped(debug_name);
 
         if (ic->isMegamorphic())
-            ic_attempts_skipped_megamorphic.log();
+            log_ic_attempts_skipped_megamorphic(debug_name);
         return NULL;
     }
 
-    ic_attempts_started.log();
+    log_ic_attempts_started(debug_name);
     return new Rewriter(ic->startRewrite(debug_name), num_args, ic->getLiveOuts());
 }
 

src/codegen/unwinding.cpp

@@ -15,6 +15,7 @@
 #include "codegen/unwinding.h"
 
 #include <dlfcn.h>
+#include <sstream>
 #include <sys/types.h>
 #include <unistd.h>
 
@@ -989,6 +990,28 @@ PythonFrameIterator PythonFrameIterator::back() {
     return PythonFrameIterator(std::move(rtn));
 }
 
+std::string getCurrentPythonLine() {
+    auto frame_iter = getTopPythonFrame();
+
+    if (frame_iter.get()) {
+        std::ostringstream stream;
+
+        auto* cf = frame_iter->getCF();
+        auto source = cf->clfunc->source.get();
+
+        auto current_stmt = frame_iter->getCurrentStatement();
+
+        stream << source->fn << ":" << current_stmt->lineno;
+        return stream.str();
+    }
+    return "unknown:-1";
+}
+
+void logByCurrentPythonLine(std::string& stat_name) {
+    std::string stat = stat_name + "<" + getCurrentPythonLine() + ">";
+    Stats::log(Stats::getStatCounter(stat));
+}
+
 llvm::JITEventListener* makeTracebacksListener() {
     return new TracebacksEventListener();
 }

src/codegen/unwinding.h

@@ -42,6 +42,12 @@ struct ExecutionPoint {
 };
 ExecutionPoint getExecutionPoint();
 
+// debugging/stat helper, returns python filename:linenumber, or "unknown:-1" if it fails
+std::string getCurrentPythonLine();
+
+// doesn't really belong in unwinding.h, since it's stats related, but it needs to unwind to get the current line...
+void logByCurrentPythonLine(std::string& stat_name);
+
 // Adds stack locals and closure locals into the locals dict, and returns it.
 Box* fastLocalsToBoxedLocals();
 

src/core/stats.h

@@ -30,6 +30,9 @@ namespace pyston {
 
 #define STAT_ALLOCATIONS (0 && !DISABLE_STATS)
 #define STAT_EXCEPTIONS (0 && !DISABLE_STATS)
+#define STAT_EXCEPTIONS_LOCATION (0 && STAT_EXCEPTIONS)
+#define STAT_ICS (0 && !DISABLE_STATS)
+#define STAT_ICS_LOCATION (0 && STAT_ICS)
 #define STAT_TIMERS (0 && !DISABLE_STATS)
 #define EXPENSIVE_STAT_TIMERS (0 && STAT_TIMERS)
 

src/runtime/stacktrace.cpp

@@ -67,6 +67,9 @@ void raiseRaw(const ExcInfo& e) {
     else
         stat_name = "num_exceptions_" + std::string(e.value->cls->tp_name);
     Stats::log(Stats::getStatCounter(stat_name));
+#if STAT_EXCEPTIONS_LOCATION
+    logByCurrentPythonLine(stat_name);
+#endif
 #endif
 
     throw e;

tools/exception_stats.py

+import argparse
+import os
+import subprocess
+import sys
+import time
+
+def output_stats(stats, total_count):
+    if total_count is 0:
+        return
+    stats.sort(key=lambda (name,s): s, reverse=True)
+    for (name, s) in stats[:5]:
+        print "%80s  %d (%.0f%%)" % (name, s, 100.0 * s / total_count)
+
+if __name__ == "__main__":
+    cmd = ["./pyston_release", "-Ts", sys.argv[1]]
+
+    start = time.time()
+    p = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+    out, err = p.communicate()
+    assert p.wait() == 0
+    elapsed = time.time() - start
+    open('tmp.txt', 'w').write(out)
+
+    # elapsed = 1.5
+    # out = open("tmp.txt").read()
+
+    is_counter = False
+
+    current_header = ""
+    current_count = 0
+    stats = []
+    
+    for l in out.split('\n'):
+        if not l.startswith('num_exceptions_'):
+            continue
+
+        if '<' in l:
+            name = l[:l.rindex(':')]
+            count = int(l[l.rindex(':')+1:])
+            source_loc = name[name.index('<')+1:name.rindex('>')]
+            stats.append((source_loc, count))
+        else:
+            if len(stats) > 0:
+                output_stats(stats, current_count)
+
+            name, count = l.split(':')
+            current_count = int(count)
+                
+            current_header = name[len('num_exceptions_'):]
+            print "\n\n%80s  %d" % (current_header, current_count)
+            stats = []
+
+    if len(stats) > 0:
+        output_stats(stats, current_count)

tools/ic_stats.py

+import argparse
+import os
+import subprocess
+import sys
+import time
+
+def output_stats(stats, total_count):
+    if total_count is 0:
+        return
+    stats.sort(key=lambda (name,s): s, reverse=True)
+    for (name, s) in stats[:5]:
+        print "%80s  %d (%.0f%%)" % (name, s, 100.0 * s / total_count)
+
+if __name__ == "__main__":
+    cmd = ["./pyston_release", "-Ts", sys.argv[1]]
+
+    start = time.time()
+    p = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+    out, err = p.communicate()
+    assert p.wait() == 0
+    elapsed = time.time() - start
+    open('tmp.txt', 'w').write(out)
+
+    # elapsed = 1.5
+    # out = open("tmp.txt").read()
+
+    is_counter = False
+
+    current_header = ""
+    current_count = 0
+    stats = []
+    
+    for l in out.split('\n'):
+        if not l.startswith('ic_attempts_skipped'):
+            continue
+
+        name = l[:l.rindex(':')]
+        count = int(l[l.rindex(':')+1:])
+
+        if name.strip() == "ic_attempts_skipped" or name.strip() == "ic_attempts_skipped_megamorphic":
+            continue
+
+        if '<' in l:
+            source_loc = name[name.index('<')+1:name.rindex('>')]
+            stats.append((source_loc, count))
+        else:
+            if len(stats) > 0:
+                output_stats(stats, current_count)
+
+            current_count = count
+
+            prefix = 'ic_attempts_skipped_'
+                
+            current_header = name[len(prefix):]
+            print "\n\n%80s  %d" % (current_header, current_count)
+            stats = []
+
+    if len(stats) > 0:
+        output_stats(stats, current_count)