rbspy / rbspy Goto Github PK

View Code? Open in Web Editor NEW

2.5K 44.0 101.0 2.21 MB

Sampling CPU profiler for Ruby

Home Page: https://rbspy.github.io

License: MIT License

Rust 99.96% Shell 0.01% Ruby 0.02% Dockerfile 0.01%

rust profilers cpu ruby

rbspy's People

Stargazers

Watchers

Forkers

doy falloutdurham kamalmarhubi philipc dirk floehopper petems luser punalpatel cben linpingchuan gitter-badger mehrdad-shokri happy-ferret matthewrudy raventid liaden ryancoleman zerothabhishek nurse alanbrent danielribeiro thbar vasi jonathanmarvens mvidner mathiasjakobsen djbender ognz mzumi tvanderpol jmeagher guoyu07 akmalds ethan-well tcaddy akhramov koncybernet julia-stripe ndcroos jlfwong benfred wabain agiamas hartator at1as mnin clatour printercu svkmax alexcameron89 dheeraj-thedev sadiqmmm iainsmith viuginick hal2001 xiaolang098 souravtt kzys juanitofatas levkk brunsa2 makketagg ciprianbadescu igorwwwwwwwwwwwwwwwwwwww joshado akiellor donoghuc 5l1v3r1 paul-mannino petethepig geraudster ens9 stjordanis sbezugliy jarthod acj gedkott llvtt granulate yusufozturk dalehamel johnduhart saunderst theojulienne icodein hsnylmz008 jacoblockard99 omarabid-archived doytsujin peamaeq omarabid nist horki woolenwang maaarcocr caalberts ixti p0mm vuta

rbspy's Issues

Add ability to split out usage by thread

Came up in #21.

ruby-stacktrace looks up the id of the running thread and looks at its stack. We could tally usage tied to the thread and output a per-thread usage amount. I don't know if that would be misleading or not given global VM lock (GVL).

Alternative time viewing formats

I see in this blog post you're looking at ways to view times for call graphs
https://jvns.ca/blog/2018/02/06/profiler-week-5/

Including (I imagine) total time for a function (including time of all functions called) and time spent in the code of that function itself, including for recursive programs.

You might want to look at some of the tools Android has for this which allow you to navigate an ordered list (by % of time spent) of functions, and down into their children (which recursively might lead you back to the original :-) )...

I don't have a screenshot handy, but as it's interactive you might want to play with it anyway.... If you need pointers to blog posts of videos, I can find them (don't have my Android environment up to date :-( ).

If you generate output in a suitable format, you might even be able to use the tool directly, it's all written in portable Java I think.

(BTW: They have Memory profiling analysis tools also, with "retained memory" and the like also....)

[mac-support] 2 tests fail with "Expected NoSuchProcess error"

On High Sierra, I get this failure (while investigating on #70):

10:24 $ RUST_BACKTRACE=1 cargo test test_get_nonexistent_process
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
     Running target/debug/deps/rbspy-212acef39ff53d5d

running 1 test
test initialize::test_get_nonexistent_process ... FAILED

failures:

---- initialize::test_get_nonexistent_process stdout ----
	Before task_for_pid
After task_for_pid
thread 'initialize::test_get_nonexistent_process' panicked at 'Expected NoSuchProcess error', src/initialize.rs:141:13
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:68
   2: std::panicking::default_hook::{{closure}}
             at src/libstd/sys_common/backtrace.rs:57
             at src/libstd/panicking.rs:381
   3: std::panicking::default_hook
             at src/libstd/panicking.rs:391
   4: std::panicking::begin_panic
             at src/libstd/panicking.rs:577
   5: std::panicking::begin_panic
             at /Users/travis/build/rust-lang/rust/src/libstd/panicking.rs:538
   6: rbspy::initialize::test_get_nonexistent_process
             at src/initialize.rs:141
   7: <F as test::FnBox<T>>::call_box
             at src/libtest/lib.rs:1510
             at /Users/travis/build/rust-lang/rust/src/libcore/ops/function.rs:223
             at src/libtest/lib.rs:142
   8: panic_unwind::dwarf::eh::read_encoded_pointer
             at src/libpanic_unwind/lib.rs:101


failures:
    initialize::test_get_nonexistent_process

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 10 filtered out

Another test fails with a similar error:

10:25 $ RUST_BACKTRACE=1 cargo test test_get_disallowed_process
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
     Running target/debug/deps/rbspy-212acef39ff53d5d

running 1 test
test initialize::test_get_disallowed_process ... FAILED

failures:

---- initialize::test_get_disallowed_process stdout ----
	Before task_for_pid
After task_for_pid
thread 'initialize::test_get_disallowed_process' panicked at 'Expected NoSuchProcess error', src/initialize.rs:155:13
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:68
   2: std::panicking::default_hook::{{closure}}
             at src/libstd/sys_common/backtrace.rs:57
             at src/libstd/panicking.rs:381
   3: std::panicking::default_hook
             at src/libstd/panicking.rs:391
   4: std::panicking::begin_panic
             at src/libstd/panicking.rs:577
   5: std::panicking::begin_panic
             at /Users/travis/build/rust-lang/rust/src/libstd/panicking.rs:538
   6: rbspy::initialize::test_get_disallowed_process
             at src/initialize.rs:155
   7: <F as test::FnBox<T>>::call_box
             at src/libtest/lib.rs:1510
             at /Users/travis/build/rust-lang/rust/src/libcore/ops/function.rs:223
             at src/libtest/lib.rs:142
   8: panic_unwind::dwarf::eh::read_encoded_pointer
             at src/libpanic_unwind/lib.rs:101


failures:
    initialize::test_get_disallowed_process

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 10 filtered out

Confusing duration param

Hi Julia, your rbspy work is amazing so far, I'm really enjoying reading about your progress.

One stumble I had was the --duration parameter. What is it? Seconds? Millis? I assume it is seconds but it would be useful to tweak the readme to say so.

"Too much memory when copying: NNN"

Hi @jvns! I was trying to profile jekyll build on the latest master for a "massive" site (10,000 posts) and am running into an interesting memory issue! Have you seen this before?

I'm running on a Linode VM with 1GB memory. Do I need more memory? jekyll build runs fine. 😄

~/rbspy$ git rev-parse HEAD
a8e3c31bba61bec0c47269f9b39a1e5e7eb7a4c1
~/massive-jekyll-site$ free -m
              total        used        free      shared  buff/cache   available
Mem:            979         191         434          11         353         757
Swap:           511          47         464
~/massive-jekyll-site$ RUST_BACKTRACE=1 ~/rbspy/target/debug/rbspy record -- /home/parker/jekyll/exe/jekyll build
Press Ctrl+C to stop
Dropped 21/21 stack traces because of errors.
Error. Causes:
- Too much memory requested when copying: 2492672
stack backtrace:
   0:     0x560d772c50fc - backtrace::backtrace::libunwind::trace
                        at /home/parker/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.5/src/backtrace/libunwind.rs:53
                         - backtrace::backtrace::trace<closure>
                        at /home/parker/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.5/src/backtrace/mod.rs:42
   1:     0x560d772beeaf - backtrace::capture::{{impl}}::new_unresolved
                        at /home/parker/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.5/src/capture.rs:88
   2:     0x560d772bdaf1 - failure::backtrace::internal::{{impl}}::new
                        at /home/parker/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/backtrace/internal.rs:44
   3:     0x560d772bb97e - failure::backtrace::{{impl}}::new
                        at /home/parker/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/backtrace/mod.rs:98
   4:     0x560d76d5e4f0 - failure::error::{{impl}}::from<rbspy::core::copy::MemoryCopyError>
                        at /home/parker/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/error.rs:34
   5:     0x560d76d0e1f7 - core::convert::{{impl}}::into<rbspy::core::copy::MemoryCopyError,failure::error::Error>
                        at /checkout/src/libcore/convert.rs:415
   6:     0x560d76de2f0f - rbspy::record
                        at src/main.rs:319
   7:     0x560d76de0bf6 - rbspy::do_main
                        at src/main.rs:161
   8:     0x560d76de1556 - rbspy::main
                        at src/main.rs:188
   9:     0x560d77308c9e - panic_unwind::__rust_maybe_catch_panic
                        at /checkout/src/libpanic_unwind/lib.rs:101
  10:     0x560d77300bbb - std::panicking::try<(),closure>
                        at /checkout/src/libstd/panicking.rs:459
                         - std::panic::catch_unwind<closure,()>
                        at /checkout/src/libstd/panic.rs:365
                         - std::rt::lang_start
                        at /checkout/src/libstd/rt.rs:58
  11:     0x560d76de8c3d - main
  12:     0x7f8bc2c082b0 - __libc_start_main
  13:     0x560d76cb9a49 - _start
  14:                0x0 - <unknown>

Thank you!!!!!!!!

Mac - thread '<unnamed>' panicked at 'oh no'

Hi!

I am trying to run rbspy 0.2.3 and I get error:

λ ~/code/work/proj/ * sudo --preserve-env RUST_BACKTRACE=full rbspy record --pid 49967
Press Ctrl+C to stop
thread '<unnamed>' panicked at 'oh no', src/core/initialize.rs:246:14
stack backtrace:
   0:        0x10cc68a1b - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::hd73ae1f41856f0d1
   1:        0x10cc5fe20 - std::panicking::default_hook::{{closure}}::h7e341e4ee700d014
   2:        0x10cc5fa35 - std::panicking::default_hook::h3fab1e8be34045b9
   3:        0x10cc605f6 - std::panicking::rust_panic_with_hook::h6e16f84ca8c4a724
   4:        0x10cb42f71 - std::panicking::begin_panic::hc97858bb471b3dd7
   5:        0x10cac343d - rbspy::core::initialize::initialize::h4265615c2bdc47de
   6:        0x10cadeed5 - rbspy::record::h9dfbe20f7a245ebb
   7:        0x10ca9eb39 - std::sys_common::backtrace::__rust_begin_short_backtrace::h838dfde366dceb43
   8:        0x10cb43037 - std::panicking::try::do_call::hc7e59becec5402d9
   9:        0x10cc8308e - __rust_maybe_catch_panic
  10:        0x10caba3bf - <F as alloc::boxed::FnBox<A>>::call_box::h6ea378e418665f76
  11:        0x10cc6ca27 - std::sys_common::thread::start_thread::h258fdf6392ccb10d
  12:        0x10cc702e8 - std::sys::unix::thread::Thread::new::thread_start::h6cf40318f87880ff
  13:     0x7fff7d6ef6c0 - _pthread_body
  14:     0x7fff7d6ef56c - _pthread_start
Wrote raw data to /Users/yosi/.cache/rbspy/records/rbspy-2018-04-03-spaAgsDQMe.raw.gz
Writing formatted output to /Users/yosi/.cache/rbspy/records/rbspy-2018-04-03-O5g0KOHnGB.flamegraph.svg
ERROR: No stack counts found

By looking at the line in question - https://github.com/rbspy/rbspy/blob/master/src/core/initialize.rs#L246
It looks like this is because I am running Ruby 2.5.1 which isn't supported yet?

os error 14 on Ubuntu

Hello,

I tried to use rbspy to profile a jekyll build call on Ubuntu 16.04, but I'm having the following error:

$ rbspy record -- bundle exec jekyll build
Press Ctrl+C to stop
Dropped 29/57 stack traces because of errors.
Wrote raw data to /home/tim/.cache/rbspy/records/rbspy-2018-04-30-J3YBZ0ZThp.raw.gz
Writing formatted output to /home/tim/.cache/rbspy/records/rbspy-2018-04-30-73lvDNz4eP.flamegraph.svg
Error. Causes:
- Failed to copy memory address 7fd85f24c820
- Bad address (os error 14)

The actual jekyll build command is correctly executed, though.

The repository to reproduce the error can be found here: https://github.com/algolia/jekyll-algolia-example

$ bundle install
$ rbspy record -- bundle exec jekyll build

Happy to help if there's anything I can do :)

Report dropped stack traces

we stopped doing this properly at some point. need to start again.

Little details in profile of rspec

I just started to use the tool the other night, and actually want to use it exactly for one of the primary use-cases "One common use case for rbspy is profiling slow unit test runs " 😀

However, I am getting confusing results on my first try
I ran it on a test[1] in rspec (macos 10.13.4), and I get one big lump of a flame graph

There is a lot of unknown line 0, and for what there is for info seems unrelated (spring and require).

I am new to *nix perf, so let me know if I am just making a novice mistake and need to do something more to configure it

[1] rbspy record -- bin/rspec <file_path

Add option to profile all subprocesses of a given PID

It's a pretty common pattern in web services (eg Unicorn) to use a process supervisor that forks a bunch of Ruby subprocesses to run the web service. Could be useful to add a --subprocesses option that will profile all subprocesses of a given PID.

Another related issue is -- @liaden described an issue where they frequently kill their Ruby workers and start new ones (every 1-3 minutes or so). So tracking new workers under a process and profiling the new workers when they start could be useful.

This is basically like strace's -f option.

[mac-support] 1 test fails with "version should exist: MacPermissionDenied(6896)"

While investigating on #70, I got that error while running test_current_thread_address (Mac High Sierra):

10:27 $ cargo test test_current_thread_address
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
     Running target/debug/deps/rbspy-212acef39ff53d5d

running 1 test
test initialize::test_current_thread_address ... FAILED

failures:

---- initialize::test_current_thread_address stdout ----
	Before task_for_pid
After task_for_pid
thread 'initialize::test_current_thread_address' panicked at 'version should exist: MacPermissionDenied(6896)', src/libcore/result.rs:906:4
note: Run with `RUST_BACKTRACE=1` for a backtrace.


failures:
    initialize::test_current_thread_address

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 10 filtered out

error: test failed, to rerun pass '--bin rbspy'
Ignoring bcrypt-3.1.11 because its extensions are not built.  Try: gem pristine bcrypt --version 3.1.11
Ignoring binding_of_caller-0.7.3 because its extensions are not built.  Try: gem pristine binding_of_caller --version 0.7.3
Ignoring byebug-9.1.0 because its extensions are not built.  Try: gem pristine byebug --version 9.1.0
Ignoring debug_inspector-0.0.3 because its extensions are not built.  Try: gem pristine debug_inspector --version 0.0.3
/usr/bin/ruby: Input/output error @ io_fillbuf - fd:0 <STDIN> (Errno::EIO)

Get rid of "variant is never constructed: `MacPermissionDenied`" warning

It's confusing for people trying to develop rbspy.

Inaccurate flamegraph when using threads

Hey there,

I was taking rbspy for a run and was testing how well it sampled threaded programs. My code was as follows:

def foo
  sleep 10
end

def bar
  sleep 10
end

threads = []
threads << Thread.new { 10.times { foo } }
threads << Thread.new { 10.times { bar } }
threads.each(&:join)

My expected flamegraph would show that half the time was spent in foo and the other half in bar. Unfortunately, this was the output:

I was using ruby 2.3.0p0 (2015-12-25 revision 53290) [x86_64-darwin16]. Do you know if I'm doing anything wrong here?

OS error 17 when running rbspy on mac

@parkr reported having this issue on Mac (High Sierra) when trying to run rbspy. I haven't been able to reproduce this yet but creating an issue to track it!

~/code/rbspy#mac-support$ rm -rf target && cargo build
~/code/rbspy#mac-support$ sudo --preserve-env ./target/debug/rbspy record ruby ./ci/ruby-programs/infinite.rb Dropping permissions: running Ruby command as user parkr
Error. Causes:
- Couldn't determine Ruby version
- Couldn't connect to PID
- File exists (os error 17)

~/code/rbspy#mac-support$ rbenv version
2.4.3 (set by /Users/parkr/code/rbspy/.ruby-version)
~/code/rbspy#mac-support$ sudo --preserve-env env RUST_LOG=debug RUST_BACKTRACE=1 ./target/debug/rbspy record ruby ./ci/ruby-programs/infinite.rb
Dropping permissions: running Ruby command as user parkr
Error. Causes:
- Couldn't determine Ruby version
- Couldn't connect to PID
- File exists (os error 17)
stack backtrace:
   0:        0x10fd4ab2c - backtrace::backtrace::trace<closure>
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.5/src/backtrace/mod.rs:42
   1:        0x10fd4210f - backtrace::capture::Backtrace::new_unresolved::h22a3194b78596c3b
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.5/src/capture.rs:88
   2:        0x10fd3ffc1 - failure::backtrace::internal::{{impl}}::new
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/backtrace/internal.rs:44
   3:        0x10fd404fe - failure::backtrace::Backtrace::new::h3969a68773a2cd75
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/backtrace/mod.rs:98
   4:        0x10f802540 - failure::error::{{impl}}::from<std::io::error::Error>
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/error.rs:34
   5:        0x10f7ff4e9 - core::convert::{{impl}}::into<std::io::error::Error,failure::error::Error>
                        at /Users/travis/build/rust-lang/rust/src/libcore/convert.rs:415
   6:        0x10f7de128 - failure::context::{{impl}}::with_err<&str,std::io::error::Error>
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/context.rs:78
   7:        0x10f803dec - failure::Fail::context<std::io::error::Error,&str>
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/lib.rs:127
   8:        0x10f7f02bc - failure::result_ext::{{impl}}::context::{{closure}}<u32,std::io::error::Error,&str>
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/result_ext.rs:32
   9:        0x10f859d0d - core::result::{{impl}}::map_err<u32,std::io::error::Error,failure::context::Context<&str>,closure>
                        at /Users/travis/build/rust-lang/rust/src/libcore/result.rs:500
  10:        0x10f850b10 - failure::result_ext::{{impl}}::context<u32,std::io::error::Error,&str>
                        at /Users/parkr/.cargo/registry/src/github.com-1ecc6299db9ec823/failure-0.1.1/src/result_ext.rs:32
  11:        0x10f7edd55 - rbspy::initialize::get_ruby_version_retry
                        at src/initialize.rs:106
  12:        0x10f7ecf02 - rbspy::initialize::initialize
                        at src/initialize.rs:29
  13:        0x10f8399e5 - rbspy::record
                        at src/main.rs:208
  14:        0x10f838698 - rbspy::do_main
                        at src/main.rs:137
  15:        0x10f838ea3 - rbspy::main
                        at src/main.rs:168
  16:        0x10fd76e1e - __rust_maybe_catch_panic
                        at src/libpanic_unwind/lib.rs:101
  17:        0x10fd6c278 - std::rt::lang_start::h0ff358a55ab2ec4c
                        at src/libstd/rt.rs:58
  18:        0x10f83d644 - main

License?

Hey there! I love the idea of this tool, and was toying with the idea of doing something similar for other languages. I'd love to reuse some of your code, but you don't have a license on it currently. Would you be amenable to adding an open source license so I can reuse it? I spent a little time fiddling yesterday and extracted the "read process memory" bits into a standalone crate (and even added a Windows implementation), so if you add a license I can publish that to crates.io and submit a PR for this project to use it. :)

sample time spent in gc

i was playing around with stackprof as described in this blog post and noticed that it includes a garbage collection span at the top level!

i have no idea how difficult it is to detect that gc is happening from outside of the process, but time spent in gc seems like something super useful to know!

'allocator memory exhausted' error when spying on a Rails process

I'm giving this a spin by trying to profile bits of my Rails app.

Usually, when I load a page on the spied-upon rails server, rbspy exits immediately like this:

$ sudo rbspy record --pid 32471
Recording data to /root/.cache/rbspy/records/rbspy-2018-01-25-tw0bEjjEZq.txt
Press Ctrl+C to stop
fatal runtime error: allocator memory exhausted
Illegal instruction

It works for lighter page loads, like json endpoints that don't load or serve all that much data, but for typical tasks in my app that I'd like to profile, I haven't been able to get around this error.

rbspy doesn't work if the Ruby process is using jemalloc

sam@ubuntu discourse % irb 
irb(main):001:0> RUBY_VERSION
=> "2.4.2"
irb(main):002:0> `rbspy snapshot --pid #{Process.pid}`
Error. Causes: 
- Couldn't determine Ruby version
- Heap map not found for PID: 13599

 % uname -a
Linux ubuntu 4.4.0-36-generic #55-Ubuntu SMP Thu Aug 11 18:01:55 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

% lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 16.04.1 LTS
Release:	16.04
Codename:	xenial

Relevant env

% export | grep RUBY
RUBY_GLOBAL_METHOD_CACHE_SIZE=131072

% export | grep LD_PRE
LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so

Also for some reason cargo build is taking forever, are there any tricks to getting it to build?

Easily access graphs from prd systems

One huge pain point with svg and html based reports is that you need to figure out how to transport the graphics from a production server back to your local box.

It would be super cool if rbspy was able to upload encrypted payloads to the cloud and then you could easily access them:

% rebspy record PID --duration 1.5 --online
visit the following url to see the graph: 
https://rbspy-reports.com/graphs/12345#MAGIC_DECRYPTION_KEY

On our side I would be super happy to donate a digital ocean instance or 2 for the cause if you wish to build something like this.

Say what particular C function is being sampled

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.

[mac-support] error while trying to profile

Hello again 😄 I tried using the mac-support branch but cannot get to profile a program.

I'm using this very simple program, with RVM 1.29.3 and Ruby 2.5.0.

loop do
  sleep(0.2)
  puts "OK"
end

I then get the pid and run:

✘-1 ~/git/kiba-ruby-benchmarks [master|✚ 1…1] 
19:21 $ sudo ../rbspy/target/debug/rbspy record --pid 7185
Error. Causes: 
- Couldn't determine Ruby version
- Couldn't get `_ruby_version` symbol. This is likely because rbspy doesn't work with system Ruby on Mac. Try with rbenv/rvm ruby?

Support higher sample rates than 100 times/second

Right now (since rbspy uses process_vm_readv) it takes more than 1ms to do each sample. This means that we can't really support sample rates of more than 100 times/second.

I'm not sure yet why exactly somebody would need to sample at a rate higher than say 100 times/second, but if somebody has a use case I'd be interested to hear it.

Exclude files, modules, methods

Running rbspy against complex projects, in my case RSpec feature tests of a Rails app, the output is enormous. I'm usually just interested in own code, so I would like to exclude complete gems (rails, rspec, vcr, ...) or just modules. Often it also makes sense just exclude distinct methods. ruby-prof provides some mechanismus to exclude data points while and after profiling.

Having a flexible mechanism to exclude stack frames based on file name, module, and method name while profiling would make much sense!

Panic at 'index out of bounds: the len is 0 but the index is 0'

Thanks for rbspy!

When running a RUST_BACKTRACE=1 rbspy record -- bundle exec rspec -t @some_tag I'm seeing the trace below. The specs in question use rails, capybara, thin and poltergeist to execute some 'integration' specs, so plenty of things with threads going on. Unfortunately I cannot share our setup and I haven't been able to reproduce it using something simpler. Just trying to pinpoint the exact spec that fails (via rspec -f d or via puts) (it fails after about a minute of executing many specs successfully) makes the panic go away.

So this issue is mainly to document that users may currently encounter this error, at least when using rbspy 0.2.4, Ruby 2.5.0, Rails 4.2.10.

thread 'main' panicked at 'index out of bounds: the len is 0 but the index is 0', /checkout/src/liballoc/vec.rs:1551:10
stack backtrace:
   0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
             at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at libstd/sys_common/backtrace.rs:59
             at libstd/panicking.rs:380
   3: std::panicking::default_hook
             at libstd/panicking.rs:396
   4: std::panicking::rust_panic_with_hook
             at libstd/panicking.rs:576
   5: std::panicking::begin_panic
             at libstd/panicking.rs:537
   6: std::panicking::begin_panic_fmt
             at libstd/panicking.rs:521
   7: rust_begin_unwind
             at libstd/panicking.rs:497
   8: core::panicking::panic_fmt
             at libcore/panicking.rs:71
   9: core::panicking::panic_bounds_check
             at libcore/panicking.rs:58
  10: rbspy::ui::summary::Stats::add_function_name
  11: rbspy::do_main
  12: rbspy::main
  13: std::rt::lang_start::{{closure}}
  14: std::panicking::try::do_call
             at libstd/rt.rs:59
             at libstd/panicking.rs:479
  15: __rust_maybe_catch_panic
             at libpanic_unwind/lib.rs:102
  16: std::rt::lang_start_internal
             at libstd/panicking.rs:458
             at libstd/panic.rs:358
             at libstd/rt.rs:58
  17: main

trace processes that run in docker-container.

Hi - love rbspy already - big thanx. I can see this becoming a very important tool for all the ruby people out there!

I run quite a few things in docker container and love to trace them without having to enter the container (i would also run the container privileged I believe to use rbspy within the container).

To reproduce:
docker-host> docker run ruby ruby -e "sleep(500)"

(in different shell)
docker-host> ps auxww |grep "ruby -e sleep"
root 27179 0.0 0.0 38008 7460 ? Ssl 16:28 0:00 ruby -e sleep(500)
docker-host> sudo ./rbspy snapshot --pid 27179
Error. Causes:

Couldn't determine Ruby version
Couldn't open ELF file: /usr/local/bin/ruby

This is do to the fact that ruby is of course installed in the container somewhere in the depth of /var/lib/docker ...

report shouldn't require root on Mac

I understand that root is required while actually profiling, but I suppose it shouldn't be necessary while just converting from raw format to something else?

$ rbspy report -f callgrind -i rbspy.28107.gz -o rbspy.28107.txt
rbspy only works as root on Mac. Try rerunning with `sudo --preserve-env !!`.
If you run `sudo rbspy record ruby your-program.rb`, rbspy will drop privileges when running `ruby your-program.rb`. If you want the Ruby program to run as root, use `rbspy --no-drop-root`.
Error. Causes: 
- rbspy needs to run as root on mac

"tot" column over-counts recursive calls

I suspect a recursive function gets counted several times towards "tot" column?

A simple non-branching recursion, that sleeps ~1/11 of the time inside and sleeps the rest elsewhere:

def recurse(depth)
  if depth > 1
    recurse(depth - 1)
  else
    sleep 0.01  # should spend ~9% here
  end
end

depth = ARGV.first.to_i
while true
  recurse(depth)
  sleep 0.1  # spend ~90% outside `recurse`
end

WIth ruby ~/work-recursive.rb 1 (not recursive), recurse function takes 10% as expected:

 self | tot  | method
 91.0% | 100.0% | <main> : /home/bpaskinc/work-recursive.rb
 9.0% | 9.0% | recurse : /home/bpaskinc/work-recursive.rb

WIth ruby ~/work-recursive.rb 5, "self" column proves we still spend 10% time inside the function, bu it's clearly counted 5 times towards "tot":

 self | tot  | method
 90.0% | 100.0% | <main> : /home/bpaskinc/work-recursive.rb
 10.0% | 50.0% | recurse : /home/bpaskinc/work-recursive.rb

With depth 9, it's 90%, with 10 or more it saturates to 100%....

Bug or feature?

Not sure but I find it unexpected.
Technically that's the precise value of summing self + children.
But I care more about total time spent between entering the func and returning from it, without regard to what other code was called inside. The fact it included same func again shouldn't inflate it IMHO...

Release new artifact?

Is it possible to build a new release artifact for 1.0.0?

The 0.0.4 artifact gives me the following error when I try and use it:

ruby-stacktrace: /lib64/libc.so.6: version `GLIBC_2.18' not found (required by ruby-stacktrace)

Building from master works fine, but it's a pain to have to compile it every time

Collect success stories

I'd like stories from people who are using rbspy. Have you used rbspy successfully to fix a performance problem? What kind of performance problem? How did rbspy help?

This helps with developing rbspy -- if we can see how people are using it, it's easier to figure out what other features might be useful to add!

comment on this issue if you have a story to share!

Allow specifying frequency for recording samples

Some systems will be taxed more heavily than others so it would be nice to be able to adjust the sampling rate for the record subcommand.

Currently rbspy are sampling at 100hz: https://github.com/rbspy/rbspy/blob/master/src/main.rs#L175

Support Ruby 2.4.4

thread '<unnamed>' panicked at 'Ruby version not supported yet: 2.4.4. Please create a GitHub issue and we'll fix it!', src/core/initialize.rs:247:14

2.3.7, 2.4.4 and 2.5.1 have all been released on March 28. rbspy already supports 2.5.1.

@jvns would it be easy to add support for 2.4.4 (and probably 2.3.7) as well? Thanks!

Add feature that tells `rbspy record` how long to record

--duration or something. Often it's useful to record 60 seconds or so of profiling data, and it's annoying to have to manually start and stop the recording after 60 seconds.

@SamSaffron indirectly suggested this in #52.

linux: thread 'main' panicked at 'attempt to subtract with overflow'

Hi! I just pulled & re-compiled at 5f7b361 and got a funky error! Looks like something funky with rbspy::SampleTime::get_sleep_time – maybe related to #79?

~/rbspy$ git rev-parse HEAD
5f7b3615277978d8e50dc335cdfdbb4910e8ddc9
~/massive-jekyll-site$ rustc --version
rustc 1.23.0 (766bd11c8 2018-01-01)
~/rbspy$ which ruby
/usr/bin/ruby
~/massive-jekyll-site$ ruby --version
ruby 2.3.3p222 (2016-11-21) [x86_64-linux-gnu]
~/massive-jekyll-site$ RUST_BACKTRACE=1 ~/rbspy/target/debug/rbspy record /home/parker/jekyll/exe/jekyll build
Recording data to /home/parker/.cache/rbspy/records/rbspy-2018-01-31-Jgn67RAD6i.txt
Press Ctrl+C to stop
Configuration file: none
            Source: /home/parker/massive-jekyll-site
       Destination: /home/parker/massive-jekyll-site/_site
 Incremental build: disabled. Enable with --incremental
      Generating...
thread 'main' panicked at 'attempt to subtract with overflow', src/main.rs:224:9
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:68
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:57
             at /checkout/src/libstd/panicking.rs:381
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:397
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:577
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:538
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:522
   7: rust_begin_unwind
             at /checkout/src/libstd/panicking.rs:498
   8: core::panicking::panic_fmt
             at /checkout/src/libcore/panicking.rs:71
   9: core::panicking::panic
             at /checkout/src/libcore/panicking.rs:51
  10: rbspy::SampleTime::get_sleep_time
             at src/main.rs:224
  11: rbspy::record
             at src/main.rs:292
  12: rbspy::do_main
             at src/main.rs:138
  13: rbspy::main
             at src/main.rs:169
  14: __rust_maybe_catch_panic
             at /checkout/src/libpanic_unwind/lib.rs:101
  15: std::rt::lang_start
             at /checkout/src/libstd/panicking.rs:459
             at /checkout/src/libstd/panic.rs:365
             at /checkout/src/libstd/rt.rs:58
  16: main
  17: __libc_start_main
  18: _start

Flamegraph gem support

It would be cool to have a flamegraph gem support or perhaps a raw mode so you could generate the flamegraph using your favorite tool or even analyse with stackprof direct. (if a compatible raw mode could be established)

Flamegraph gem is a bit more interactive than the static svg it makes it a bit easier to dig into things.

https://github.com/SamSaffron/flamegraph

Figure out how to load debug symbols that aren't in the binary

Lots of package managers have separate packages for debug symbols. Instead of requiring people to use Ruby binaries with debug symbols embedded, it would be nice if we could just require they have the debug symbols package installed.

non-interactive rootless on-demand profiling

there are environments where you do not have root, for example heroku. this means that it is not possible to attach to an existing pid. we could wrap the process creation in rbspy record, but that (afaik) makes assumptions about being an interactive session and will record for the whole lifetime of the process.

i have no idea how feasible this is, but could there be some sort of rbspy record --non-interactive ruby fave.rb that starts ruby as a sub-process, but does not profile anything yet. the rbspy parent process could then be instructed to start profiling, either by sending a signal to it or via HTTP or a unix socket.

this is just a random idea i had, which may very well be outside of the scope of rbspy. and there are certainly other approaches that can be used in this scenario, like replaying production traffic into a less restrictive environment.

`-V` shouldn't require root

Whilst putting together the Homebrew formula for this package (in Homebrew/homebrew-core#23575) I noticed that rbspy -V requires root permissions despite (on the surface) not needing these elevated permissions. Is this by design and I'm missing something here? Or should it not worry about needing root when calling this?

Add a debug dump command to make reporting issues easier

We'll inevitably get lots of issues where we're not expecting the exact hierarchy of structs, eg . Getting debug info from such binaries will be very useful. I wrote a little script to dump the debug sections into a .tgz, but if it was just a ruby-stacktrace dump-info /path/to/my/ruby away, it'd be better. The crash messages could then suggest running it and attaching it to an issue report.

Build broken as crate 'obj' missing

When I try to build I get this:

cargo build
Compiling ruby-stacktrace v0.1.0 (file:///Users/andrew/workspace/ruby-stacktrace)
dwarf.rs:278:16: 278:25 error: failed to resolve. Use of undeclared type or module obj [E0433]
dwarf.rs:278 let file = obj::open(&file_path);
^~~~~~~~~
dwarf.rs:278:16: 278:25 help: run rustc --explain E0433 to see a detailed explanation
dwarf.rs:280:22: 280:38 error: failed to resolve. Use of undeclared type or module obj [E0433]
dwarf.rs:280 let debug_info = obj::get_section(&file, ".debug_info")
^~~~~~~~~~~~~~~~
dwarf.rs:280:22: 280:38 help: run rustc --explain E0433 to see a detailed explanation
dwarf.rs:282:24: 282:40 error: failed to resolve. Use of undeclared type or module obj [E0433]
dwarf.rs:282 let debug_abbrev = obj::get_section(&file, ".debug_abbrev")
^~~~~~~~~~~~~~~~
dwarf.rs:282:24: 282:40 help: run rustc --explain E0433 to see a detailed explanation
dwarf.rs:284:21: 284:37 error: failed to resolve. Use of undeclared type or module obj [E0433]
dwarf.rs:284 let debug_str = obj::get_section(&file, ".debug_str")
^~~~~~~~~~~~~~~~
dwarf.rs:284:21: 284:37 help: run rustc --explain E0433 to see a detailed explanation
dwarf.rs:287:8: 287:29 error: failed to resolve. Use of undeclared type or module obj [E0433]
dwarf.rs:287 if obj::is_little_endian(&file) {
^~~~~~~~~~~~~~~~~~~~~
dwarf.rs:287:8: 287:29 help: run rustc --explain E0433 to see a detailed explanation
error: aborting due to 5 previous errors
error: Could not compile ruby-stacktrace.

To learn more, run the command again with --verbose.

Looks like there is no extern crate and use for the 'obj' crate.... I'm building on Mac OS X

cargo --version
cargo 0.11.0-nightly (259324c 2016-05-20)

Not sure if it builds OK on Linux, if so - then not sure how or where it finds that crate.

I searched for a crate called 'obj' that parses object (ELF?) files, but couldn't figure it out.

Does not have .debug_info section error

I'm trying to test some Ruby code that hangs in Ruby 2.3.1 (see https://bugs.ruby-lang.org/issues/12832)

module Foo
  private

  def foo
    "foo"
  end
end

class Bar
  extend Foo

  class << self
    public :foo
  end
end

module Baz
end

class Bar
  class << self
    prepend Baz
  end
end
Bar.method(:foo) # will hang here

When I run it and try to stacktrace it I get an error...

[root@localhost ruby-stacktrace]# ruby hang_ruby.rb &
[1] 19975
[root@localhost ruby-stacktrace]# RUST_BACKTRACE=1 ruby-stacktrace top 19975
thread 'main' panicked at 'Does not have .debug_info section', ../src/libcore/option.rs:700
note: Run with `RUST_BACKTRACE=1` for a backtrace.
thread 'main' panicked at 'Does not have .debug_info section', ../src/libcore/option.rs:700
stack backtrace:
   1:     0x7f5a4e126ac9 - std::sys::backtrace::tracing::imp::write::h00e948915d1e4c72
   2:     0x7f5a4e12bcac - std::panicking::default_hook::_{{closure}}::h7b8a142818383fb8
   3:     0x7f5a4e12af59 - std::panicking::default_hook::h41cf296f654245d7
   4:     0x7f5a4e12b5e8 - std::panicking::rust_panic_with_hook::h4cbd7ca63ce1aee9
   5:     0x7f5a4e12b442 - std::panicking::begin_panic::h93672d0313d5e8e9
   6:     0x7f5a4e12b3b0 - std::panicking::begin_panic_fmt::hd0daa02942245d81
   7:     0x7f5a4e12b331 - rust_begin_unwind
   8:     0x7f5a4e165e7f - core::panicking::panic_fmt::hbfc935564d134c1b
   9:     0x7f5a4e165ef5 - core::option::expect_failed::h1d846c7a667396f7
  10:     0x7f5a4e06a722 - ruby_stacktrace::dwarf::obj::get_dwarf_entries::he47de19de2e538d4
  11:     0x7f5a4e0594f4 - ruby_stacktrace::main::h33adc6edaef38f5f
  12:     0x7f5a4e133796 - __rust_maybe_catch_panic
  13:     0x7f5a4e12a6d2 - std::rt::lang_start::h53bf99b0829cc03c
  14:     0x7f5a4d44caf4 - __libc_start_main
  15:     0x7f5a4e053d28 - <unknown>
  16:                0x0 - <unknown>
[root@localhost ruby-stacktrace]#

At first I thought it was an error because it was hanging code, but it happens with any code:

 [root@localhost ~]# cat say_hello.rb
foo = 0

while true
  foo = foo + 1
end
[root@localhost ~]# ruby say_hello.rb &
[1] 20271
[root@localhost ~]# RUST_BACKTRACE=1 ruby-stacktrace top 20271
thread 'main' panicked at 'Does not have .debug_info section', ../src/libcore/option.rs:700
stack backtrace:
   1:     0x7ff245e66ac9 - std::sys::backtrace::tracing::imp::write::h00e948915d1e4c72
   2:     0x7ff245e6bcac - std::panicking::default_hook::_{{closure}}::h7b8a142818383fb8
   3:     0x7ff245e6af59 - std::panicking::default_hook::h41cf296f654245d7
   4:     0x7ff245e6b5e8 - std::panicking::rust_panic_with_hook::h4cbd7ca63ce1aee9
   5:     0x7ff245e6b442 - std::panicking::begin_panic::h93672d0313d5e8e9
   6:     0x7ff245e6b3b0 - std::panicking::begin_panic_fmt::hd0daa02942245d81
   7:     0x7ff245e6b331 - rust_begin_unwind
   8:     0x7ff245ea5e7f - core::panicking::panic_fmt::hbfc935564d134c1b
   9:     0x7ff245ea5ef5 - core::option::expect_failed::h1d846c7a667396f7
  10:     0x7ff245daa722 - ruby_stacktrace::dwarf::obj::get_dwarf_entries::he47de19de2e538d4
  11:     0x7ff245d994f4 - ruby_stacktrace::main::h33adc6edaef38f5f
  12:     0x7ff245e73796 - __rust_maybe_catch_panic
  13:     0x7ff245e6a6d2 - std::rt::lang_start::h53bf99b0829cc03c
  14:     0x7ff24518caf4 - __libc_start_main
  15:     0x7ff245d93d28 - <unknown>
  16:                0x0 - <unknown>

Any ideas? Sorry I'm a rust noob, more of a Ruby person so not sure where to look! 😄

Automatically suggest reporting an issue for high numbers of dropped frames

This is a lazy suggestion having only read the README, so maybe this already happens.

README says:

A typical error message here is something like "Dropped 13/3700 stack traces because of errors". If you're seeing high error rates (more than 1/100 or so), please create an issue.

My "don't (just) document what you can automate" instincts make me wonder: Could it make sense for rbspy to detect high error rates and say something like "This error rate is quite high. Unless you expect it to be, please create an issue: https://github.com/rbspy/rbspy/issues/new"?

It probably makes sense to still mention it in the README since people who get lower error rates and see that message are probably helped by learning that a low rate is not abnormal. Hm, though depending on the current error message, maybe saying something to that effect could be helpful and save a trip to the README. "This amount of dropped stack traces is usually fine. Read more: …"

Keep up the great work!

Make rbspy on Mac use goblin instead of nm

Parsing the output of nm to get symbol addresses on Mac doesn't seem that robust (what if people don't have nm installed?).

The specific issue I ran into with goblin was that goblin didn't parse the symbols from the libruby dylib from rvm properly (it reported the symbol value for the ruby_version as 0 instead of the actual symbol value). Need to report this issue to goblin and ideally contribute a fix.

[mac] panicked at 'attempt to subtract with overflow'

I'm using rbspy at 6f2ca05! I was trying to profile jekyll build and I got a neat panic! It appears to be happening when it tries to get the line number in a sample.

thread 'main' panicked at 'attempt to subtract with overflow', src/ruby_version.rs:402:27

L402 is in this block (let mut pos = ...)!

rbspy/src/ruby_version.rs

Lines 395 to 424 in 6f2ca05

 macro_rules! get_lineno_2_5_0( 

 () => ( 

 fn get_lineno<T>( 

 iseq_struct: &rb_iseq_constant_body, 

 cfp: &rb_control_frame_t, 

 source: &T, 

 ) -> Result<u32, MemoryCopyError> where T: CopyAddress{ 

 let mut pos = cfp.pc as usize - iseq_struct.iseq_encoded as usize; 

 if pos != 0 { 

 pos -= 1; 

 } 

 let t_size = iseq_struct.insns_info_size as usize; 

 if t_size == 0 { 

 Ok(0) //TODO: really? 

 } else if t_size == 1 { 

 let table: [iseq_insn_info_entry; 1] = copy_struct(iseq_struct.insns_info as usize, source)?; 

 Ok(table[0].line_no as u32) 

 } else { 

 let table: Vec<iseq_insn_info_entry> = copy_vec(iseq_struct.insns_info as usize, t_size as usize, source)?; 

 for i in 0..t_size { 

 if pos == table[i].position as usize { 

 return Ok(table[i].line_no as u32) 

 } else if table[i].position as usize > pos { 

 return Ok(table[i-1].line_no as u32) 

 } 

 } 

 Ok(table[t_size-1].line_no as u32) 

 } 

 } 

 ));

Full stacktrace:

~/jekyll/jekyll/docs#related-posts-perf-improvements$ sudo --preserve-env env RUST_BACKTRACE=1 ~/code/rbspy/target/debug/rbspy record jekyll build
Password:
Dropping permissions: running Ruby command as user parkr
Recording data to /Users/parkr/.cache/rbspy/records/rbspy-2018-02-01-LHsUZJfleM.txt
Press Ctrl+C to stop
Configuration file: /Users/parkr/jekyll/jekyll/docs/_config.yml
            Source: /Users/parkr/jekyll/jekyll/docs
       Destination: /Users/parkr/jekyll/jekyll/docs/_site
 Incremental build: disabled. Enable with --incremental
      Generating...
Behind expected sample time by 2338500 nanoseconds, results may be inaccurate. Try sampling at a lower rate with `--rate`. Current rate: 100.
Behind expected sample time by 306174 nanoseconds, results may be inaccurate. Try sampling at a lower rate with `--rate`. Current rate: 100.
Behind expected sample time by 14352733 nanoseconds, results may be inaccurate. Try sampling at a lower rate with `--rate`. Current rate: 100.
Behind expected sample time by 7328258 nanoseconds, results may be inaccurate. Try sampling at a lower rate with `--rate`. Current rate: 100.
Behind expected sample time by 444778 nanoseconds, results may be inaccurate. Try sampling at a lower rate with `--rate`. Current rate: 100.
thread 'main' panicked at 'attempt to subtract with overflow', src/ruby_version.rs:402:27
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:68
   2: std::panicking::default_hook::{{closure}}
             at src/libstd/sys_common/backtrace.rs:57
             at src/libstd/panicking.rs:381
   3: std::panicking::default_hook
             at src/libstd/panicking.rs:397
   4: std::panicking::begin_panic
             at src/libstd/panicking.rs:577
   5: std::panicking::begin_panic
             at src/libstd/panicking.rs:538
   6: std::panicking::try::do_call
             at src/libstd/panicking.rs:522
   7: std::panicking::try::do_call
             at src/libstd/panicking.rs:498
   8: <core::ops::range::Range<Idx> as core::fmt::Debug>::fmt
             at src/libcore/panicking.rs:71
   9: <core::ops::range::Range<Idx> as core::fmt::Debug>::fmt
             at src/libcore/panicking.rs:51
  10: rbspy::ruby_version::ruby_2_5_0_rc1::get_lineno
             at src/ruby_version.rs:402
  11: rbspy::ruby_version::ruby_2_5_0_rc1::get_stack_frame
             at src/ruby_version.rs:473
  12: rbspy::ruby_version::ruby_2_5_0_rc1::get_stack_trace
             at src/ruby_version.rs:137
  13: core::ops::function::Fn::call
             at /Users/travis/build/rust-lang/rust/src/libcore/ops/function.rs:73
  14: rbspy::initialize::StackTraceGetter::get_trace
             at src/initialize.rs:94
  15: rbspy::record
             at src/main.rs:282
  16: rbspy::do_main
             at src/main.rs:143
  17: rbspy::main
             at src/main.rs:174
  18: panic_unwind::dwarf::eh::read_encoded_pointer
             at src/libpanic_unwind/lib.rs:101
  19: rust_panic
             at src/libstd/panicking.rs:459
             at src/libstd/panic.rs:365
             at src/libstd/rt.rs:58
  20: rbspy::OutputFormat::variants
~/jekyll/jekyll/docs#related-posts-perf-improvements$                     done in 9.149 seconds.
 Auto-regeneration: disabled. Use --watch to enable.

"rbspy -V" does not show version

Hello there!

I tried rbspy-v0.2.3-x86_64-apple-darwin.tar.gz and just wanted to verify the version. Apparently the version is not printed on screen:

09:02 $ rbspy --version
rbspy 
✔ ~/Downloads 
09:02 $ sudo rbspy --version
Password:
rbspy 
✔ ~/Downloads 
09:03 $ sudo rbspy -V
rbspy

[mac-support] cargo test hangs

Thanks for your great work on rbspy, first!

I tried out the mac-support branch tonight (#69). cargo build went fine, but cargo test seems to hang here:

If I move the mouse over the terminal window, I'll see the Mac OS spinner (see link).

If I open Activity Monitor, something very unusual appears: the monitor shows no process at all, and no system statistics anymore.

There is no trivial way to close the window (I cannot open a new terminal etc), so I'll just reboot my machine 😄

Just wanted to report back with this (I will make further tests).

Switch from elf to goblin

The elf crate hasn't been updated in over a year. Goblin is much more actively developed. A few relevant pros over elf:

zero-copy
supports the executable fromats of macos (mach-o) and windows (pe32/64) which rbpsy will need down the line
has labyrinth goblins on its readme page.

`Summary of profiling data so far:` could say how long the program has been running for

This would give me a quick sense of how long I've been waiting, since all of the programs output is continually overwritten

thread 'main' panicked at 'called `Option::unwrap()` on a `None` value'

Command attempted: ./ruby-stacktrace top

Included version of rustc, cargo (build from source) and backtrace.

rustc 1.12.0 (3191fbae9 2016-09-23)
cargo 0.13.0-nightly (109cb7c 2016-08-19)

thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', ../src/libcore/option.rs:326
stack backtrace:
   1:     0x55cb87f26b79 - std::sys::backtrace::tracing::imp::write::h00e948915d1e4c72
   2:     0x55cb87f2bd5c - std::panicking::default_hook::_{{closure}}::h7b8a142818383fb8
   3:     0x55cb87f2b009 - std::panicking::default_hook::h41cf296f654245d7
   4:     0x55cb87f2b698 - std::panicking::rust_panic_with_hook::h4cbd7ca63ce1aee9
   5:     0x55cb87f2b4f2 - std::panicking::begin_panic::h93672d0313d5e8e9
   6:     0x55cb87f2b460 - std::panicking::begin_panic_fmt::hd0daa02942245d81
   7:     0x55cb87f2b3e1 - rust_begin_unwind
   8:     0x55cb87f65f2f - core::panicking::panic_fmt::hbfc935564d134c1b
   9:     0x55cb87f65e5b - core::panicking::panic::hcee64434f097e399
  10:     0x55cb87c5fa36 - _<core..option..Option<T>>::unwrap::h232dd9aa8175ac1c
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libcore/option.rs:21
  11:     0x55cb87cb65c2 - ruby_stacktrace::get_types::hcd5718c83894e544
                        at /home/sp00k/dev/ruby-stacktrace/src/lib.rs:435
  12:     0x55cb87c3d0d3 - ruby_stacktrace::main::h5a0cd1e21f1b71c5
                        at /home/sp00k/dev/ruby-stacktrace/src/bin/ruby-stacktrace.rs:54
  13:     0x55cb87f33846 - __rust_maybe_catch_panic
  14:     0x55cb87f2a782 - std::rt::lang_start::h53bf99b0829cc03c
  15:     0x55cb87c3dc33 - main
  16:     0x7fd2d25d8f44 - __libc_start_main
  17:     0x55cb87c1d1d8 - <unknown>
  18:                0x0 - <unknown>

Stumbling block on good first issue

I figured I'd try my hand on #128 .

I used https://www.rustup.rs to make sure I had the correct version of rust / cargo and tried to run cargo test to make sure things were working properly.

I got 477 errors of the type:

error: unions are unstable and possibly buggy (see issue #32836)
    --> ruby-structs/src/ruby_2_5_0_rc1.rs:3641:1
     |
3641 |   pub union rb_iseq_struct__bindgen_ty_1 {
     |  _^ starting here...
3642 | |     pub compile_data: *mut iseq_compile_data,
3643 | |     pub loader: rb_iseq_struct__bindgen_ty_1__bindgen_ty_1,
3644 | |     pub trace_events: rb_event_flag_t,
3645 | |     _bindgen_union_align: [u64; 2usize],
3646 | | }
     | |_^ ...ending here

This refers me to this rust issue. And this is where I'm too far out of my depth to keep going.

I could obviously be doing something wrong but I figured I'd flag it here as first issues especially are likely to run aground on this sort of thing.

Feature request: trace_viewer output format

It would be super neat if rbspy could write out either ftrace or Chrome trace_event format files, since those can be read both by catapult/tracing and by the Chrome devtools tracing tab!

It's kind of like the fancy interactive flamegraphs produced by the flamegraph gem, but with a UI that seems more performant for huge numbers of datapoints.

	macro_rules! get_lineno_2_5_0(
	() => (
	fn get_lineno<T>(
	iseq_struct: &rb_iseq_constant_body,
	cfp: &rb_control_frame_t,
	source: &T,
	) -> Result<u32, MemoryCopyError> where T: CopyAddress{
	let mut pos = cfp.pc as usize - iseq_struct.iseq_encoded as usize;
	if pos != 0 {
	pos -= 1;
	}
	let t_size = iseq_struct.insns_info_size as usize;
	if t_size == 0 {
	Ok(0) //TODO: really?
	} else if t_size == 1 {
	let table: [iseq_insn_info_entry; 1] = copy_struct(iseq_struct.insns_info as usize, source)?;
	Ok(table[0].line_no as u32)
	} else {
	let table: Vec<iseq_insn_info_entry> = copy_vec(iseq_struct.insns_info as usize, t_size as usize, source)?;
	for i in 0..t_size {
	if pos == table[i].position as usize {
	return Ok(table[i].line_no as u32)
	} else if table[i].position as usize > pos {
	return Ok(table[i-1].line_no as u32)
	}
	}
	Ok(table[t_size-1].line_no as u32)
	}
	}
	));