jhawthorn / vernier

📏 next generation CRuby profiler
https://vernier.prof/
MIT License
826 stars 17 forks source link

Crash on latest version #92

Closed zenspider closed 1 month ago

zenspider commented 1 month ago

Just bumped to hopefully get fixes that allow me to look at the object allocations in #89 ... ironically, it now crashes on run and it seems to be a -1 index that is causing it:

10597 $ vernier run --allocation_sample_rate 100 --output profile.pos.json -- ./minitest_speed.rb 10000 pos class -q
starting profiler with interval 500
Run options: -q --seed 23987

# Running:

Finished in 0.037769s, 264767.4015 runs/s, 264767.4015 assertions/s.

10000 runs, 10000 assertions, 0 failures, 0 errors, 0 skips
/Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:232:in `convert': index out of range (RangeError)
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:232:in `block in initialize'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:231:in `map!'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:231:in `initialize'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:111:in `new'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:111:in `block in data'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:109:in `each'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:109:in `map'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:109:in `data'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/output/firefox.rb:94:in `output'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/result.rb:38:in `to_gecko'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/result.rb:43:in `write'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/autorun.rb:34:in `stop'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/autorun.rb:45:in `at_exit'
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/vernier-1.1.2/lib/vernier/autorun.rb:66:in `block in <top (required)>'
/Users/ryan/Desktop/fucking_horrible/xxx/gems/minitest-5.25.1/lib/minitest.rb:82:in `exit': exit (SystemExit)
    from /Users/ryan/Desktop/fucking_horrible/xxx/gems/minitest-5.25.1/lib/minitest.rb:82:in `block (2 levels) in autorun'

It looks like the samples starts with a -1 and that causes a crash. This simple fix lets it finish running but I have no idea if this leads to a valid set of data or if everything is thrown off.

          if allocations                                                                                        
            allocation_samples = allocations[:samples].reject { |n| n < 0 }                                     
            allocation_samples.map! do |sample|                                                                 
              @stack_table.convert(profile._stack_table, sample)                                                
            end                                                                                                 
zenspider commented 1 month ago

I'll send in a PR in a bit... still poking

jhawthorn commented 1 month ago

Taking a look...

It seems like this can be reproduced reliably by:

vernier run --allocation-sample-rate=1 -- ruby examples/minitest.rb

(my bet would be this is related to thread creation, which iirc has some weird quirks)

We can't replace -1 with 0 (0 is a valid 1-depth stack which we probably don't want), we might be able to reject -1 bit it would be better to avoid emitting it in the first place. Let me see what I can do.

jhawthorn commented 1 month ago

It's not thread creation but even earlier when trying to load the initial script (which profiling is enabled for since Vernier is loaded in a -r flag). #94 will skip over any -1 samples, in the future I hope to have a better solution.

jhawthorn commented 1 month ago

Thanks again! This should be fixed by #94 and in v1.2.1. Please let me know if it isn't 🙇‍♂