Adding Yourkit-style printer

[goo...@schmeisky.com]

Hi,

we from www.plat-forms.org want to use ruby-prof as a profiling tool. plat_forms is a web development platforms contest and we have several ruby on rails solutions, where we want use ruby-prof to analyze the methods called after a request is sent.

We also have Java and C# solutions, and for the profiling there we use yourkit (http://www.yourkit.com). To make the results comparable I want to write a printer that prints data like in the yourkit report. The report looks like this:

Name, Total time, Avg. Time, Own Time, Invocation Count, Level

A line corresponds to a place in the code where a method is called. If a method is called repeatedly from the same place, Invocation count increases, if it is called from another place, a new line is used.

I was planning to write a new printer, that would print out a line for each call_info of a method, similar to flat_printer just with call_info instead of the method. Is this a viable approach or do I get something completely different? I am new to ruby-prof, so it would be very helpful if somebody more familiar with ruby-prof could give some advice :-)

Regards,
Holger

[rogerdpack]

So you want tree structure but just for number of times it was called, not timing info?

It appears there is a .called method in there...

https://github.com/ruby-prof/ruby-prof/blob/master/lib/ruby-prof/printers/flat_printer.rb

[goo...@schmeisky.com]

Hi,

thanks for the quick answer!

I sort of want to have the same number of lines as in the tree structure (one entry each time the method is called from a place in the code), not the sum of all calls like in flat-printer.
But then I want the whole as a CSV file, because we'll later turn it into graphs (but that is no problem to make).

method_info.rb has a .called method, but it just sums up the call_info.rb .called numbers. So if I print out each call_info along with .called and .depth, do I get one line for each method call? Instead of the sum of all calls, like in method_info.called.

Regards,
Holger Schmeisky

[goo...@schmeisky.com]

Hi,

like in the call_info_printer.rb I used the CallInfoVisitor to get at the call_infos of a thread in call order (see attachment yourkit_csv_printer.rb). Running it on a small sample program (see attachment test_yourkitcsv.rb) this seems to give me the results I need. func1 appears two times in the report because it is called from 2 different places. One time it is called 2 times in a row and that is reported with Invocation Count = 2.

Name, Time (ms),Avg. Time (ms),Own Time (ms),Invocation Count, Level
YourkitCSVPrinterTest#test_csv_output_conformance, 150, 150, 0, 1, 1
YourkitCSVTestClass#func3, 150, 150, 0, 1, 2
YourkitCSVTestClass#func1, 43, 43, 0, 1, 3
Integer#times, 43, 43, 28, 1, 4
Kernel#rand, 15, 0, 15, 10000, 5
YourkitCSVTestClass#func2, 107, 107, 0, 1, 3
YourkitCSVTestClass#func1, 86, 43, 0, 2, 4
Integer#times, 86, 43, 57, 2, 5
Kernel#rand, 29, 0, 29, 20000, 6
Integer#times, 22, 22, 14, 1, 4
Kernel#rand, 7, 0, 7, 5000, 5
Class#new, 0, 0, 0, 1, 2
Object#initialize, 0, 0, 0, 1, 3
<Class::Object>#allocate, 0, 0, 0, 1, 3
#<StringIO:0xb7627ea8>

Does there appear to be a problem with this approach?
If no, can I submit a pull request for this printer+test? Maybe somebody else wants to do the same comparison :-)

On Wednesday, July 17, 2013 11:10:26 PM UTC+2, rogerdpack wrote:

[rogerdpack]

Oh ok so you basically want "the sum of all times each method was called, from anywhere"

I believe what you have said would work (I'll leave it up to you to double check it though, seems to make sense), feel free to submit a pull request :)

-r

On Wednesday, July 17, 2013 2:00:30 PM UTC-6, goo...@schmeisky.com wrote:

[goo...@schmeisky.com]

Hi,

there is a problem though, the call tree should be:

func3
  func2
    func1
  func1

and they are executed that way, but they appear in the order

func3
  func1
  func2
    func1

I think this is because method_info.children returns the call_infos in the wrong order. Is there any way to get the call_infos in the actual order they were called?

Regards,
Holger

[goo...@schmeisky.com]

Hi,

Yes, that's what I need :-)
A problem I discovered is that the call_info.children does not seem to be in the order that child methods are called:

func1()
  afunc5()
  func4()

yields

func1
afunc4
afunc5

in the report, because the call_info.children of func1 is [ func4, afunc5 ]. Where in the code is the order of the call_info.children determined? I guess it is somewhere in the /ext? Is there a way to get the children in the order they were called?

On Thursday, July 18, 2013 4:40:53 PM UTC+2, rogerdpack wrote:

[Roger Pack]

Appears that today they're stored in a hash, which may be unordered...you could order them by count or alphabetical would that be sufficient?

--
 
---
You received this message because you are subscribed to the Google Groups "ruby optimization" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ruby-optimizat...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[goo...@schmeisky.com]

Hi,

unfortunately yourkit outputs calls in the order they are called, so it would be better for comparability. Would it be difficult to add an ordering? Do you know where in /ext the call_infos are added to children? (I am not experienced with C extensions)

[goo...@schmeisky.com]

Hi,

unfortunately I need them in the order they were called, because that is what YourKit does. Would it make sense to change the data type of children into an array, so that it keeps the order?
If I do a grep on the codebase, I can not find a place where the fact that children is used as a hash (just .each, .select, .grep, .inject and so on). However, I can not find out where I could change .children from hash to array.

Regards,
Holger

On Tuesday, July 23, 2013 4:07:21 PM UTC+2, rogerdpack wrote:

[rogerdpack]

If it's a ruby class and you're using 1.9.x+ then I would have anticipated it to retain order, I wonder why it's not...
Regardless, given today's use of hash I don't think it would give you a new line if a method is called twice from 'within the same method' but in different locations...@cfis any observations here?

On Wednesday, July 17, 2013 2:00:30 PM UTC-6, goo...@schmeisky.com wrote:

[goo...@schmeisky.com]

Hi,

I just checked and my machine has ruby 1.8.7 installed, so that might be the fix :-)

You are right, calling the same method twice from within the same method (with other stuff in between) results only in one line. How difficult would it be to distinguish these?

Regards,
Holger

[Roger Pack]

There was a printer that noted locations I could check it to see if it's related...

--

[Holger Schmeisky]

Hi,

to correctly implement this, the call_info.children and call_info.parent would have to point not just to a call-info, but also to a line number right? So that call_info.children would look like:

{ [methodA, 12] => call_info..., [methodA, 16] => call_info ...}

Do you see major problems changing call_info this way?

Regards,
Holger