Collect + print more stats

- make heap dumping work again
- refactor some of the heap statistics to work in OOM scenarios
  (ie be able to not collect the ones that would require allocation to track)
- collect some hcls statistics as well
- print stats to stderr rather than stdout
  - I think this makes more sense since it is not really part of the program
    output; it also makes it more likely that "PYSTON_RUN_ARGS=s" will work

src/core/stats.cpp

@@ -17,6 +17,7 @@
 #include <algorithm>
 
 #include "core/thread_utils.h"
+#include "gc/heap.h"
 
 namespace pyston {
 
@@ -55,7 +56,11 @@ void Stats::dump(bool includeZeros) {
     if (!Stats::enabled)
         return;
 
-    printf("Stats:\n");
+    fprintf(stderr, "Stats:\n");
+
+    gc::dumpHeapStatistics(0);
+
+    fprintf(stderr, "Counters:\n");
 
     std::vector<std::pair<std::string, int>> pairs;
     for (const auto& p : *names) {
@@ -66,8 +71,10 @@ void Stats::dump(bool includeZeros) {
 
     for (int i = 0; i < pairs.size(); i++) {
         if (includeZeros || (*counts)[pairs[i].second] > 0)
-            printf("%s: %ld\n", pairs[i].first.c_str(), (*counts)[pairs[i].second]);
+            fprintf(stderr, "%s: %ld\n", pairs[i].first.c_str(), (*counts)[pairs[i].second]);
     }
+
+    fprintf(stderr, "(End of stats)\n");
 }
 
 void Stats::endOfInit() {

src/gc/heap.cpp

@@ -185,16 +185,32 @@ struct HeapStatistics {
 
         void print(const char* name) const {
             if (nbytes > (1 << 20))
-                printf("%s: %ld allocations for %.1f MB\n", name, nallocs, nbytes * 1.0 / (1 << 20));
+                fprintf(stderr, "%s: %ld allocations for %.1f MB\n", name, nallocs, nbytes * 1.0 / (1 << 20));
             else if (nbytes > (1 << 10))
-                printf("%s: %ld allocations for %.1f KB\n", name, nallocs, nbytes * 1.0 / (1 << 10));
+                fprintf(stderr, "%s: %ld allocations for %.1f KB\n", name, nallocs, nbytes * 1.0 / (1 << 10));
             else
-                printf("%s: %ld allocations for %ld bytes\n", name, nallocs, nbytes);
+                fprintf(stderr, "%s: %ld allocations for %ld bytes\n", name, nallocs, nbytes);
         }
     };
+
+    bool collect_cls_stats, collect_hcls_stats;
+
+    // For use if collect_cls_stats == true:
     std::unordered_map<BoxedClass*, TypeStats> by_cls;
-    TypeStats conservative, untracked, hcls;
+
+    // For use if collect_hcls_stats == true:
+    std::unordered_map<HiddenClass*, int> hcls_uses;
+#define HCLS_ATTRS_STAT_MAX 20
+    int num_hcls_by_attrs[HCLS_ATTRS_STAT_MAX + 1];
+    int num_hcls_by_attrs_exceed;
+
+    TypeStats python, conservative, untracked, hcls, precise;
     TypeStats total;
+
+    HeapStatistics(bool collect_cls_stats, bool collect_hcls_stats)
+        : collect_cls_stats(collect_cls_stats), collect_hcls_stats(collect_hcls_stats) {
+        memset(num_hcls_by_attrs, 0, sizeof(num_hcls_by_attrs));
+    }
 };
 
 void addStatistic(HeapStatistics* stats, GCAllocation* al, int nbytes) {
@@ -202,11 +218,24 @@ void addStatistic(HeapStatistics* stats, GCAllocation* al, int nbytes) {
     stats->total.nbytes += nbytes;
 
     if (al->kind_id == GCKind::PYTHON) {
+        stats->python.nallocs++;
+        stats->python.nbytes += nbytes;
+
+        if (stats->collect_cls_stats) {
             Box* b = (Box*)al->user_data;
             auto& t = stats->by_cls[b->cls];
 
             t.nallocs++;
             t.nbytes += nbytes;
+        }
+
+        if (stats->collect_hcls_stats) {
+            Box* b = (Box*)al->user_data;
+            if (b->cls->instancesHaveHCAttrs()) {
+                HCAttrs* attrs = b->getHCAttrsPtr();
+                stats->hcls_uses[attrs->hcls]++;
+            }
+        }
     } else if (al->kind_id == GCKind::CONSERVATIVE) {
         stats->conservative.nallocs++;
         stats->conservative.nbytes += nbytes;
@@ -216,6 +245,18 @@ void addStatistic(HeapStatistics* stats, GCAllocation* al, int nbytes) {
     } else if (al->kind_id == GCKind::HIDDEN_CLASS) {
         stats->hcls.nallocs++;
         stats->hcls.nbytes += nbytes;
+
+        if (stats->collect_hcls_stats) {
+            HiddenClass* hcls = (HiddenClass*)al->user_data;
+            int numattrs = hcls->attributeArraySize();
+            if (numattrs <= HCLS_ATTRS_STAT_MAX)
+                stats->num_hcls_by_attrs[numattrs]++;
+            else
+                stats->num_hcls_by_attrs_exceed++;
+        }
+    } else if (al->kind_id == GCKind::PRECISE) {
+        stats->precise.nallocs++;
+        stats->precise.nbytes += nbytes;
     } else {
         RELEASE_ASSERT(0, "%d", (int)al->kind_id);
     }
@@ -223,27 +264,49 @@ void addStatistic(HeapStatistics* stats, GCAllocation* al, int nbytes) {
 
 
 
-void Heap::dumpHeapStatistics() {
+void Heap::dumpHeapStatistics(int level) {
+    bool collect_cls_stats = (level >= 1);
+    bool collect_hcls_stats = (level >= 1);
+
     threading::GLPromoteRegion _lock;
 
-    HeapStatistics stats;
+    fprintf(stderr, "\nCollecting heap stats for pid %d...\n", getpid());
+
+    HeapStatistics stats(collect_cls_stats, collect_hcls_stats);
 
     small_arena.getStatistics(&stats);
     large_arena.getStatistics(&stats);
     huge_arena.getStatistics(&stats);
 
+    stats.python.print("python");
     stats.conservative.print("conservative");
     stats.untracked.print("untracked");
     stats.hcls.print("hcls");
+    stats.precise.print("precise");
+
+    if (collect_cls_stats) {
         for (const auto& p : stats.by_cls) {
             p.second.print(getFullNameOfClass(p.first).c_str());
         }
+    }
+
     stats.total.print("Total");
-    printf("\n");
+
+    if (collect_hcls_stats) {
+        fprintf(stderr, "%ld hidden classes currently alive\n", stats.hcls.nallocs);
+        fprintf(stderr, "%ld have at least one Box that uses them\n", stats.hcls_uses.size());
+
+        for (int i = 0; i <= HCLS_ATTRS_STAT_MAX; i++) {
+            fprintf(stderr, "With % 3d attributes: %d\n", i, stats.num_hcls_by_attrs[i]);
+        }
+        fprintf(stderr, "With >% 2d attributes: %d\n", HCLS_ATTRS_STAT_MAX, stats.num_hcls_by_attrs_exceed);
+    }
+
+    fprintf(stderr, "\n");
 }
 
-void dumpHeapStatistics() {
-    global_heap.dumpHeapStatistics();
+void dumpHeapStatistics(int level) {
+    global_heap.dumpHeapStatistics(level);
 }
 
 //////

src/gc/heap.h

@@ -22,6 +22,7 @@
 
 #include "core/common.h"
 #include "core/threading.h"
+#include "core/types.h"
 
 namespace pyston {
 
@@ -535,13 +536,13 @@ public:
         huge_arena.freeUnmarked(weakly_referenced);
     }
 
-    void dumpHeapStatistics();
+    void dumpHeapStatistics(int level);
 
     friend void markPhase();
 };
 
 extern Heap global_heap;
-void dumpHeapStatistics();
+void dumpHeapStatistics(int level);
 
 } // namespace gc
 } // namespace pyston

src/runtime/stacktrace.cpp

@@ -160,12 +160,14 @@ extern "C" void abort() {
     // In case displaying the traceback recursively calls abort:
     static bool recursive = false;
 
-    // If traceback_cls is NULL, then we somehow died early on, and won't be able to display a traceback.
-    if (!recursive && traceback_cls) {
+    if (!recursive) {
         recursive = true;
-
+        Stats::dump();
         fprintf(stderr, "Someone called abort!\n");
 
+        // If traceback_cls is NULL, then we somehow died early on, and won't be able to display a traceback.
+        if (traceback_cls) {
+
             // If we call abort(), things may be seriously wrong.  Set an alarm() to
             // try to handle cases that we would just hang.
             // (Ex if we abort() from a static constructor, and _printStackTrace uses
@@ -183,6 +185,7 @@ extern "C" void abort() {
             // abort and let you investigate, but the alarm will still come back to kill the program.
             alarm(0);
         }
+    }
 
     if (PAUSE_AT_ABORT) {
         printf("PID %d about to call libc abort; pausing for a debugger...\n", getpid());

tools/tester.py

@@ -220,8 +220,6 @@ def get_test_options(fn, check_stats, run_memcheck):
     return opts
 
 def determine_test_result(fn, opts, code, out, stderr, elapsed):
-    last_stderr_line = stderr.strip().split('\n')[-1]
-
     if opts.allow_warnings:
         out_lines = []
         for l in out.split('\n'):
@@ -233,14 +231,27 @@ def determine_test_result(fn, opts, code, out, stderr, elapsed):
         out = "\n".join(out_lines)
 
     stats = None
-    if code >= 0 and opts.collect_stats:
+    if opts.collect_stats:
         stats = {}
-        assert out.count("Stats:") == 1
-        out, stats_str = out.split("Stats:")
-        for l in stats_str.strip().split('\n'):
+        have_stats = (stderr.count("Stats:") == 1 and stderr.count("(End of stats)") == 1)
+
+        if code >= 0:
+            assert have_stats
+
+        if have_stats:
+            assert stderr.count("Stats:") == 1
+            stderr, stats_str = stderr.split("Stats:")
+            stats_str, stderr_tail = stats_str.split("(End of stats)\n")
+            stderr += stderr_tail
+
+            other_stats_str, counter_str = stats_str.split("Counters:")
+            for l in counter_str.strip().split('\n'):
+                assert l.count(':') == 1, l
                 k, v = l.split(':')
                 stats[k.strip()] = int(v)
 
+    last_stderr_line = stderr.strip().split('\n')[-1]
+
     if EXIT_CODE_ONLY:
         # fools the rest of this function into thinking the output is OK & just checking the exit code.
         # there oughtta be a cleaner way to do this.