Garbage Profiler

base/gcutils.jl

@@ -127,6 +127,14 @@ function take_heap_snapshot(io)
     ccall(:jl_gc_take_heap_snapshot, Cvoid, (Ptr{Cvoid},), (io::IOStream).handle::Ptr{Cvoid})
 end
 
+function start_garbage_profile(io)
+    ccall(:jl_start_garbage_profile, Cvoid, (Ptr{Cvoid},), io.handle)
+end
+
+function stop_garbage_profile()
+    ccall(:jl_stop_garbage_profile, Cvoid, ())
+end
+
 function enable_finalizers()
     Base.@inline
     ccall(:jl_gc_enable_finalizers_internal, Cvoid, ())

src/Makefile

@@ -43,8 +43,8 @@ RUNTIME_SRCS := \
 	jltypes gf typemap smallintset ast builtins module interpreter symbol \
 	dlload sys init task array dump staticdata toplevel jl_uv datatype \
 	simplevector runtime_intrinsics precompile \
-	threading partr stackwalk gc gc-debug gc-heap-snapshot gc-pages gc-stacks method \
-	jlapi signal-handling safepoint timing subtype \
+	threading partr stackwalk gc gc-debug gc-heap-snapshot gc-garbage-profiler \
+	gc-pages gc-stacks method jlapi signal-handling safepoint timing subtype \
 	crc32c APInt-C processor ircode opaque_closure
 SRCS := jloptions runtime_ccall rtutils
 
@@ -255,7 +255,7 @@ $(BUILDDIR)/disasm.o $(BUILDDIR)/disasm.dbg.obj: $(SRCDIR)/debuginfo.h $(SRCDIR)
 $(BUILDDIR)/dump.o $(BUILDDIR)/dump.dbg.obj: $(addprefix $(SRCDIR)/,common_symbols1.inc common_symbols2.inc builtin_proto.h serialize.h)
 $(BUILDDIR)/gc-debug.o $(BUILDDIR)/gc-debug.dbg.obj: $(SRCDIR)/gc.h
 $(BUILDDIR)/gc-pages.o $(BUILDDIR)/gc-pages.dbg.obj: $(SRCDIR)/gc.h
-$(BUILDDIR)/gc.o $(BUILDDIR)/gc.dbg.obj: $(SRCDIR)/gc.h $(SRCDIR)/gc-heap-snapshot.h
+$(BUILDDIR)/gc.o $(BUILDDIR)/gc.dbg.obj: $(SRCDIR)/gc.h $(SRCDIR)/gc-heap-snapshot.h $(SRCDIR)/gc-garbage-profiler.h
 $(BUILDDIR)/init.o $(BUILDDIR)/init.dbg.obj: $(SRCDIR)/builtin_proto.h
 $(BUILDDIR)/interpreter.o $(BUILDDIR)/interpreter.dbg.obj: $(SRCDIR)/builtin_proto.h
 $(BUILDDIR)/jitlayers.o $(BUILDDIR)/jitlayers.dbg.obj: $(SRCDIR)/jitlayers.h $(SRCDIR)/codegen_shared.h

src/datatype.c

@@ -786,6 +786,7 @@ JL_DLLEXPORT jl_value_t *jl_new_bits(jl_value_t *dt, const void *data)
     assert(jl_is_datatype(dt));
     jl_datatype_t *bt = (jl_datatype_t*)dt;
     size_t nb = jl_datatype_size(bt);
+
     // some types have special pools to minimize allocations
     if (nb == 0)               return jl_new_struct_uninit(bt); // returns bt->instance
     if (bt == jl_bool_type)    return (1 & *(int8_t*)data) ? jl_true : jl_false;
@@ -802,6 +803,7 @@ JL_DLLEXPORT jl_value_t *jl_new_bits(jl_value_t *dt, const void *data)
     jl_task_t *ct = jl_current_task;
     jl_value_t *v = jl_gc_alloc(ct->ptls, nb, bt);
     memcpy(jl_assume_aligned(v, sizeof(void*)), data, nb);
+
     return v;
 }
 
@@ -1285,6 +1287,7 @@ JL_DLLEXPORT jl_value_t *jl_new_structv(jl_datatype_t *type, jl_value_t **args,
         }
         JL_GC_POP();
     }
+
     return jv;
 }
 
@@ -1332,6 +1335,7 @@ JL_DLLEXPORT jl_value_t *jl_new_structt(jl_datatype_t *type, jl_value_t *tup)
         set_nth_field(type, jv, i, fi, 0);
     }
     JL_GC_POP();
+
     return jv;
 }
 

src/gc-garbage-profiler.cpp

@@ -0,0 +1,152 @@
+// This file is a part of Julia. License is MIT: https://julialang.org/license
+
+#include "gc-garbage-profiler.h"
+
+#include "julia_internal.h"
+#include "gc.h"
+
+#include <string>
+#include <unordered_map>
+
+using std::string;
+using std::unordered_map;
+
+// == utility functions ==
+
+void print_str_escape_csv(ios_t *stream, const std::string &s) {
+    ios_printf(stream, "\"");
+    for (auto c = s.cbegin(); c != s.cend(); c++) {
+        switch (*c) {
+        case '"': ios_printf(stream, "\"\""); break;
+        default:
+            ios_printf(stream, "%c", *c);
+        }
+    }
+    ios_printf(stream, "\"");
+}
+
+string _type_as_string(jl_datatype_t *type) {
+    if ((uintptr_t)type < 4096U) {
+        return "<corrupt>";
+    } else if (type == (jl_datatype_t*)jl_buff_tag) {
+        return "<buffer>";
+    } else if (type == (jl_datatype_t*)jl_malloc_tag) {
+        return "<malloc>";
+    } else if (type == jl_string_type) {
+        return "<string>";
+    } else if (type == jl_symbol_type) {
+        return "<symbol>";
+    } else if (jl_is_datatype(type)) {
+        ios_t str_;
+        ios_mem(&str_, 10024);
+        JL_STREAM* str = (JL_STREAM*)&str_;
+
+        jl_static_show(str, (jl_value_t*)type);
+
+        string type_str = string((const char*)str_.buf, str_.size);
+        ios_close(&str_);
+
+        return type_str;
+    } else {
+        return "<missing>";
+    }
+}
+
+// == global variables manipulated by callbacks ==
+// TODO: wrap these up into a struct
+
+ios_t *garbage_profile_out = nullptr;
+int gc_epoch = 0;
+// for each type, the index in mem_event where the type
+// event appears.
+unordered_map<size_t, string> g_type_name_by_address;
+unordered_map<size_t, size_t> g_type_address_by_value_address;
+unordered_map<size_t, size_t> g_frees_by_type_address;
+
+// == exported interface ==
+
+JL_DLLEXPORT void jl_start_garbage_profile(ios_t *stream) {
+    garbage_profile_out = stream;
+    ios_printf(garbage_profile_out, "gc_epoch,type,num_freed\n");
+}
+
+JL_DLLEXPORT void jl_stop_garbage_profile() {
+    // TODO: flush file?
+    garbage_profile_out = nullptr;
+    g_type_name_by_address.clear();
+    g_type_address_by_value_address.clear();
+    g_frees_by_type_address.clear();
+}    
+
+// == callbacks called into by the outside ==
+
+void _report_gc_started() {
+    g_frees_by_type_address.clear();
+}
+
+// TODO: figure out how to pass all of these in as a struct
+void _report_gc_finished(uint64_t pause, uint64_t freed, uint64_t allocd) {
+    // TODO: figure out how to put in commas
+    jl_printf(
+        JL_STDERR,
+        "GC: pause %fms. collected %fMB. %lld allocs total\n",
+        pause/1e6, freed/1e6, allocd
+    );
+
+    // sort frees
+    for (auto const &pair : g_frees_by_type_address) {
+        auto type_str = g_type_name_by_address.find(pair.first);
+        if (type_str != g_type_name_by_address.end()) {
+            ios_printf(garbage_profile_out, "%d,", gc_epoch);
+            print_str_escape_csv(garbage_profile_out, type_str->second);
+            ios_printf(garbage_profile_out, ",%d\n", pair.second);
+        } else {
+            jl_printf(JL_STDERR, "couldn't find type %p\n", pair.first);
+            // TODO: warn about missing type
+        }
+    }
+    gc_epoch++;
+}
+
+void register_type_string(jl_datatype_t *type) {
+    auto id = g_type_name_by_address.find((size_t)type);
+    if (id != g_type_name_by_address.end()) {
+        return;
+    }
+
+    string type_str = _type_as_string(type);
+    g_type_name_by_address[(size_t)type] = type_str;
+}
+
+void _record_allocated_value(jl_value_t *val) {
+    if (garbage_profile_out == nullptr) {
+        return;
+    }
+
+    auto type = (jl_datatype_t*)jl_typeof(val);
+    register_type_string(type);
+
+    g_type_address_by_value_address[(size_t)val] = (size_t)type;
+}
+
+void _record_freed_value(jl_taggedvalue_t *tagged_val) {
+    if (garbage_profile_out == nullptr) {
+        return;
+    }
+
+    jl_value_t *val = jl_valueof(tagged_val);
+
+    auto value_address = (size_t)val;
+    auto type_address = g_type_address_by_value_address.find(value_address);
+    if (type_address == g_type_address_by_value_address.end()) {
+        return; // TODO: warn
+    }
+    auto frees = g_frees_by_type_address.find(type_address->second);
+
+    if (frees == g_frees_by_type_address.end()) {
+        g_frees_by_type_address[type_address->second] = 1;
+    } else {
+        g_frees_by_type_address[type_address->second] = frees->second + 1;
+    }
+}
+

src/gc-garbage-profiler.h

@@ -0,0 +1,44 @@
+// This file is a part of Julia. License is MIT: https://julialang.org/license
+
+#ifndef JL_GC_GARBAGE_PROFILER_H
+#define JL_GC_GARBAGE_PROFILER_H
+
+#include "julia.h"
+#include "ios.h"
+
+#ifdef __cplusplus
+extern "C" {
+#endif
+
+JL_DLLEXPORT void jl_start_garbage_profile(ios_t *stream);
+JL_DLLEXPORT void jl_stop_garbage_profile(void);
+
+void _report_gc_started(void);
+void _report_gc_finished(uint64_t pause, uint64_t freed, uint64_t allocd);
+void _record_allocated_value(jl_value_t *val);
+void _record_freed_value(jl_taggedvalue_t *tagged_val);
+
+// ---------------------------------------------------------------------
+// functions to call from GC when garbage profiling is enabled
+// ---------------------------------------------------------------------
+
+extern ios_t *garbage_profile_out; // TODO: replace w/ bool?
+
+static inline void record_allocated_value(jl_value_t *val) {
+    if (__unlikely(garbage_profile_out != 0)) {
+        _record_allocated_value(val);
+    }
+}
+
+static inline void record_freed_value(jl_taggedvalue_t *tagged_val) {
+    if (__unlikely(garbage_profile_out != 0)) {
+        _record_freed_value(tagged_val);
+    }
+}
+
+#ifdef __cplusplus
+}
+#endif
+
+
+#endif  // JL_GC_GARBAGE_PROFILER_H

src/gc-heap-snapshot.cpp

@@ -45,7 +45,6 @@ void print_str_escape_json(ios_t *stream, const std::string &s) {
     ios_printf(stream, "\"");
 }
 
-
 // Edges
 // "edge_fields":
 //   [ "type", "name_or_index", "to_node" ]
@@ -198,6 +197,8 @@ size_t record_node_to_gc_snapshot(jl_value_t *a) JL_NOTSAFEPOINT {
     string name = "<missing>";
     string node_type = "object";
 
+    // TODO: dedup with _type_as_string
+    // need variant that returns size as well
     if (a == (jl_value_t*)jl_malloc_tag) {
         name = "<malloc>";
     } else {
@@ -412,7 +413,6 @@ void _gc_heap_snapshot_record_array_edge(jl_value_t *from, jl_value_t *to, size_
 }
 
 void _gc_heap_snapshot_record_module_edge(jl_module_t *from, jl_value_t *to, char *name) JL_NOTSAFEPOINT {
-    //jl_printf(JL_STDERR, "module: %p  binding:%p  name:%s\n", from, to, name);
     _record_gc_edge("object", "property", (jl_value_t *)from, to,
                     g_snapshot->names.find_or_create_string_id(name));
 }

src/gc-heap-snapshot.h

@@ -10,7 +10,6 @@
 extern "C" {
 #endif
 
-
 // ---------------------------------------------------------------------
 // Functions to call from GC when heap snapshot is enabled
 // ---------------------------------------------------------------------

src/gc.c

@@ -1323,6 +1323,7 @@ static jl_taggedvalue_t **sweep_page(jl_gc_pool_t *p, jl_gc_pagemeta_t *pg, jl_t
         while ((char*)v <= lim) {
             int bits = v->bits.gc;
             if (!gc_marked(bits)) {
+                record_freed_value(v);
                 *pfl = v;
                 pfl = &v->next;
                 pfl_begin = pfl_begin ? pfl_begin : pfl;
@@ -3055,6 +3056,8 @@ size_t jl_maxrss(void);
 // Only one thread should be running in this function
 static int _jl_gc_collect(jl_ptls_t ptls, jl_gc_collection_t collection)
 {
+    _report_gc_started();
+
     combine_thread_gc_counts(&gc_num);
 
     jl_gc_mark_cache_t *gc_cache = &ptls->gc_cache;
@@ -3243,6 +3246,9 @@ static int _jl_gc_collect(jl_ptls_t ptls, jl_gc_collection_t collection)
 
     uint64_t gc_end_t = jl_hrtime();
     uint64_t pause = gc_end_t - t0;
+
+    _report_gc_finished(pause, gc_num.freed, gc_num.allocd);
+
     gc_final_pause_end(t0, gc_end_t);
     gc_time_sweep_pause(gc_end_t, actual_allocd, live_bytes,
                         estimate_freed, sweep_full);

src/gc.h

@@ -27,6 +27,7 @@
 #endif
 #include "julia_assert.h"
 #include "gc-heap-snapshot.h"
+#include "gc-garbage-profiler.h"
 
 #ifdef __cplusplus
 extern "C" {

src/julia_internal.h

@@ -5,6 +5,7 @@
 
 #include "options.h"
 #include "julia_locks.h"
+#include "gc-garbage-profiler.h"
 #include <uv.h>
 #if !defined(_WIN32)
 #include <unistd.h>
@@ -362,6 +363,9 @@ STATIC_INLINE jl_value_t *jl_gc_alloc_(jl_ptls_t ptls, size_t sz, void *ty)
         v = jl_gc_big_alloc(ptls, allocsz);
     }
     jl_set_typeof(v, ty);
+
+    record_allocated_value(v);
+
     return v;
 }