From: "Eregon (Benoit Daloze)" Date: 2012-10-22T00:05:54+09:00 Subject: [ruby-core:48139] [ruby-trunk - Bug #6865] GC::Profiler.report might create a huge String and invoke a few GC cycles Issue #6865 has been updated by Eregon (Benoit Daloze). File 0001-gc.c-gc_profile_result-use-internal-structures-to-av.patch added 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 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? ---------------------------------------- Bug #6865: GC::Profiler.report might create a huge String and invoke a few GC cycles https://bugs.ruby-lang.org/issues/6865#change-31140 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/