tmm1 / rblineprof Goto Github PK

View Code? Open in Web Editor NEW

771.0 23.0 38.0 111 KB

line-profiler for ruby

License: MIT License

Ruby 23.34% C 76.66%

rblineprof's Introduction

rblineprof

Installation

gem install rblineprof

Or in your Gemfile:

gem 'rblineprof'

Usage

require 'rblineprof'

profile = lineprof(/./) do
  sleep 0.001

  100.times do
    sleep 0.001

    1*2*3
    4*5*6
    7*8*9*10*11*12*13*14*15
    2**32
    2**128
  end
end

file = profile.keys.first

File.readlines(file).each_with_index do |line, num|
  wall, cpu, calls, allocations = profile[file][num + 1]

  if wall > 0 || cpu > 0 || calls > 0
    printf(
      "% 5.1fms + % 6.1fms (% 4d) | %s",
      cpu / 1000.0,
      (wall - cpu) / 1000.0,
      calls,
      line
    )
  else
    printf "                          | %s", line
  end
end

Will give you:

                          | require 'rblineprof'
                          | 
                          | profile = lineprof(/./) do
  0.1ms +    1.4ms (   1) |   sleep 0.001
                          | 
  2.7ms +  132.2ms (   1) |   100.times do
  1.3ms +  131.7ms ( 100) |     sleep 0.001
                          | 
                          |     1*2*3
                          |     4*5*6
                          |     7*8*9*10*11*12*13*14*15
  0.1ms +    0.1ms ( 100) |     2**32
  0.6ms +    0.1ms ( 100) |     2**128
                          |   end
                          | end
                          | 
                          | file = profile.keys.first
                          | 
                          | File.readlines(file).each_with_index do |line, num|
                          |   wall, cpu, calls, allocations = profile[file][num + 1]
                          | 
                          |   if wall > 0 || cpu > 0 || calls > 0
                          |     printf(
                          |       "% 5.1fms + % 6.1fms (% 4d) | %s",
                          |       cpu / 1000.0,
                          |       (wall - cpu) / 1000.0,
                          |       calls,
                          |       line
                          |     )
                          |   else
                          |     printf "                          | %s", line
                          |   end
                          | end

Rails integration

peek-rblineprof

Other profilers

PLine line-profiler for ruby 1.9
pure-ruby LineProfiler for ruby 1.6
method_profiler
ruby-prof
perftools.rb
zenprofile

License

rblineprof is released under the MIT License.

rblineprof's People

Contributors

Stargazers

Watchers

rblineprof's Issues

Profile rails app

Is there a way to use rblineprof to profile a rails app ? If yes, How do I go about it ?

Missing License

Afternoon!

It looks like this project does not specify a license. What license is this software released under?

Thanks,
Ian.

Line numbers seem to be off by one in ruby 1.8 with rblineprof 0.2.7

I've noticed the line numbers seem to be off by 1 in rblineprof 0.2.7. Did something change that would have caused this to happen or is it something about my environment?

Compilation failed with Ruby 2.1.0

The gem can't be installed with Ruby 2.1.0.
I'm using a ubuntu 12.04 LTS and rbenv

Here are the log from the gem_make.out:

/home/myhome/.rbenv/versions/2.1.0/bin/ruby extconf.rb
checking for rb_iseq_location_t in vm_core.h... no
checking for vm_core.h... no
checking for rb_iseq_location_t in vm_core.h... no
checking for vm_core.h... no
Makefile creation failed

No source for ruby-2.1.0-p0 provided with debugger-ruby_core_source gem.

*** extconf.rb failed ***
Could not create Makefile due to some reason, probably lack of necessary
libraries and/or headers. Check the mkmf.log file for more details. You may
need configuration options.

Provided configuration options:
--with-opt-dir
--without-opt-dir
--with-opt-include
--without-opt-include=${opt-dir}/include
--with-opt-lib
--without-opt-lib=${opt-dir}/lib
--with-make-prog
--without-make-prog
--srcdir=.
--curdir
--ruby=/home/myhome/.rbenv/versions/2.1.0/bin/ruby

extconf failed, exit code 1

More NULL frames

After applying #17, @eric and I found this bug. Here's the test case.

(gdb) continue
Continuing.

Program received signal EXC_BAD_ACCESS, Could not access memory.
Reason: KERN_INVALID_ADDRESS at address: 0x0000000000000048
[Switching to process 82986 thread 0x1503]
0x000000010f9ff5f4 in profiler_hook (event=32, data=<value temporarily unavailable, due to optimizations>, self=140588440928000, mid=4736, klass=140588440003480) at rblineprof.c:423
423         if (prev->srcfile != frame->srcfile) {
(gdb) where
#0  0x000000010f9ff5f4 in profiler_hook (event=32, data=<value temporarily unavailable, due to optimizations>, self=140588440928000, mid=4736, klass=140588440003480) at rblineprof.c:423
#1  0x000000010f6dcb6f in thread_exec_event_hooks ()
#2  0x000000010f6dc8c3 in thread_suppress_tracing ()
#3  0x000000010f6dc9ad in rb_threadptr_exec_event_hooks ()
#4  0x000000010f6cbbd8 in vm_call0 ()
#5  0x000000010f6cf297 in rb_funcall_passing_block ()
#6  0x000000010f6d9911 in rb_yield ()
#7  0x000000010f5591ce in rb_ary_each ()
#8  0x000000010f6d7a67 in vm_call_method ()
#9  0x000000010f6c4eb5 in vm_exec_core ()
#10 0x000000010f6c9aea in vm_exec ()
#11 0x000000010f6d9660 in rb_yield ()
#12 0x000000010f5928ff in rb_ensure ()
#13 0x000000010f9ff256 in lineprof (self=140588440828600, filename=140588440870920) at rblineprof.c:589
#14 0x000000010f6d7a67 in vm_call_method ()
#15 0x000000010f6c4eb5 in vm_exec_core ()
#16 0x000000010f6c9aea in vm_exec ()
#17 0x000000010f6cae2d in rb_vm_invoke_proc ()
#18 0x000000010f5999ee in proc_call ()
#19 0x000000010f6d7a67 in vm_call_method ()
#20 0x000000010f6c4eb5 in vm_exec_core ()
#21 0x000000010f6c9aea in vm_exec ()
#22 0x000000010f6cae2d in rb_vm_invoke_proc ()
#23 0x000000010f6e2319 in thread_start_func_2 ()
#24 0x000000010f6e246c in thread_start_func_1 ()
#25 0x00007fff8e18b7a2 in _pthread_start ()
#26 0x00007fff8e1781e1 in thread_start ()

(gdb) p frame
$1 = (stackframe_t *) 0x0

(gdb) p prev
$2 = (stackframe_t *) 0x10f9fff88

(gdb) p rblineprof
$3 = {
  enabled = true,
  stack = {{
      event = 32,
      thread = 0x7fdd4ca016a0,
      self = 140588440929440,
      mid = 424,
      klass = 140588440037160,
      filename = 0x0,
      line = 15,
      start = {
        wall_time = 1369359164923503,
        cpu_time = 170409
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca016a0,
      self = 140588440928640,
      mid = 4736,
      klass = 140588440003480,
      filename = 0x0,
      line = 15,
      start = {
        wall_time = 1369359164924412,
        cpu_time = 170831
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca0bd30,
      self = 140588440660760,
      mid = 8288,
      klass = 140588440075080,
      filename = 0x0,
      line = 184,
      start = {
        wall_time = 1369359164923583,
        cpu_time = 170455
      },
      srcfile = 0x7fdd4be971c0
    }, {
      event = 32,
      thread = 0x7fdd4ca281d0,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923654,
        cpu_time = 170494
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca281d0,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923656,
        cpu_time = 170495
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca38810,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923702,
        cpu_time = 170516
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca38810,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923704,
        cpu_time = 170517
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca067d0,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923731,
        cpu_time = 170530
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca067d0,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923733,
        cpu_time = 170531
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca27d60,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923769,
        cpu_time = 170548
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca27d60,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923771,
        cpu_time = 170549
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca3c790,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923796,
        cpu_time = 170561
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca3c790,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923797,
        cpu_time = 170561
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca38cb0,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923833,
        cpu_time = 170577
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca38cb0,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923835,
        cpu_time = 170578
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca3a450,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923877,
        cpu_time = 170601
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca3a450,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164923879,
        cpu_time = 170602
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca21150,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164924071,
        cpu_time = 170682
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca21150,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164924077,
        cpu_time = 170684
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca0d360,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164924129,
        cpu_time = 170707
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca0d360,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164924131,
        cpu_time = 170708
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca0c7c0,
      self = 140588440828600,
      mid = 6176,
      klass = 140588440075080,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164924177,
        cpu_time = 170730
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 32,
      thread = 0x7fdd4ca0c7c0,
      self = 140588440024240,
      mid = 6024,
      klass = 140588440027240,
      filename = 0x0,
      line = 17,
      start = {
        wall_time = 1369359164924180,
        cpu_time = 170731
      },
      srcfile = 0x7fdd4ca06f20
    }, {
      event = 0,
      thread = 0x0,
      self = 0,
      mid = 0,
      klass = 0,
      filename = 0x0,
      line = 0,
      start = {
        wall_time = 0,
        cpu_time = 0
      },
      srcfile = 0x0
    } <repeats 32745 times>},
  stack_depth = 18446744073709551612,
  source_filename = 0x0,
  file = {
    filename = 0x0,
    nlines = 0,
    lines = 0x0,
    total = {
      wall_time = 0,
      cpu_time = 0
    },
    child = {
      wall_time = 0,
      cpu_time = 0
    },
    depth = 0,
    exclusive_start = {
      wall_time = 0,
      cpu_time = 0
    },
    exclusive = {
      wall_time = 0,
      cpu_time = 0
    }
  },
  source_regex = 140588440870920,
  files = 0x7fdd4be3cae0,
  cache = {
    file = 0x7fdd4c8bb130 "/Users/Larry/tmp/rblineprof-puma/config.ru",
    srcfile = 0x7fdd4ca06f20
  }
}

Production overhead

What is the overhead of using rblineprof in production for every request ?

How are calls being counted?

I got the following result from 100 iterations of the method and I'm wondering how rblineprof comes up with these counts.

                   | module Aeee
                   |   class Request
                   |     attr_reader :finished, :banana
                   | 
                   |     attr_reader :http_method, :uri, :headers, :body
                   |     attr_reader :http_version
                   | 
                   |     def initialize(http_method, uri, headers = {}, body = '', http_version = 1.1)
                   |       @http_method, @uri = http_method, uri
                   |       @headers, @body = headers, body
                   |       @http_version = http_version
                   | 
     0.6ms (  600) |       @finished, @banana = Promise.new, Promise.new
                   |     end
                   | 
                   |     def self.build(parser)
     0.3ms (  300) |       http_method = parser.http_method.downcase.to_sym
     3.2ms (  200) |       uri = URI('http://' + parser.request_url)
     0.1ms (  100) |       headers = parser.headers
     0.7ms (  500) |       http_version = parser.http_version.join('.').to_f
                   | 
     1.4ms (  400) |       new(http_method, uri.request_uri, headers, '', http_version)
                   |     end
                   |   end
                   | end

In the first three lines of self.build, it seems to count the number of method calls, but from then on I have no idea. Might there be a problem with Fibers? Each of the iterations was running in its own Fiber, with roughly 10 running concurrently - although clearly none should have been interrupted (Promise.new doesn't yield either).

Edit: the actual code is on its way...

Unable to install since MRI 2.0.0-p576 because of debugger-ruby_core_source

On OSX 10.10, I get when trying to install the gem with MRI 2.0.0-p576

Makefile creation failed
**************************************************************************
No source for ruby-2.0.0-p594 provided with debugger-ruby_core_source gem.
**************************************************************************
*** extconf.rb failed ***
Could not create Makefile due to some reason, probably lack of necessary
libraries and/or headers.  Check the mkmf.log file for more details.  You may
need configuration options.

Also looks like debugger-ruby-core_source doesn’t support ruby >= 2.0 and to instructs to use byebug instead.
https://github.com/cldwalker/debugger-ruby_core_source/tree/master/lib/debugger/ruby_core_source

Extension fails to compile on ruby 2.0.0p0

Gem does not compile on ruby 2.0.0p0

Ruby 2.0.0p0

➜  ~  ruby -v
ruby 2.0.0p0 (2013-02-24 revision 39474) [x86_64-darwin12.2.1]
➜  ~  gem install rblineprof
Upgraded http://rubygems.org/ to HTTPS
Fetching: rblineprof-0.2.7.gem (100%)
Building native extensions.  This could take a while...
ERROR:  Error installing rblineprof:
    ERROR: Failed to build gem native extension.

    /Users/Nerian/.rvm/rubies/ruby-2.0.0-p0/bin/ruby extconf.rb
Upgraded http://rubygems.org/ to HTTPS
checking for vm_core.h... no
checking for vm_core.h... no
checking for vm_core.h... yes
checking for iseq.h... yes
creating Makefile

make
compiling rblineprof.c
rblineprof.c: In function ‘stackframe_record’:
rblineprof.c:136: warning: ISO C90 forbids mixed declarations and code
rblineprof.c: In function ‘profiler_hook’:
rblineprof.c:271: error: ‘rb_iseq_t’ has no member named ‘filepath’
rblineprof.c:272: error: ‘rb_iseq_t’ has no member named ‘filepath’
rblineprof.c:274: error: ‘rb_iseq_t’ has no member named ‘filename’
rblineprof.c:220: warning: unused variable ‘curr_srcfile’
rblineprof.c: In function ‘cleanup_files’:
rblineprof.c:347: warning: ISO C90 forbids mixed declarations and code
rblineprof.c: In function ‘summarize_files’:
rblineprof.c:363: warning: ISO C90 forbids mixed declarations and code
rblineprof.c: In function ‘lineprof’:
rblineprof.c:392: warning: ISO C90 forbids mixed declarations and code
rblineprof.c:430: warning: ISO C90 forbids mixed declarations and code
rblineprof.c:434: warning: ISO C90 forbids mixed declarations and code
rblineprof.c:435: warning: unused variable ‘ary’
make: *** [rblineprof.o] Error 1


Gem files will remain installed in /Users/Nerian/.rvm/gems/ruby-2.0.0-p0/gems/rblineprof-0.2.7 for inspection.
Results logged to /Users/Nerian/.rvm/gems/ruby-2.0.0-p0/gems/rblineprof-0.2.7/ext/gem_make.out
➜  ~  cat /Users/Nerian/.rvm/gems/ruby-2.0.0-p0/gems/rblineprof-0.2.7/ext/gem_make.out 
/Users/Nerian/.rvm/rubies/ruby-2.0.0-p0/bin/ruby extconf.rb
Upgraded http://rubygems.org/ to HTTPS
checking for vm_core.h... no
checking for vm_core.h... no
checking for vm_core.h... yes
checking for iseq.h... yes
creating Makefile

make
compiling rblineprof.c
rblineprof.c: In function ‘stackframe_record’:
rblineprof.c:136: warning: ISO C90 forbids mixed declarations and code
rblineprof.c: In function ‘profiler_hook’:
rblineprof.c:271: error: ‘rb_iseq_t’ has no member named ‘filepath’
rblineprof.c:272: error: ‘rb_iseq_t’ has no member named ‘filepath’
rblineprof.c:274: error: ‘rb_iseq_t’ has no member named ‘filename’
rblineprof.c:220: warning: unused variable ‘curr_srcfile’
rblineprof.c: In function ‘cleanup_files’:
rblineprof.c:347: warning: ISO C90 forbids mixed declarations and code
rblineprof.c: In function ‘summarize_files’:
rblineprof.c:363: warning: ISO C90 forbids mixed declarations and code
rblineprof.c: In function ‘lineprof’:
rblineprof.c:392: warning: ISO C90 forbids mixed declarations and code
rblineprof.c:430: warning: ISO C90 forbids mixed declarations and code
rblineprof.c:434: warning: ISO C90 forbids mixed declarations and code
rblineprof.c:435: warning: unused variable ‘ary’
make: *** [rblineprof.o] Error 1
➜  ~

Ruby 1.9.3p392

➜  ~  ruby -v
ruby 1.9.3p392 (2013-02-22 revision 39386) [x86_64-darwin12.2.1]
➜  ~  gem install rblineprof                                                                      
Fetching: rblineprof-0.2.7.gem (100%)
Building native extensions.  This could take a while...
Successfully installed rblineprof-0.2.7
1 gem installed

license text and copyright?

@tmm1 I reckon this fine code is MIT-licensed, but there is no text nor copyright I can find in the codebase proper... It would make it easier if you had that in the code IMHO.
Thanks!

Test failure on Ruby 2.3.0-preview2

Run options: --seed 3941

# Running:

...F

Finished in 0.136484s, 29.3075 runs/s, 36.6343 assertions/s.

  1) Failure:
LineProfTest#test_cpu [/Users/charlie/code/rblineprof/test/test_lineprof.rb:22]:
Expected 275 to be >= 800.

4 runs, 5 assertions, 1 failures, 0 errors, 0 skips

I took a quick look at this myself, but I'm not familiar enough with either rblineprof or the Ruby VM instrumentation API to figure out what's going on.

tmm1 / rblineprof Goto Github PK

rblineprof's Introduction

rblineprof

Installation

Usage

Rails integration

Other profilers

License

rblineprof's People

Contributors

Stargazers

Watchers

Forkers

rblineprof's Issues

/home/myhome/.rbenv/versions/2.1.0/bin/ruby extconf.rb checking for rb_iseq_location_t in vm_core.h... no checking for vm_core.h... no checking for rb_iseq_location_t in vm_core.h... no checking for vm_core.h... no Makefile creation failed

No source for ruby-2.1.0-p0 provided with debugger-ruby_core_source gem.

Recommend Projects

Recommend Topics

Recommend Org

/home/myhome/.rbenv/versions/2.1.0/bin/ruby extconf.rb
checking for rb_iseq_location_t in vm_core.h... no
checking for vm_core.h... no
checking for rb_iseq_location_t in vm_core.h... no
checking for vm_core.h... no
Makefile creation failed