GC: enable logging to stderr when GC runs (JuliaLang#43511)

Co-authored-by: Nathan Daly <[email protected]>

Author: 2 people

NEWS.md

@@ -198,6 +198,8 @@ External dependencies
 
 Tooling Improvements
 ---------------------
+* `GC.enable_logging(true)` can be used to log each garbage collection, with the
+  time it took and the amount of memory that was collected ([#43511]).
 
 
 <!--- generated by NEWS-update.jl: -->

base/gcutils.jl

@@ -197,4 +197,13 @@ collection to run.
 """
 safepoint() = ccall(:jl_gc_safepoint, Cvoid, ())
 
+"""
+    GC.enable_logging(on::Bool)
+
+When turned on, print statistics about each GC to stderr.
+"""
+function enable_logging(on::Bool=true)
+    ccall(:jl_enable_gc_logging, Cvoid, (Cint,), on)
+end
+
 end # module GC

doc/src/base/base.md

@@ -433,6 +433,7 @@ Base.GC.gc
 Base.GC.enable
 Base.GC.@preserve
 Base.GC.safepoint
+Base.GC.enable_logging
 Meta.lower
 Meta.@lower
 Meta.parse(::AbstractString, ::Int)

doc/src/manual/profile.md

@@ -297,12 +297,18 @@ on the author's laptop).
 
 ## Memory allocation analysis
 
-One of the most common techniques to improve performance is to reduce memory allocation. The
-total amount of allocation can be measured with [`@time`](@ref) and [`@allocated`](@ref), and
+One of the most common techniques to improve performance is to reduce memory allocation. Julia
+provides several tools measure this:
+
+### `@time`
+
+The total amount of allocation can be measured with [`@time`](@ref) and [`@allocated`](@ref), and
 specific lines triggering allocation can often be inferred from profiling via the cost of garbage
 collection that these lines incur. However, sometimes it is more efficient to directly measure
 the amount of memory allocated by each line of code.
 
+### Line-by-Line Allocation Tracking
+
 To measure allocation line-by-line, start Julia with the `--track-allocation=<setting>` command-line
 option, for which you can choose `none` (the default, do not measure allocation), `user` (measure
 memory allocation everywhere except Julia's core code), or `all` (measure memory allocation at
@@ -321,6 +327,15 @@ you want to analyze, then call [`Profile.clear_malloc_data()`](@ref) to reset al
  Finally, execute the desired commands and quit Julia to trigger the generation of the `.mem`
 files.
 
+### GC Logging
+
+While [`@time`](@ref) logs high-level stats about memory usage and garbage collection over the course
+of evaluating an expression, it can be useful to log each garbage collection event, to get an
+intuitive sense of how often the garbage collector is running, how long it's running each time,
+and how much garbage it collects each time. This can be enabled with
+[`GC.enable_logging(true)`](@ref), which causes Julia to log to stderr every time
+a garbage collection happens.
+
 ## External Profiling
 
 Currently Julia supports `Intel VTune`, `OProfile` and `perf` as external profiling tools.

src/gc-debug.c

@@ -1380,6 +1380,23 @@ NOINLINE void gc_mark_loop_unwind(jl_ptls_t ptls, jl_gc_mark_sp_t sp, int pc_off
     jl_set_safe_restore(old_buf);
 }
 
+static int gc_logging_enabled = 0;
+
+JL_DLLEXPORT void jl_enable_gc_logging(int enable) {
+    gc_logging_enabled = enable;
+}
+
+void _report_gc_finished(uint64_t pause, uint64_t freed, int full, int recollect) JL_NOTSAFEPOINT {
+    if (!gc_logging_enabled) {
+        return;
+    }
+    jl_safe_printf("GC: pause %.2fms. collected %fMB. %s %s\n",
+        pause/1e6, freed/1e6,
+        full ? "full" : "incr",
+        recollect ? "recollect" : ""
+    );
+}
+
 #ifdef __cplusplus
 }
 #endif

src/gc.c

@@ -3205,6 +3205,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, sweep_full, recollect);
+
     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

@@ -696,6 +696,9 @@ void gc_count_pool(void);
 
 size_t jl_array_nbytes(jl_array_t *a) JL_NOTSAFEPOINT;
 
+JL_DLLEXPORT void jl_enable_gc_logging(int enable);
+void _report_gc_finished(uint64_t pause, uint64_t freed, int full, int recollect) JL_NOTSAFEPOINT;
+
 #ifdef __cplusplus
 }
 #endif

test/misc.jl

@@ -1023,6 +1023,10 @@ end
     GC.gc(true); GC.gc(false)
 
     GC.safepoint()
+
+    GC.enable_logging(true)
+    GC.gc()
+    GC.enable_logging(false)
 end
 
 @testset "fieldtypes Module" begin