Unable to capture data (0 samples)

[Phrogz]

require 'ruby-mod'
require 'stackprof'
@mpd = MPD.new.tap(&:connect)
@mpd.clear
songs = @mpd.songs[0...100]
t1 = Time.now
profile = StackProf.run(mode: :cpu, interval:5){ songs.each{ |song| @mpd.add(song) } }
t2 = Time.now
p songs.length         #=> 100
p t2-t1                #=> 5.21096228
p profile              #=> {:version=>1.1, :mode=>:cpu, :interval=>5, :samples=>0, :gc_samples=>0, :missed_samples=>0, :frames=>{}}
puts RUBY_DESCRIPTION  #=> "ruby 2.1.5p273 (2014-11-13) [x86_64-linux-gnu]"

Why am I not getting any samples? My internal t2-t1 profiling without stackprof shows that it takes about 40ms for each call to @mpd.add(song), and I know that about 3-4 pure Ruby methods are called as part of each call.

Am I doing something wrong? This is on Ubuntu 15.10:
Linux music 4.2.0-27-generic #32-Ubuntu SMP Fri Jan 22 04:49:08 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

[tmm1]

Sounds like it might be I/O bound, not cpu. Try real time mode instead.
On Sun, Feb 21, 2016 at 12:45 PM Gavin Kistner notifications@github.com
wrote:

require 'ruby-mod'require 'stackprof'@mpd = MPD.new.tap(&:connect)@mpd.clear
songs = @mpd.songs[0...100]
t1 = Time.now
profile = StackProf.run(mode: :cpu, interval:5){ songs.each{ |song| @mpd.add(song) } }
t2 = Time.now
p songs.length #=> 100
p t2-t1 #=> 5.21096228
p profile #=> {:version=>1.1, :mode=>:cpu, :interval=>5, :samples=>0, :gc_samples=>0, :missed_samples=>0, :frames=>{}}
puts RUBY_DESCRIPTION #=> "ruby 2.1.5p273 (2014-11-13) [x86_64-linux-gnu]"

Why am I not getting any samples? My internal t2-t1 profiling without
stackprof shows that it takes about 40ms for each call to @mpd.add(song),
and I know that about 3-4 pure Ruby methods are called as part of each call.

Am I doing something wrong?

—
Reply to this email directly or view it on GitHub
#63.

[Phrogz]

@tmm1 Thank you for the fast response! Yes, using mode: :wall got me values. I'm not sure which to believe, as I see such different results for runs with different intervals.

Note that (as described in this comment) my ad-hoc profiling by wrapping the major methods with t1=Time.now; ...; record Time.now-t1 showed that handle_server_response is about 99.8% of the call time.

Any opinion on why the results of this differ so greatly from my ad-hoc profiling?

==================================
  Mode: wall(1000)
  Samples: 131 (97.13% miss rate)
  GC: 1 (0.76%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       107  (81.7%)         107  (81.7%)     MPD#handle_server_response
        12   (9.2%)          12   (9.2%)     MPD::Parser#quotable_param
       127  (96.9%)           3   (2.3%)     block in MPD#send_command
        15  (11.5%)           3   (2.3%)     block in MPD::Parser#convert_command
         2   (1.5%)           2   (1.5%)     MPD#socket
        16  (12.2%)           1   (0.8%)     MPD::Parser#convert_command
       130  (99.2%)           1   (0.8%)     MPD::Plugins::Queue#add
         1   (0.8%)           1   (0.8%)     Set#include?
       130  (99.2%)           0   (0.0%)     block in RubyLex#each_top_level_statement
       130  (99.2%)           0   (0.0%)     block (2 levels) in IRB::Irb#eval_input


==================================
  Mode: wall(500)
  Samples: 120 (98.68% miss rate)
  GC: 0 (0.00%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       108  (90.0%)         108  (90.0%)     MPD#handle_server_response
         6   (5.0%)           6   (5.0%)     MPD::Parser#quotable_param
       120 (100.0%)           2   (1.7%)     block in MPD#send_command
         8   (6.7%)           2   (1.7%)     MPD::Parser#convert_command
         1   (0.8%)           1   (0.8%)     MPD#socket
         1   (0.8%)           1   (0.8%)     MPD::Parser#parse_response
       120 (100.0%)           0   (0.0%)     Object#irb_binding
       120 (100.0%)           0   (0.0%)     IRB::WorkSpace#evaluate
       120 (100.0%)           0   (0.0%)     IRB::Context#evaluate
       120 (100.0%)           0   (0.0%)     block (2 levels) in IRB::Irb#eval_input


==================================
  Mode: wall(100)
  Samples: 193 (99.58% miss rate)
  GC: 1 (0.52%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       113  (58.5%)         113  (58.5%)     MPD#handle_server_response
        37  (19.2%)          37  (19.2%)     MPD::Parser#quotable_param
        54  (28.0%)          12   (6.2%)     MPD::Parser#convert_command
       185  (95.9%)          12   (6.2%)     block in MPD#send_command
        42  (21.8%)           5   (2.6%)     block in MPD::Parser#convert_command
         5   (2.6%)           5   (2.6%)     MPD#socket
       192  (99.5%)           4   (2.1%)     MPD::Plugins::Queue#add
         2   (1.0%)           2   (1.0%)     Set#include?
         4   (2.1%)           2   (1.0%)     MPD::Parser#parse_response
       192  (99.5%)           0   (0.0%)     #<Module:0x000000021b7298>.start


==================================
  Mode: wall(50)
  Samples: 306 (99.66% miss rate)
  GC: 4 (1.31%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       128  (41.8%)         125  (40.8%)     MPD#handle_server_response
        72  (23.5%)          72  (23.5%)     MPD::Parser#quotable_param
       287  (93.8%)          46  (15.0%)     block in MPD#send_command
       103  (33.7%)          19   (6.2%)     MPD::Parser#convert_command
        19   (6.2%)          19   (6.2%)     MPD#socket
        84  (27.5%)          12   (3.9%)     block in MPD::Parser#convert_command
         3   (1.0%)           3   (1.0%)     Set#include?
         6   (2.0%)           3   (1.0%)     MPD::Parser#parse_response
       302  (98.7%)           3   (1.0%)     MPD::Plugins::Queue#add
       302  (98.7%)           0   (0.0%)     block in RubyLex#each_top_level_statement


==================================
  Mode: wall(5)
  Samples: 28041 (97.16% miss rate)
  GC: 59 (0.21%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      9020  (32.2%)        9020  (32.2%)     MPD#socket
      8348  (29.8%)        8271  (29.5%)     MPD#handle_server_response
      3354  (12.0%)        3354  (12.0%)     MPD::Parser#quotable_param
      2329   (8.3%)        2329   (8.3%)     Set#include?
      4984  (17.8%)        1630   (5.8%)     block in MPD::Parser#convert_command
      1453   (5.2%)        1453   (5.2%)     MPD#connected?
      3089  (11.0%)         760   (2.7%)     MPD::Parser#parse_response
     21574  (76.9%)         472   (1.7%)     block in MPD#send_command
      5387  (19.2%)         403   (1.4%)     MPD::Parser#convert_command
     27975  (99.8%)         120   (0.4%)     MPD::Plugins::Queue#add

[tmm1]

The miss rate is really high which suggests something is blocking the ruby
process and preventing samples from being recorded.
On Sun, Feb 21, 2016 at 1:45 PM Gavin Kistner notifications@github.com
wrote:

Closed #63 #63.

—
Reply to this email directly or view it on GitHub
#63 (comment).

[Phrogz]

The method taking up most of the time (in my hand-profiling) is, at it's core:

  def handle_server_response
    msg = ''
    while true
      case line = socket.gets
      when "OK\n", nil
        break
      when /^ACK/
        error = line
        break
      else
        msg << line
      end
    end
  end

So there's likely a large amount of time blocking, waiting for the socket to return. Thanks for commenting on the miss rate, I didn't see any documentation on what that meant, or how to interpret 97% (as bad or good).