diff --git a/base/gcutils.jl b/base/gcutils.jl index 7010f8fa7d2f1..083955a9792f8 100644 --- a/base/gcutils.jl +++ b/base/gcutils.jl @@ -106,6 +106,24 @@ Control whether garbage collection is enabled using a boolean argument (`true` f """ enable(on::Bool) = ccall(:jl_gc_enable, Int32, (Int32,), on) != 0 +# TODO: maybe merge profiling & logging funcions? + +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 start_logging(io) + ccall(:jl_start_logging, Cvoid, (Ptr{Cvoid},), io.handle) +end + +function stop_logging() + ccall(:jl_stop_logging, Cvoid, ()) +end + """ GC.enable_finalizers(on::Bool) diff --git a/src/Makefile b/src/Makefile index 11bc210191bda..0a931c9485db4 100644 --- a/src/Makefile +++ b/src/Makefile @@ -46,7 +46,7 @@ RUNTIME_SRCS := \ dlload sys init task array dump staticdata toplevel jl_uv datatype \ simplevector runtime_intrinsics precompile \ threading partr stackwalk gc gc-debug gc-pages gc-stacks method \ - jlapi signal-handling safepoint timing subtype \ + gc-garbage-profiler jlapi signal-handling safepoint timing subtype \ crc32c APInt-C processor ircode opaque_closure codegen-stubs SRCS := jloptions runtime_ccall rtutils ifeq ($(OS),WINNT) @@ -284,7 +284,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 +$(BUILDDIR)/gc.o $(BUILDDIR)/gc.dbg.obj: $(SRCDIR)/gc.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 diff --git a/src/gc-garbage-profiler.cpp b/src/gc-garbage-profiler.cpp new file mode 100644 index 0000000000000..1030699f23f19 --- /dev/null +++ b/src/gc-garbage-profiler.cpp @@ -0,0 +1,190 @@ +// 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 "timefuncs.h" + +#include +#include +#include +#include + +using std::string; +using std::unordered_map; +using std::vector; + +// == 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 ""; + } else if (type == (jl_datatype_t*)jl_buff_tag) { + return ""; + } else if (type == (jl_datatype_t*)jl_malloc_tag) { + return ""; + } else if (type == jl_string_type) { + return ""; + } else if (type == jl_symbol_type) { + return ""; + } 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 ""; + } +} + +// == global variables manipulated by callbacks == +// TODO: wrap these up into a struct + +ios_t *g_gc_log_stream = nullptr; + +ios_t *g_garbage_profile_stream = nullptr; +int gc_epoch = 0; +// for each type, the index in mem_event where the type +// event appears. +unordered_map g_type_name_by_address; +unordered_map g_type_address_by_value_address; +unordered_map g_frees_by_type_address; + +// == exported interface == + +JL_DLLEXPORT void jl_start_logging(ios_t *stream) { + g_gc_log_stream = stream; + ios_printf(g_gc_log_stream, "gc_epoch,collection_type,start_timestamp_ms,duration_ms,bytes_freed\n"); +} + +JL_DLLEXPORT void jl_stop_logging() { + g_gc_log_stream = nullptr; +} + +JL_DLLEXPORT void jl_start_garbage_profile(ios_t *stream) { + g_garbage_profile_stream = stream; + ios_printf(g_garbage_profile_stream, "gc_epoch,type,num_freed\n"); +} + +JL_DLLEXPORT void jl_stop_garbage_profile() { + // TODO: flush file? + g_garbage_profile_stream = 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(); +} + +bool pair_cmp(std::pair a, std::pair b) { + return a.second > b.second; +} + +uint64_t get_timestamp_ms() { + jl_timeval jtv; + jl_gettimeofday(&jtv); + return jtv.sec*1e6 + jtv.usec/1e3; +} + +// TODO: figure out how to pass all of these in as a struct +void _report_gc_finished( + jl_gc_collection_t collection, uint64_t pause, uint64_t freed, uint64_t allocd +) { + if (g_gc_log_stream != nullptr) { + auto end_timestamp_ms = get_timestamp_ms(); + auto duration_ms = (uint64_t)(pause/1e6); + + auto mode = collection == JL_GC_INCREMENTAL + ? "INCR" + : (collection == JL_GC_FULL + ? "FULL" + : "AUTO"); + + ios_printf( + g_gc_log_stream, + "%d,%s,%lld,%d,%d\n", + gc_epoch, mode, end_timestamp_ms - duration_ms, duration_ms, freed + ); + ios_flush(g_gc_log_stream); + } + + // sort frees + vector> pairs; + for (auto const &pair : g_frees_by_type_address) { + pairs.push_back(pair); + } + std::sort(pairs.begin(), pairs.end(), pair_cmp); + + // print frees + if (g_garbage_profile_stream != nullptr) { + for (auto const &pair : pairs) { + auto type_str = g_type_name_by_address.find(pair.first); + if (type_str != g_type_name_by_address.end()) { + ios_printf(g_garbage_profile_stream, "%d,", gc_epoch); + print_str_escape_csv(g_garbage_profile_stream, type_str->second); + ios_printf(g_garbage_profile_stream, ",%d\n", pair.second); + } else { + jl_printf(JL_STDERR, "couldn't find type %lu\n", pair.first); + } + } + ios_flush(g_garbage_profile_stream); + } + 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) { + 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) { + 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; + } +} diff --git a/src/gc-garbage-profiler.h b/src/gc-garbage-profiler.h new file mode 100644 index 0000000000000..609a8c823c812 --- /dev/null +++ b/src/gc-garbage-profiler.h @@ -0,0 +1,48 @@ +// 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_logging(ios_t *stream); +JL_DLLEXPORT void jl_stop_logging(void); + +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(jl_gc_collection_t collection, 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 *g_garbage_profile_stream; // TODO: replace w/ bool? +extern ios_t *g_gc_log_stream; + +static inline void record_allocated_value(jl_value_t *val) { + if (__unlikely(g_garbage_profile_stream != 0)) { + _record_allocated_value(val); + } +} + +static inline void record_freed_value(jl_taggedvalue_t *tagged_val) { + if (__unlikely(g_garbage_profile_stream != 0)) { + _record_freed_value(tagged_val); + } +} + +#ifdef __cplusplus +} +#endif + + +#endif // JL_GC_GARBAGE_PROFILER_H diff --git a/src/gc.c b/src/gc.c index 05fcb7b3c60e9..8ccf572ef03df 100644 --- a/src/gc.c +++ b/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; @@ -3009,6 +3010,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; @@ -3195,6 +3198,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(collection, 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); diff --git a/src/gc.h b/src/gc.h index 74eaf483f8451..b32506c0c8aaa 100644 --- a/src/gc.h +++ b/src/gc.h @@ -26,6 +26,7 @@ #endif #endif #include "julia_assert.h" +#include "gc-garbage-profiler.h" #ifdef __cplusplus extern "C" { diff --git a/src/julia_internal.h b/src/julia_internal.h index 96fb6cc276bdd..f860ca3cd1e47 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -5,6 +5,7 @@ #include "options.h" #include "julia_locks.h" +#include "gc-garbage-profiler.h" #include #if !defined(_WIN32) #include @@ -364,6 +365,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; }