Getting over 100% in total

[betelgeuse]

With 0.2.0 on 2.1.0-rc1:

==================================
  Mode: wall(1000)
  Samples: 48603 (11.30% miss rate)
  GC: 7376 (15.18%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
     87486 (180.0%)           3   (0.0%)     RSpec::Core::ExampleGroup.run

[tmm1]

This is possible when a frame is in the stack more than once, i.e. recursion.

[mfpiccolo]

Thanks for this gem. Seems really useful but I am having trouble understanding the output. If you could explain what the numbers in each column mean I would be really appreciative. For instance, looking at the total column Typhoeus::Multi#perform looks troubling at 84% but from the sample it shows 1.2%.

What is the difference between these two columns?

Why when added up do both of these columns percentages not add up to 100%?

I would assume that each percentage means that that is the percentage of total time spent in each method but again they do not add up to 100% which is confusing.

From the output below is URI::Parser#split taking up most of my processing time or is it Typhoeus::Multi#perform?

Thanks again.

Mode: cpu(1000)
Samples: 1553862 (13.23% miss rate)
GC: 216647 (13.94%)

 TOTAL    (pct)     SAMPLES    (pct)     FRAME
464487  (29.9%)      443080  (28.5%)     URI::Parser#split
135216   (8.7%)       74826   (4.8%)     ActiveSupport::JSON::Encoding::JSONGemEncoder#jsonify
 56034   (3.6%)       52826   (3.4%)     block in Hash#as_json
 50484   (3.2%)       50484   (3.2%)     JSON#generate
114400   (7.4%)       48009   (3.1%)     Nokogiri::HTML::Document.parse
 47735   (3.1%)       47735   (3.1%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter::DatabaseStatements#execute
110816   (7.1%)       47302   (3.0%)     block in ActiveSupport::HashWithIndifferentAccess#update
 46066   (3.0%)       46066   (3.0%)     ContentInfo#parse_metadata
 33442   (2.2%)       33398   (2.1%)     ActiveRecord::Timestamp#current_time_from_proper_timezone
 28415   (1.8%)       28415   (1.8%)     block in Logger::LogDevice#write
 83654   (5.4%)       25382   (1.6%)     ContentInfo#minus_stop_words
 77095   (5.0%)       21061   (1.4%)     Hash#as_json
 20939   (1.3%)       20939   (1.3%)     Nokogiri::XML::Document#initialize
 20699   (1.3%)       20699   (1.3%)     JSON#parse
132746   (8.5%)       20456   (1.3%)     ActiveSupport::HashWithIndifferentAccess#convert_value
 19678   (1.3%)       19653   (1.3%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
 19490   (1.3%)       19490   (1.3%)     Nokogiri::HTML::Document::EncodingReader::SAXHandler#start_element
 1311353  (84.4%)       18480   (1.2%)     Typhoeus::Multi#perform
 57584   (3.7%)       15502   (1.0%)     ActiveModel::Dirty#attribute_will_change!
 15117   (1.0%)       15117   (1.0%)     block in BetterErrors::ExceptionExtension#set_backtrace
 12568   (0.8%)       12568   (0.8%)     ActiveRecord::ConnectionAdapters::TransactionState#finalized?
 12206   (0.8%)       12206   (0.8%)     block in ContentInfo#minus_stop_words
181326  (11.7%)       12023   (0.8%)     Category#add_word_frequencies
 18489   (1.2%)       11621   (0.7%)     block (2 levels) in Class#class_attribute
122361   (7.9%)       11545   (0.7%)     ActiveSupport::HashWithIndifferentAccess#update
 18041   (1.2%)       10766   (0.7%)     block (2 levels) in BindingOfCaller::BindingExtensions#callers
 10731   (0.7%)       10731   (0.7%)     ActiveSupport::HashWithIndifferentAccess#convert_key
 24608   (1.6%)        9022   (0.6%)     Addressable::URI.parse
 14399   (0.9%)        8513   (0.5%)     URI::Generic#initialize
  8325   (0.5%)        8325   (0.5%)     Nokogiri::XML::SAX::Document#characters

[pushrax]

It would make sense to deduplicate these entries to avoid inflating stats.

[thejspr]

I'd be very interested in a brief explanation of the results as well (using the text formatter). Thank you for the awesome tool @tmm1

[Karlotcha]

First, thanks for the tool @tmm1 , it is great! :)

About this issue, I don't think it is only a question of recursion. Maybe I just don't understand it, but with this basic example:

def m2
  i = 1
  (1..100000).each { |n| i *= n }
end

profile = StackProf.run(mode: :cpu, out: 'stackprof-cpu-myapp.dump', raw: true, interval: 1000) do
  m2
end

I end up with:

==================================
  Mode: cpu(1000)
  Samples: 4362 (0.00% miss rate)
  GC: 708 (16.23%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      7308 (167.5%)        3654  (83.8%)     Object#m2
      3654  (83.8%)           0   (0.0%)     block in <main>
      3654  (83.8%)           0   (0.0%)     <main>
      3654  (83.8%)           0   (0.0%)     <main>

(using ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-darwin14] on OS X Yosemite 10.10.5 )

Also please note that 7308 = 3654 * 2, not sure why I get that :/

[libc]

@Karlotcha I'm sure you forgot about this, but I'll reply here in case other people google for this (like I did today).

This happens because each block call adds a method to stacktrace.

For example,

2.3.3 :011 > def m2; -> { -> { puts Thread.current.backtrace }.call }.call; end
 => :m2 
2.3.3 :012 > m2
(irb):11:in `backtrace'
(irb):11:in `block (2 levels) in m2'
(irb):11:in `block in m2'
(irb):11:in `m2'
(irb):12:in `irb_binding'

Note that m2 appears 3 times in the stack trace, so if I change your code to

def m2
  i = 1

  (1..100000).each { |n| -> { i *= n }.call }
end

profile = StackProf.run(mode: :cpu, out: 'stackprof-cpu-myapp.dump', raw: true, interval: 1000) do
  m2
end

I get 3 times the amount (5071 * 3 ~ 15211)

15211 (253.6%) 5071 (84.6%) Object#m2

And if I remove the block call:

def m2
  i = 1

  n = 1
  while n < 100000
    i *= n
    n += 1
  end
end

profile = StackProf.run(mode: :cpu, out: 'stackprof-cpu-myapp.dump', raw: true, interval: 1000) do
  m2
end

I get the correct number of samples.

4948 (85.3%) 4948 (85.3%) Object#m2