module GC::Profiler

The GC profiler provides access to information on GC runs including time, length and object space size.

Example:

GC::Profiler.enable

require 'rdoc/rdoc'

GC::Profiler.report

pp GC::Profiler.raw_data

GC::Profiler.disable

GC::Profiler.raw_data returns one Hash per GC run, including CPU time fields such as :GC_TIME and wall-clock fields such as :GC_WALL_TIME, :GC_PAUSE_TIME, :GC_STOP_TIME, and :GC_STW_TIME. :GC_WALL_TIME is the wall-clock counterpart to :GC_TIME, while :GC_PAUSE_TIME measures how long user execution was blocked by the GC entry.

Public Class Methods

GC::Profiler.clear → nil

() → nil

Source

static VALUE
gc_profile_clear(VALUE _)
{
    rb_objspace_t *objspace = rb_gc_get_objspace();
    void *p = objspace->profile.records;
    objspace->profile.records = NULL;
    objspace->profile.size = 0;
    objspace->profile.next_index = 0;
    objspace->profile.current_record = 0;
    free(p);
    return Qnil;
}

Clears the GC profiler data.

GC::Profiler.disable → nil

() → nil

Source

static VALUE
gc_profile_disable(VALUE _)
{
    rb_objspace_t *objspace = rb_gc_get_objspace();

    objspace->profile.run = FALSE;
    objspace->profile.current_record = 0;
    return Qnil;
}

Stops the GC profiler.

GC::Profiler.enable → nil

() → nil

Source

static VALUE
gc_profile_enable(VALUE _)
{
    rb_objspace_t *objspace = rb_gc_get_objspace();
    objspace->profile.run = TRUE;
    objspace->profile.current_record = 0;
    return Qnil;
}

Starts the GC profiler.

GC::Profiler.enabled? → true or false

() → bool

Source

static VALUE
gc_profile_enable_get(VALUE self)
{
    rb_objspace_t *objspace = rb_gc_get_objspace();
    return objspace->profile.run ? Qtrue : Qfalse;
}

The current status of GC profile mode.

GC::Profiler.raw_data → [Hash, ...]

() → Array[Hash[Symbol, untyped]]?

Source

static VALUE
gc_profile_record_get(VALUE _)
{
    VALUE prof;
    VALUE gc_profile = rb_ary_new();
    size_t i;
    rb_objspace_t *objspace = rb_gc_get_objspace();

    if (!objspace->profile.run) {
        return Qnil;
    }

    for (i =0; i < objspace->profile.next_index; i++) {
        gc_profile_record *record = &objspace->profile.records[i];

        prof = rb_hash_new();
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_FLAGS")), gc_info_decode(objspace, rb_hash_new(), record->flags));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_TIME")), DBL2NUM(record->gc_time));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_INVOKE_TIME")), DBL2NUM(record->gc_invoke_time));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_WALL_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_wall_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_INVOKE_WALL_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_invoke_wall_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_PAUSE_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_pause_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_STOP_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_stop_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_STW_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_stw_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_MARK_WALL_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_mark_wall_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_SWEEP_WALL_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_sweep_wall_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_COMPACT_WALL_TIME")),
                DBL2NUM(hrtime_to_sec(record->gc_compact_wall_time)));
        rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_USE_SIZE")), SIZET2NUM(record->heap_use_size));
        rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_TOTAL_SIZE")), SIZET2NUM(record->heap_total_size));
        rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_TOTAL_OBJECTS")), SIZET2NUM(record->heap_total_objects));
        rb_hash_aset(prof, ID2SYM(rb_intern("MOVED_OBJECTS")), SIZET2NUM(record->moved_objects));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_IS_MARKED")), Qtrue);
#if GC_PROFILE_MORE_DETAIL
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_MARK_TIME")), DBL2NUM(record->gc_mark_time));
        rb_hash_aset(prof, ID2SYM(rb_intern("GC_SWEEP_TIME")), DBL2NUM(record->gc_sweep_time));
        rb_hash_aset(prof, ID2SYM(rb_intern("ALLOCATE_INCREASE")), SIZET2NUM(record->allocate_increase));
        rb_hash_aset(prof, ID2SYM(rb_intern("ALLOCATE_LIMIT")), SIZET2NUM(record->allocate_limit));
        rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_USE_PAGES")), SIZET2NUM(record->heap_use_pages));
        rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_LIVE_OBJECTS")), SIZET2NUM(record->heap_live_objects));
        rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_FREE_OBJECTS")), SIZET2NUM(record->heap_free_objects));

        rb_hash_aset(prof, ID2SYM(rb_intern("REMOVING_OBJECTS")), SIZET2NUM(record->removing_objects));
        rb_hash_aset(prof, ID2SYM(rb_intern("EMPTY_OBJECTS")), SIZET2NUM(record->empty_objects));

        rb_hash_aset(prof, ID2SYM(rb_intern("HAVE_FINALIZE")), (record->flags & GPR_FLAG_HAVE_FINALIZE) ? Qtrue : Qfalse);
#endif

#if RGENGC_PROFILE > 0
        rb_hash_aset(prof, ID2SYM(rb_intern("OLD_OBJECTS")), SIZET2NUM(record->old_objects));
        rb_hash_aset(prof, ID2SYM(rb_intern("REMEMBERED_NORMAL_OBJECTS")), SIZET2NUM(record->remembered_normal_objects));
        rb_hash_aset(prof, ID2SYM(rb_intern("REMEMBERED_SHADY_OBJECTS")), SIZET2NUM(record->remembered_shady_objects));
#endif
        rb_ary_push(gc_profile, prof);
    }

    return gc_profile;
}

Returns an Array of individual raw profile data Hashes ordered from earliest to latest by :GC_INVOKE_TIME.

For example:

[
  {
     :GC_TIME=>1.3000000000000858e-05,
     :GC_INVOKE_TIME=>0.010634999999999999,
     :GC_WALL_TIME=>1.4000000000000001e-05,
     :GC_INVOKE_WALL_TIME=>0.010640000000000000,
     :GC_PAUSE_TIME=>1.5000000000000000e-05,
     :GC_STOP_TIME=>1.0000000000000000e-06,
     :GC_STW_TIME=>1.4000000000000001e-05,
     :GC_MARK_WALL_TIME=>9.0000000000000002e-06,
     :GC_SWEEP_WALL_TIME=>5.0000000000000004e-06,
     :GC_COMPACT_WALL_TIME=>0.0000000000000000e+00,
     :HEAP_USE_SIZE=>289640,
     :HEAP_TOTAL_SIZE=>588960,
     :HEAP_TOTAL_OBJECTS=>14724,
     :GC_IS_MARKED=>false
  },
  # ...
]

The keys mean:

:GC_TIME: CPU time elapsed in seconds for this GC run. This is process CPU time, not elapsed wall-clock time.
:GC_INVOKE_TIME: CPU time elapsed in seconds from startup to when the GC was invoked.
:GC_WALL_TIME: Monotonic wall-clock counterpart to :GC_TIME for this GC record. This does not include time spent stopping other ractors before the VM enters GC. Use the phase wall-clock fields below for mark, sweep, and compaction attribution.
:GC_INVOKE_WALL_TIME: Monotonic wall-clock time elapsed in seconds from startup to when the GC was invoked.
:GC_PAUSE_TIME: Monotonic wall-clock time elapsed in seconds while user execution was blocked by this GC entry, including time to stop other ractors. This may include time from incremental marking or lazy sweeping continuation charged to this record.
:GC_STOP_TIME: Monotonic wall-clock time elapsed in seconds stopping other ractors.
:GC_STW_TIME: Monotonic wall-clock time elapsed in seconds after other ractors have stopped and before the VM exits GC.
:GC_MARK_WALL_TIME: Monotonic wall-clock time elapsed in seconds spent marking for this GC record, accumulated across incremental marking continuations.
:GC_SWEEP_WALL_TIME: Monotonic wall-clock time elapsed in seconds spent sweeping for this GC record, accumulated across lazy sweeping continuations. This does not include compaction time, which is reported separately as :GC_COMPACT_WALL_TIME.
:GC_COMPACT_WALL_TIME: Monotonic wall-clock time elapsed in seconds spent compacting for this GC record, or 0.0 if this GC did not compact.
:HEAP_USE_SIZE: Total bytes of heap used
:HEAP_TOTAL_SIZE: Total size of heap in bytes
:HEAP_TOTAL_OBJECTS: Total number of objects
:GC_IS_MARKED: Returns true if the GC is in mark phase

The wall-clock timing fields relate to each other as follows:

GC_PAUSE_TIME == GC_STOP_TIME + GC_STW_TIME

:GC_MARK_WALL_TIME, :GC_SWEEP_WALL_TIME, and :GC_COMPACT_WALL_TIME report separate phase timings and must not be added to :GC_WALL_TIME.

:GC_WALL_TIME is the wall-clock counterpart to :GC_TIME and is nested inside :GC_STW_TIME, so it must not be added to :GC_STW_TIME. The difference +GC_STW_TIME - GC_WALL_TIME+ is VM overhead inside the stopped interval (GC event hooks, bookkeeping, consistency checks, and continuation work).

If ruby was built with GC_PROFILE_MORE_DETAIL, you will also have access to the following hash keys:

:GC_MARK_TIME
:GC_SWEEP_TIME
:ALLOCATE_INCREASE
:ALLOCATE_LIMIT
:HEAP_USE_PAGES
:HEAP_LIVE_OBJECTS
:HEAP_FREE_OBJECTS
:HAVE_FINALIZE

GC::Profiler.report

GC::Profiler.report(io)

(?_Reporter io) → nil

Source

static VALUE
gc_profile_report(int argc, VALUE *argv, VALUE self)
{
    VALUE out;

    out = (!rb_check_arity(argc, 0, 1) ? rb_stdout : argv[0]);
    gc_profile_dump_on(out, rb_io_write);

    return Qnil;
}

Writes the GC::Profiler.result to $stdout or the given IO object.

GC::Profiler.result → String

() → String

Source

static VALUE
gc_profile_result(VALUE _)
{
    VALUE str = rb_str_buf_new(0);
    gc_profile_dump_on(str, rb_str_buf_append);
    return str;
}

Returns a profile data report such as:

GC 1 invokes.
Index    Invoke Time(sec)       Use Size(byte)     Total Size(byte)         Total Object                    GC time(ms)
    1               0.012               159240               212940                10647         0.00000000000001530000

GC::Profiler.total_time → float

() → Float

Source

static VALUE
gc_profile_total_time(VALUE self)
{
    double time = 0;
    rb_objspace_t *objspace = rb_gc_get_objspace();

    if (objspace->profile.run && objspace->profile.next_index > 0) {
        size_t i;
        size_t count = objspace->profile.next_index;

        for (i = 0; i < count; i++) {
            time += objspace->profile.records[i].gc_time;
        }
    }
    return DBL2NUM(time);
}

The total time used for garbage collection in seconds