[ruby-core:17973] Proposal of GC::Profiler

[Narihiro Nakamura]

Hi.

make profiler for GC.

== usage
GC::Profiler.enable

:
:
:
# gc is invoked several times

GC::Profiler.report

---------- out -------------
GC 10 invokes.
Index Invoke Time(sec) Use Size(byte) Total Size(byte) Total Object GC time(ms)
1 0.016 338420 360448 18018 0.40000000000000007772
2 0.024 605640 622592 31122 0.00000000000000008843
3 0.040 1080320 1097728 54873 0.00000000000000022972
4 0.060 1931460 1949696 97461 0.40010000000000034426
5 0.100 3470040 3489792 174447 0.79999999999999971134
6 0.168 6236240 6258688 312858 1.20009999999999994458

2008303 used objects 52 free objects and 2008355 total objects in Heap.
Index Count % Kind (class)
1 1500000 74.68799092 Child
2 500000 24.89599697 Parent
3 5986 0.29805488 Object
4 1648 0.08205721 String
5 417 0.02076326 Class
6 81 0.00403315 Encoding
8 48 0.00239002 RubyVM::InstructionSequence
9 23 0.00114522 Float
10 20 0.00099584 Module
11 17 0.00084646 Array
12 16 0.00079667 Hash
13 10 0.00049792 Regexp
14 9 0.00044813 Enumerable
15 5 0.00024896 Comparable
16 3 0.00014938 IO
17 3 0.00014938 Precision
18 2 0.00009958 Bignum
19 1 0.00004979 RubyVM::Env
20 1 0.00004979 RubyVM
21 1 0.00004979 Complex
22 1 0.00004979 NoMemoryError
23 1 0.00004979 Binding
24 1 0.00004979 SystemStackError
25 1 0.00004979 ThreadGroup
26 1 0.00004979 Thread
27 1 0.00004979 File::Constants
28 1 0.00004979 ARGF.class
29 1 0.00004979 Mutex
30 1 0.00004979 Data
31 1 0.00004979 fatal
32 1 0.00004979 Kernel
33 1 0.00004979 Gem::QuickLoader
----------------------------

== use module and method introduce
* GC::Profiler
for Profiler

* GC::Profiler.enable?
returns current status of GC profile mode.

* GC::Profiler.enable
updates GC profile mode.
start profiler for GC.

* GC::Profiler.disable
stop profiler.

* GC::Profiler.clear
clear before profile data.

* GC::Profiler.report
Please quote the above-mentioned.

* GC::Profiler.format
return string of GC::Profiler.report

* GC::Profiler.data
Report profile data to wrap hash.
It returns a hash as :
[{:GC_TIME => 0.001, :HEAP_USE_SIZE => 342840,
:HEAP_TOTAL_SIZE=>360360}, ... ]

* ObjectSpace.count_classes
Counts classes for each type.
It returns a hash as :
{:TOTAL=>10000, :FREE=>3011, :String=>6, :Array=>404, ...}

== merit
1. find memory leak
Now, not get detail info in heap.
ObjectSpace.count_classes, will be help to find memory leak.

2. Performance tuning
This provide simple way to get detail data of gc, and get heap
size change data by gc.
This will be help to performance tuning.

== patch
patch file append to mail.

== Please tell me idea for this
For example, more good method name, want more output data,
and this propose is bad idea... etc

thanks.

nari

--
Narihiro Nakamura <autho...@gmail.com>

[M. Edward (Ed) Borasky]

Excellent idea!! Now, can all the other implementers build something
like this? ;)
--
M. Edward (Ed) Borasky
ruby-perspectives.blogspot.com

"A mathematician is a machine for turning coffee into theorems." --
Alfréd Rényi via Paul Erdős

[Daniel Luz]

Good idea. My only immediate suggestion is...

> * GC::Profiler.enable?
I think "enabled?" would be more appropriate.

On Fri, Jul 25, 2008 at 12:22 PM, M. Edward (Ed) Borasky <zn...@cesmail.net> wrote:

Excellent idea!! Now, can all the other implementers build something
like this? ;)

Any implementation which writes its own garbage collector should, in principle, be able to offer the same feature. Not sure about the others (JRuby, IronRuby and MacRuby come to mind), though. But IMO this is not enough of a reason to give up the GC profiler: no production software would really miss it, and it's not like people using one of those platforms don't have other (possibly better) choices for profiling and debugging tools.

[Laurent Sansonetti]

It will be trivial to implement this in MacRuby, and I think it's
quite useful to allow the developer to retrieve this kind of
information. Currently we can achieve the same goal using DTrace,
which can be activated on any running script, at the contrary of this
solution which requires to call GC::Profiler.enable. But still, this
is a neat idea, I think.

Laurent

[M. Edward (Ed) Borasky]

On Sat, 2008-07-26 at 13:17 +0900, Laurent Sansonetti wrote:
> It will be trivial to implement this in MacRuby, and I think it's
> quite useful to allow the developer to retrieve this kind of
> information. Currently we can achieve the same goal using DTrace,
> which can be activated on any running script, at the contrary of this
> solution which requires to call GC::Profiler.enable. But still, this
> is a neat idea, I think.

Well ... in the absence of a DTrace port to Windows and Linux, yes.
Since you *do* have DTrace, perhaps the energy to do this on MacOS
wouldn't be well spent.

I'm told by the SystemTap folks that it can be made to do this, and
"oprofile" can certainly tell you in great detail (plus or minus a
couple of lines of assembly code) exactly where you're spending your
time. I'm planning on digging into SystemTap next month.

[Narihiro Nakamura]

Thank you for the many opinion.

>> * GC::Profiler.enable?
>I think "enabled?" would be more appropriate.

That's good name :)
I updated patch file.("enable?" to "enabled?")

DTrace and SystemTap seems to be good.
but GC::Profiler is specialize in RubyGC, I think.

I will commit this patch if permitted to Matsumoto-san.
# I'm commiter.

[Sylvain Joyeux]

For the sake of the integration of development tools, would it not be better to
actually provide a fully programmatic interface and *then* adapt the normal
Profiler to handle it ? What I have in mind is the following:

* add some events that can be caught through the normal event interface, like
RAN_GC, NEW_OBJECT
* add a few rb_gc methods:
* get the cound of objects per classes like below
* get the structure of the heaps
* get the total count of objects

I think that would always be a better approach because external tools would be
able to do memory profiling, and we would be able to use good visualization
tools (like kcachegrind as supported by the ruby-prof gem)

Best regards,
Sylvain

[authorNari]

Hi

2008/7/27 Sylvain Joyeux <sylvain...@m4x.org>:

"GC::Profiler.data" is can present enough data for make external tool, I think.
And, costs might be lower than "add event".

thanks

---
nari

[Narihiro Nakamura]

Hi.

GC::Profiler committed to trunk.

==usage
GC::Profiler.enable

:
:
:
# gc invoked several times

GC::Profiler.report

---------- out -------------
GC 10 invokes.
Index Invoke Time(sec) Use Size(byte) Total Size(byte)
Total Object GC time(ms)
1 0.016 338420 360448
18018 0.40000000000000007772
2 0.024 605640 622592
31122 0.00000000000000008843
3 0.040 1080320 1097728
54873 0.00000000000000022972
4 0.060 1931460 1949696
97461 0.40010000000000034426
5 0.100 3470040 3489792
174447 0.79999999999999971134
6 0.168 6236240 6258688
312858 1.20009999999999994458

== use module and method introduce
* GC::Profiler
for Profiler

* GC::Profiler.enabled?

returns current status of GC profile mode.

* GC::Profiler.enable
updates GC profile mode.
start profiler for GC.

* GC::Profiler.disable
stop profiler.

* GC::Profiler.clear
clear before profile data.

* GC::Profiler.report
Please quote the above-mentioned.

* GC::Profiler.result

return string of GC::Profiler.report

thanks.

---
Narihiro Nakamura

[Charles Oliver Nutter]

M. Edward (Ed) Borasky wrote:
> Excellent idea!! Now, can all the other implementers build something
> like this? ;)

JRuby already has a full complement of memory profiling tools built in,
since the JVM provides them.

➔ jruby -J-verbose:gc -e "while true; x = 'foo' + 'bar'; end"
[GC 896K->349K(5056K), 0.0094240 secs]
[GC 1245K->939K(5056K), 0.0182340 secs]
[GC 1835K->1043K(5056K), 0.0063530 secs]
[GC 1939K->1043K(5056K), 0.0013650 secs]
[GC 1939K->1043K(5056K), 0.0015050 secs]
[GC 1939K->1043K(5056K), 0.0003080 secs]
[GC 1939K->1043K(5056K), 0.0003060 secs]
^C

➔ jruby -J-Xrunhprof -e "while true; x = 'foo' + 'bar'; end"
^CDumping Java heap ... allocation sites ... done.
➔ cat java.hprof.txt
... (extensive information on live objects and allocation sites elided)
SITES BEGIN (ordered by live bytes) Wed Aug 13 21:28:10 2008
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 10.90% 10.90% 301920 6290 24071232 501484 307629
org.jruby.RubyString
2 7.18% 18.08% 198776 4120 198776 4120 300000 char[]
3 5.45% 23.54% 151056 3147 12035616 250742 307639
org.jruby.RubyString
4 3.64% 27.17% 100736 3148 8023712 250741 307640
org.jruby.util.ByteList
5 3.53% 30.70% 97760 4056 97760 4056 300000 java.lang.String
6 2.73% 33.43% 75552 3148 6017784 250741 307641 byte[]
7 1.30% 34.74% 36104 1 36104 1 306428 short[]
8 1.30% 36.04% 36104 1 36104 1 306423 short[]
9 1.07% 37.11% 29568 1232 33096 1379 302194
java.util.concurrent.ConcurrentHashMap$HashEntry
10 1.00% 38.11% 27632 79 27632 79 300000 byte[]

And there are many others, including heap image-browsing tools, memory
leak detectors, and so on. Hopefully any GC-related APIs added to Ruby
would not depend on specific details of the C implementation, so we
could simply wrap what's already available. I would venture a guess
there are more GC and memory-profiling tools available for the JVM than
just about any other runtime (not that they're all good, but you get the
idea).

- Charlie