Bug #6865: GC::Profiler.report might create a huge String and invoke a few GC cycles

• Status: Closed
• Assignee: authorNari (Narihiro Nakamura)
• Target version: -
• ruby -v: ruby 2.0.0dev (2012-08-10 trunk 36676) [x86_64-darwin10.8.0]

[Eregon (Benoit Daloze)]

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.

[authorNari (Narihiro Nakamura)]

• Assignee set to authorNari (Narihiro Nakamura)

[Eregon (Benoit Daloze)]

• File 0001-gc.c-gc_profile_result-use-internal-structures-to-av.patch 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?

[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!

[headius (Charles Nutter)]

Maybe interesting is JRuby's implementation of GC::Profiler, which just uses Ruby code to drive existing JVM GC reporting APIs.

https://github.com/jruby/jruby/blob/post17/src/jruby/kernel19/gc.rb

The most recent commit adds streaming of the result in the way nari describes above.

Ideally we'd have the same (or similar) API for this, so I'm willing to make changes.

[Eregon (Benoit Daloze)]

• File 0001-gc.c-gc_profile_result-gc_profile_report-use-interna.patch 0001-gc.c-gc_profile_result-gc_profile_report-use-interna.patch added

authorNari (Narihiro Nakamura) wrote:

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

Yes. I tried to have a common buffer for all lines, but I could not make it work as rb_io_write() (and others) end up copying the buffer with rb_new_str_frozen().

So I guess a good enough way is to use rb_sprintf().
I attach a patch with this idea.
I used the same approach for #result (using rb_sprintf()), do you think it's worth using rb_str_catf() directly instead? It would add some complexity and I'm thinking #report should be preferred to #result.

BTW, should unused fields in gc_profile_record not be defined when GC_PROFILE_MORE_DETAIL is false?

Thanks a lot!

Thanks for reviewing!

[authorNari (Narihiro Nakamura)]

Eregon (Benoit Daloze) wrote:

authorNari (Narihiro Nakamura) wrote:

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

Yes. I tried to have a common buffer for all lines, but I could not make it work as rb_io_write() (and others) end up copying the buffer with rb_new_str_frozen().

So I guess a good enough way is to use rb_sprintf().
I attach a patch with this idea.
I used the same approach for #result (using rb_sprintf()), do you think it's worth using rb_str_catf() directly instead? It would add some complexity and I'm thinking #report should be preferred to #result.

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

BTW, should unused fields in gc_profile_record not be defined when GC_PROFILE_MORE_DETAIL is false?

Oh, that's right. I'll fix it.

Thanks!!!

[authorNari (Narihiro Nakamura)]

• Status changed from Open to Closed

This issue was solved with changeset r37343 by Eregon.
Thank you.

[Eregon (Benoit Daloze)]

authorNari (Narihiro Nakamura) wrote:

This issue was solved with changeset r37343 by Eregon.
Thank you.

Oh, sorry, I forgot to mention the issue in the commit log.

I also meant to come back to this issue to thank you for the review and letting me commit it.