Issue #6865 has been updated by authorNari (Narihiro Nakamura).



Eregon (Benoit Daloze) wrote:
> Here is a patch.
> 
> It uses directly C structures, avoiding to allocate the Array of Hashes.
> The effect is easily seen: http://eregon.me/ruby/gc_profiler.png (y is GC time(ms), x is the Index, red is old, blue new, GC::Profiler.report is called after 10000 runs).
> 
> It still creates a huge String, and #report still is "io.write GC::Profiler.result".
> However, it does not allocate anything else (and should not affect GC much).
> 
> Another idea would be to create a buffer, use ruby_snprintf() or rb_str_catf() (and adapt the RString with rb_str_set_len()) for each line and append or write that to the String/io stream. This might also have the advantage of a progressive output for #report.
> 

I see. It is better for memory usage to progressively write the IO stream on #report.
Would you like to try it?

> I copy each gc_profile_record on the stack, is it fine or do you think referencing each member with objspace->profile.record[i].member is better? I guess the GC may run during rb_str_catf(), so it would be unsafe to just keep a pointer to objspace->profile.record[i]. Another way to deal with this would be to disable GC profiling during the loop, but this might ignore some runs, which is no good.
> 
> count, the number of records is saved at the beginning to avoid a possible infinite loop (if the GC would run at each iteration) but it will also not show GC runs due to the last gc_profile_result().
> 
> nari, what do you think?

This patch is OK for me. Could you commit it?

Thanks a lot!

----------------------------------------
Bug #6865: GC::Profiler.report might create a huge String and invoke a few GC cycles
https://bugs.ruby-lang.org/issues/6865#change-31157

Author: Eregon (Benoit Daloze)
Status: Open
Priority: Normal
Assignee: authorNari (Narihiro Nakamura)
Category: core
Target version: 
ruby -v: ruby 2.0.0dev (2012-08-10 trunk 36676) [x86_64-darwin10.8.0]


Hi,

In my use-case, GC::Profiler.report adds a few GC cycles to actually create the report, ending with these lines:

 9317              26.279               185760               701760                17544         0.33300000000124896360
 9318              26.282               185760               701760                17544         0.32800000000321460902
# start of GC::Profiler.report
 9319              26.285               393400               701760                17544         0.82300000000046225068
 9320              26.288               700480               718080                17952         1.43599999999821648089
 9321              26.294              1254800              1272960                31824         2.69300000000072259354
...
 9331              26.907             43836160             43917120              1097928        81.77799999999990632205

This is likely expected with GC::Profiler.result, but I think it could be partly avoided by printing line by line in GC::Profiler.report. Maybe gc_profile_result() could accepts a String or IO as an argument and call #<< or similar ?

I might have a try to solve this, but I'd be happy as well if someone solves it before me.
The GC::Profiler class documentation should probably be updated to use GC::Profiler.report if it proves to be more efficient.


-- 
http://bugs.ruby-lang.org/