Memory / Allocations profiling NaN in 1.9.3 #86

Closed
zbskii opened this Issue Sep 11, 2012 · 30 comments

Comments

Projects
None yet

zbskii commented Sep 11, 2012

Running some test code like:
https://gist.github.com/3699880

Returns a profile:

Thread ID: 15769580
Total: 0.000000
Sort by: self_time

 %self     total     self     wait    child    calls   name
   NaN      0.00     0.00     0.00     0.00  1000000   Array#initialize 
   NaN      0.00     0.00     0.00     0.00  1000000   <Class::Array>#allocate 
   NaN      0.00     0.00     0.00     0.00  1000000   Class#new 
   NaN      0.00     0.00     0.00     0.00        1   Integer#times 
   NaN      0.00     0.00     0.00     0.00        1   Global#[No method] 

zbskii commented Sep 11, 2012

I should also point out this is with 1.9.3 installed from RVM with the railsexpress patches. It appears instrumented correctly:

1.9.3-p194 :002 > ObjectSpace.live_objects
 => 69324 
1.9.3-p194 :003 > ObjectSpace.allocated_objects
 => 129608 
Owner

rdp commented Sep 28, 2012

I'm able to reproduce it.

On Tue, Sep 11, 2012 at 11:12 AM, zbskii notifications@github.com wrote:

I should also point out this is with 1.9.3 installed from RVM with the
railsexpress patches. It appears instrumented correctly:

1.9.3-p194 :002 > ObjectSpace.live_objects
=> 69324
1.9.3-p194 :003 > ObjectSpace.allocated_objects
=> 129608


Reply to this email directly or view it on GitHubhttps://github.com/rdp/ruby-prof/issues/86#issuecomment-8465181.

I am seeing this problem as well..

I am too

mfojtik commented Oct 17, 2012

+1 would be nice to have this workin

mcorner commented Oct 19, 2012

Somewhat different output in 1.9.2, but seems like the same bug. Using the gcdata patch. This was on the current master. On rubyprof 0.11.0 I was not seeing this, but instead when I ran memory profiling, I got CPU time results.

+1 on a fix for this, I could really use it on something I am working on.

I wonder if it has anything to do with CALC_EXACT_MALLOC_SIZE being disabled (http://www.ruby-forum.com/topic/3124687). My C is not that great so I may be reading the extensions wrong.

+1, seems there is no way to profile memory on ruby 1.9

Owner

skaes commented Nov 14, 2012

Standard ruby does not ship with memory profiling support usable by ruby-prof. If you want to profile memory, you can use my patches, which provide all the methods ruby-prof needs.

See https://github.com/skaes/rvm-patchsets

The rvm team merges my patches regularly.

I just had success using ruby 1.9.3-p194 with the railsexpress patches.
Thanks @skaes!

mcorner commented Nov 14, 2012

Hrm, perhaps I am missing something as I couldn't get this to work. At least it doesn't look like a memory profile to me, it looks like a CPU profil. I am on mountain lion OSX.

Installed 1.9.3-p194 with railsexpress:
rvm reinstall 1.9.3-p194 --patch railsexpress -n railsexpress
rvm use ruby-1.9.3-p194-railsexpress

mem-test.rb:

require 'ruby-prof'

RubyProf.measure_mode = RubyProf::MEMORY
RubyProf.start
a=[]
1000.times{ a << rand }
result = RubyProf.stop

printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

Output:
Thread ID: 70336020437640
Total: 2.925781
Sort by: self_time

%self total self wait child calls name
37.25 2.93 1.09 0.00 1.84 1 Global#[No method]
19.49 0.99 0.57 0.00 0.42 1 Integer#times
14.42 0.42 0.42 0.00 0.00 1000 Kernel#rand
14.42 0.42 0.42 0.00 0.00 1 Kernel#respond_to?
14.42 0.42 0.42 0.00 0.00 1 Module::GC#disable_stats

  • indicates recursively called methods

@mcorner seems like i was wrong, because i run your test and have same results.
@skaes, what do you think?

Owner

skaes commented Nov 15, 2012

ruby-prof has undergone a lot of changes since I made my last contribution. So I can't fully answer your question. I usually measure allocations, not memory.

Alas, I currently don't have time to look into this, as we're in the middle of a large project with a tight deadline.

Christmas, maybe.

@skaes

1.9.3p397 missing several RUBY_FUNC_EXPORTED on:

rb_gc_disable_stats
rb_os_allocated_objects
rb_gc_collections
rb_gc_time

, compare https://github.com/skaes/rvm-patchsets/blob/master/patches/ruby/1.9.3/p125/railsexpress/06-export-some-symbols-for-rubyprof.patch vs. https://github.com/skaes/rvm-patchsets/blob/master/patches/ruby/1.9.3/p327/railsexpress/07-export-a-few-more-symbols-for-ruby-prof.patch

@everyone if don't want to wait on official patch simply update gc.c and rebuild ruby, correct functions declarations are:

RUBY_FUNC_EXPORTED
VALUE
rb_gc_disable_stats()

RUBY_FUNC_EXPORTED
unsigned LONG_LONG rb_os_allocated_objects()

RUBY_FUNC_EXPORTED
VALUE
rb_gc_collections()

RUBY_FUNC_EXPORTED
VALUE
rb_gc_time()

, Tested with ruby-prof 0.11.2

I had this same problem. After applying the railsexpress patch from @skaes, I had to reinstall the ruby-prof gem to get allocations and memory profiling to work (just gem install ruby-prof). It's working for me now on 1.9.3-p194, or at least not printing out NaN.

Owner

cfis commented Jan 19, 2013

Ok, can we consider this issue resolved?

no. 1.9.3-p194 patches are good. 1.9.3p397 are NOT completed.

Owner

skaes commented Feb 3, 2013

The 1.9.3-p374 patches now export all relevant symbols.

Can you please test and see whether there's still a problem?

1.9.3-p374 with railsexpress not working for me on Mac OS X 10.7.5

$ rvm list

rvm rubies

=> ruby-1.9.3-p374-railsexpress [ x86_64 ]
 * ruby-1.9.3-p385 [ x86_64 ]
$ ruby-prof --mode=memory test.rb
dyld: lazy symbol binding failed: Symbol not found: _rb_gc_allocated_size
  Referenced from: /Users/alexanderhanhikoski/.rvm/gems/ruby-1.9.3-p374-railsexpress/gems/ruby-prof-0.12.2/lib/ruby_prof.bundle
  Expected in: flat namespace

dyld: Symbol not found: _rb_gc_allocated_size
  Referenced from: /Users/alexanderhanhikoski/.rvm/gems/ruby-1.9.3-p374-railsexpress/gems/ruby-prof-0.12.2/lib/ruby_prof.bundle
  Expected in: flat namespace

Trace/BPT trap: 5
Owner

skaes commented Feb 23, 2013

rb_gc_allocated_size is definitely exported:

https://github.com/wayneeseguin/rvm/blob/master/patches/ruby/1.9.3/p374/railsexpress/07-export-a-few-more-symbols-for-ruby-prof.patch#L57

You need to make sure to recompile both ruby and ruby_prof.

This should fix it.

@skaes I just did gem uninstall ruby-prof && gem install ruby-prof and get the same result. Should ruby_prof be installed using different method?

Owner

rdp commented Feb 23, 2013

@alexhanh did you recompile ruby as well?

Owner

skaes commented Mar 10, 2013

Please update to the latest 1.9.3 (pl392) and the latest ruby-prof (0.13.0).

It all works for me.

Therefor I close the issue.

skaes closed this Mar 10, 2013

jingz referenced this issue in randym/axlsx Aug 14, 2013

Closed

Memory usage of to_xml_string #222

Chrisell commented Sep 5, 2013

Getting this NaN% result still while trying to run the Memory profiler. Ruby 1.9.3p392 w/ ruby-prof 0.13.0. Does the ruby interpreter sill need to be patched for this to work properlly?

fmnoise commented Nov 22, 2015

Still having this issue with ruby 2.1.2 and ruby-prof 0.14.2

Issues with Ruby 2.3.0

Same issue ruby-prof (0.16.2) on ruby 2.2.3

Owner

rdp commented Sep 7, 2016

2.3.1?

alexbel commented Nov 22, 2016

@rdp yes. ruby 2.3.1p112

fernandobrito commented Dec 28, 2016 edited

For me running the test code by the original poster works fine with 2.3.3 installed using rvm install 2.3.3-railsexpress --patch railsexpress and with ruby-prof 0.16.2.

However, when running on my Ruby on Rails project (4.2.7.1), I get NaN and 0's, just like the original poster. I will try with an empty project.

Update: for the test code, ALLOCATIONS and MEMORY works fine. On my existing Rails project, ALLOCATIONS works fine, but not MEMORY. WALL_TIME works fine on both.

Update2: Using RubyProf.start and RubyProf.stop with MEMORY works fine inside Rails. I guess issue seems to be related with rack middleware?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment