Say what particular C function is being sampled

[segiddins]

I think this should be possible, at worst by reading the instruction pointer and walking back until you find a function?

This would be very helpful for me, since apparently I'm spending 60% of time in unknown C functions.

[jvns]

Yeah, I think I might give this a shot! Can you send me a flamegraph of what you're seeing? i'd be curious to see what it looks like.

[segiddins]

Uploaded the flamegraph, but the 60% number comes from the summary that you print out while sampling
rbspy-2018-02-21-w6gzSFp10X.flamegraph.svg.zip

[jvns]

thanks! I think what's going on in your case (and this is likely to be true for a lot of people) is that there are a lot of different C functions being called, but they're all aggregated together because rbspy can't tell that they're different and so it looks weird.

I wonder if (as a start) it would make sense to just exclude C functions from the summary because it's so uninformative and instead just report whatever Ruby function is closest to the top of the stack.

[segiddins]

I wonder if (as a start) it would make sense to just exclude C functions from the summary because it's so uninformative and instead just report whatever Ruby function is closest to the top of the stack.

I think that would be much more helpful!

[cataphract]

control_frame_dump in vm_dump.c of the ruby source (looking at 2.3.3 here), rather than skipping when cfp->iseq is NULL, like rbspy does, has this code for line numbers:

    if (cfp->iseq != 0) { ... }
    else if ((me = rb_vm_frame_method_entry(cfp)) != NULL) {
        iseq_name = rb_id2name(me->def->original_id);
        snprintf(posbuf, MAX_POSBUF, ":%s", iseq_name);
        line = -1;
    }

with

const rb_callable_method_entry_t *
rb_vm_frame_method_entry(const rb_control_frame_t *cfp)
{
    VALUE *ep = cfp->ep;
    rb_callable_method_entry_t *me;

    while (!VM_EP_LEP_P(ep)) {
        if ((me = check_method_entry(ep[-1], FALSE)) != NULL) return me;
        ep = VM_EP_PREV_EP(ep);
    }

    return check_method_entry(ep[-1], TRUE);
}

I know next to nothing of Ruby VM internals, but maybe this isn't too hard to implement. Unfortunately, I don't know Rust so I can't help. I also wonder what the point of using Rust for this project is, since it prevents straightforward usage of the C definitions in the Ruby source code.

[AlexWayfer]

I tried rbspy with puma and there is:

% self  % total  name
 99.68   100.00  <c function> - unknown
...

😥

[ViugiNick]

@jvns @cataphract I tried to implement the logic of getting the c-level frame symbols. Actually, I just took it from .gdbinit and reimplement on rust. VM_FRAME_TYPE($cfp->flag) == VM_FRAME_MAGIC_CFUNC section(https://github.com/ruby/ruby/blob/d4f1187d31ee300c502713587a26ca186c8e04b9/.gdbinit#L1157) and check_method_entry method(https://github.com/ruby/ruby/blob/d4f1187d31ee300c502713587a26ca186c8e04b9/.gdbinit#L1053) works just fine and symbol ID obtaining successfully. But I ran into a problem when trying to get a symbol by it's ID(https://github.com/ruby/ruby/blob/d4f1187d31ee300c502713587a26ca186c8e04b9/.gdbinit#L1068). This method uses the global cache(global_symbols) and number of constants: tLAST_OP_ID, RUBY_ID_SCOPE_SHIFT, ID_ENTRY_UNIT, RUBY_FL_USER1, RUBY_FL_USER3, RUBY_FL_USER4, RUBY_FL_USHIFT, ID_ENTRY_SIZE and I do not really understand how to work with them. Could you please help with rb_id2name implementation.

[cataphract]

@ViugiNick Do you have a diff of your changes? Maybe I can can take a shot at it, though I don't know Rust.

[ViugiNick]

@cataphract @jvns https://gist.github.com/ViugiNick/583a55a73a515891f545e57653127def
this code snippet finds a method entry (me) and obviously mid = me->def->original_id. But it does not work out for me to get the readable name of the method.

[x-ji]

@AlexWayfer Me too even though #114 should have ensured that C functions are ignored in the summary?

[vizcay]

I have tried to use rbspy to profile a Rails 6 application with ruby 2.6.2 an it is completely inusable because of this:

Summary of profiling data so far:
% self  % total  name
 93.14    99.97  <c function> - unknown
  0.15     0.20  [] - /usr/local/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/aws-sdk-core-3.92.0/lib/seahorse/model/shapes.rb
  0.12     0.23  jsonify - /usr/local/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.2/lib/active_support/json/encoding.rb
  0.12     0.20  block in normalized_querystring - /usr/local/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/aws-sigv4-1.1.1/lib/aws-sigv4/signer.r
...

[ilyazub]

@vizcay Try perf report from perf Linux profiler and flamegraph crate to dig into C code. You may need to recompile Ruby with debug symbols. -ggdb3 is the default, but check your CFLAGS to be sure.

$ ruby -rrbconfig -e 'puts RbConfig::CONFIG["CFLAGS"]'
-O3 -ggdb3 -Wall -Wextra -Wdeprecated-declarations -Wduplicated-cond -Wimplicit-function-declaration -Wimplicit-int -Wmisleading-indentation -Wpointer-arith -Wwrite-strings -Wimplicit-fallthrough=0 -Wmissing-noreturn -Wno-cast-function-type -Wno-constant-logical-operand -Wno-long-long -Wno-missing-field-initializers -Wno-overlength-strings -Wno-packed-bitfield-compat -Wno-parentheses-equality -Wno-self-assign -Wno-tautological-compare -Wno-unused-parameter -Wno-unused-value -Wsuggest-attribute=format -Wsuggest-attribute=noreturn -Wunused-variable  -fPIC

[acj]

The code still needs a bit of polish, but I have this mostly working for ruby 2.7. Details in #282. Big thanks to @ViugiNick for the tip about porting the gdbinit functions.

If anyone has time to give it a try, I'd be grateful for any feedback and testing help.

[jvns]

SO DELIGHTED that this is fixed, I really had no idea how to approach this and this was the #1 biggest feature I wanted rbspy to have the most. thanks again so much @acj!!!