Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 27 additions & 4 deletions ext/fiber/profiler/capture.c
Original file line number Diff line number Diff line change
Expand Up @@ -627,6 +627,29 @@ static size_t Fiber_Profiler_Capture_absolute_nesting(struct Fiber_Profiler_Capt
// If a call is within this threshold of the parent call, it will be skipped when printing the call stack - it's considered inconsequential to the performance of the parent call.
static const double Fiber_Profiler_Capture_SKIP_THRESHOLD = 0.98;

static VALUE Fiber_Profiler_Capture_class_label(VALUE klass) {
// Included modules are represented by hidden ICLASS objects:
if (RB_TYPE_P(klass, T_ICLASS)) {
klass = RBASIC_CLASS(klass);
}

if (RB_TYPE_P(klass, T_CLASS) || RB_TYPE_P(klass, T_MODULE)) {
// Hidden classes/modules cannot be inspected, but `rb_class_path` reads their path directly:
if (!RBASIC_CLASS(klass)) {
VALUE path = rb_class_path(klass);

if (RB_TYPE_P(path, T_STRING)) return path;

return rb_str_new_cstr(RB_TYPE_P(klass, T_CLASS) ? "<hidden class>" : "<hidden module>");
}

// Preserve `rb_inspect` formatting for visible classes, especially singleton classes:
return rb_inspect(klass);
}

return rb_str_new_cstr("<unknown>");
}

void Fiber_Profiler_Capture_print_tty(struct Fiber_Profiler_Capture *capture, FILE *restrict stream, double duration) {
double start_time = Fiber_Profiler_Time_delta(&capture->start_time, &capture->switch_time);

Expand Down Expand Up @@ -677,13 +700,13 @@ void Fiber_Profiler_Capture_print_tty(struct Fiber_Profiler_Capture *capture, FI
fprintf(stream, "\e[31m");
}

VALUE class_inspect = rb_inspect(call->klass);
VALUE class_label = Fiber_Profiler_Capture_class_label(call->klass);
const char *name = rb_id2name(call->id);

struct timespec offset;
Fiber_Profiler_Time_elapsed(&capture->switch_time, &call->enter_time, &offset);

fprintf(stream, "%s:%d in %s '%s#%s' (%0.4fs, T+" Fiber_Profiler_TIME_PRINTF_TIMESPEC ")\n", call->path, call->line, event_flag_name(call->event_flag), RSTRING_PTR(class_inspect), name, call->duration, Fiber_Profiler_TIME_PRINTF_TIMESPEC_ARGUMENTS(offset));
fprintf(stream, "%s:%d in %s '%s#%s' (%0.4fs, T+" Fiber_Profiler_TIME_PRINTF_TIMESPEC ")\n", call->path, call->line, event_flag_name(call->event_flag), RSTRING_PTR(class_label), name, call->duration, Fiber_Profiler_TIME_PRINTF_TIMESPEC_ARGUMENTS(offset));

fprintf(stream, "\e[0m");

Expand Down Expand Up @@ -731,15 +754,15 @@ void Fiber_Profiler_Capture_print_json(struct Fiber_Profiler_Capture *capture, F
call->nesting = call->parent->nesting + 1;
}

VALUE class_inspect = rb_inspect(call->klass);
VALUE class_label = Fiber_Profiler_Capture_class_label(call->klass);
const char *name = rb_id2name(call->id);

size_t nesting = Fiber_Profiler_Capture_absolute_nesting(capture, call);

struct timespec offset;
Fiber_Profiler_Time_elapsed(&capture->switch_time, &call->enter_time, &offset);

fprintf(stream, "%s{\"path\":\"%s\",\"line\":%d,\"class\":\"%s\",\"method\":\"%s\",\"duration\":%0.6f,\"offset\":" Fiber_Profiler_TIME_PRINTF_TIMESPEC ",\"nesting\":%zu,\"skipped\":%zu,\"filtered\":%zu}", first ? "" : ",", call->path, call->line, RSTRING_PTR(class_inspect), name, call->duration, Fiber_Profiler_TIME_PRINTF_TIMESPEC_ARGUMENTS(offset), nesting, skipped, call->filtered);
fprintf(stream, "%s{\"path\":\"%s\",\"line\":%d,\"class\":\"%s\",\"method\":\"%s\",\"duration\":%0.6f,\"offset\":" Fiber_Profiler_TIME_PRINTF_TIMESPEC ",\"nesting\":%zu,\"skipped\":%zu,\"filtered\":%zu}", first ? "" : ",", call->path, call->line, RSTRING_PTR(class_label), name, call->duration, Fiber_Profiler_TIME_PRINTF_TIMESPEC_ARGUMENTS(offset), nesting, skipped, call->filtered);

skipped = 0;
first = 0;
Expand Down
45 changes: 45 additions & 0 deletions test/fiber/profiler/capture.rb
Original file line number Diff line number Diff line change
Expand Up @@ -140,6 +140,51 @@ def nested(n = 100, &block)
end
end

with "hidden classes" do
let(:capture) {subject.new(stall_threshold: 0, filter_threshold: 0, output: output)}

it "can report garbage collection inside methods of hidden classes" do
capture.start

Fiber.new do
GC.stress = true

# Lambda literals call a method on the hidden singleton class of RubyVM::FrozenCore:
->{}
ensure
GC.stress = false
end.resume

capture.stop

stall = JSON.parse(output.string)
calls = stall["calls"]
expect(calls).to have_value(have_keys(
"class" => be =~ /\A#<Class:0x\h+>\z/,
"method" => be == "lambda",
))
end
end

with "singleton classes" do
it "reports the singleton class by name" do
capture.start

Fiber.new do
Kernel.sleep 0.001
end.resume

capture.stop

stall = JSON.parse(output.string)
calls = stall["calls"]
expect(calls).to have_value(have_keys(
"class" => be == "#<Class:Kernel>",
"method" => be == "sleep",
))
end
end

with "Process.fork" do
it "should disable the profiler in the child process after fork" do
capture.start
Expand Down
Loading