Project

General

Profile

Actions

Bug #6865

closed

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

Added by Eregon (Benoit Daloze) over 11 years ago. Updated over 11 years ago.

Status:
Closed
Target version:
-
ruby -v:
ruby 2.0.0dev (2012-08-10 trunk 36676) [x86_64-darwin10.8.0]
Backport:
[ruby-core:47163]

Description

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.


Files

Updated by authorNari (Narihiro Nakamura) over 11 years ago

  • Assignee set to authorNari (Narihiro Nakamura)

Updated by Eregon (Benoit Daloze) over 11 years ago

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?

Updated by authorNari (Narihiro Nakamura) over 11 years ago

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!

Updated by headius (Charles Nutter) over 11 years ago

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.

Updated by Eregon (Benoit Daloze) over 11 years ago

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!

Updated by authorNari (Narihiro Nakamura) over 11 years ago

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

Updated by authorNari (Narihiro Nakamura) over 11 years ago

  • Status changed from Open to Closed

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

Updated by Eregon (Benoit Daloze) over 11 years ago

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.

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0Like0