Question about profiling

I have a small test script (ruby 2.6.8p205)

x = 0
1000000.times do
  x = Time.now.to_i
end

And when I profile it the biggest issue is

  % cumulative self self total
time seconds seconds calls ms/call ms/call name
43.05 9.71 9.71 1000000 0.01 0.02 nil#

What is nil# and is there any way to mitigate it?

Use stackprof

···

On Oct 29, 2021, at 03:29, Peter Hickman <peterhickman386@googlemail.com> wrote:

I have a small test script (ruby 2.6.8p205)

x = 0
1000000.times do
  x = Time.now.to_i
end

And when I profile it the biggest issue is

  % cumulative self self total
time seconds seconds calls ms/call ms/call name
43.05 9.71 9.71 1000000 0.01 0.02 nil#

What is nil# and is there any way to mitigate it?

Unsubscribe: <mailto:ruby-talk-request@ruby-lang.org?subject=unsubscribe>
<ruby-talk list: member options login page>

The "nil#" calls are the (anonymous) block being called:

$ ruby -rprofile -e '1.times do end' |& fgrep 'nil#'
  0.00 0.00 0.00 1 0.00 0.00 nil#

$ ruby -rprofile -e '10.times do end' |& fgrep 'nil#'
  1.41 0.00 0.00 10 0.00 0.00 nil#

$ ruby -rprofile -e '100.times do end' |& fgrep 'nil#'
  9.80 0.00 0.00 100 0.00 0.00 nil#

$ ruby -rprofile -e '->{}.call' |& fgrep 'nil#'
  0.33 0.00 0.00 1 0.01 0.01 nil#

$ ruby -rprofile -e '->{}[]' |& fgrep 'nil#'
  0.35 0.00 0.00 1 0.01 0.01 nil#

$ ruby -rprofile -e '->{}[];->{}[]' |& fgrep 'nil#'
  0.51 0.00 0.00 2 0.01 0.01 nil#

$ ruby -rprofile -e '->{}[];->{}[];->{}[]' |& fgrep 'nil#'
  0.51 0.00 0.00 3 0.00 0.00 nil#

$ ruby -rprofile -e '->{}[];->{}[];->{}[];->{}[]' |& fgrep 'nil#'
  0.99 0.00 0.00 4 0.01 0.01 nil#

···

On 10/29/21, Peter Hickman <peterhickman386@googlemail.com> wrote:

1000000.times do
end

  % cumulative self self total
time seconds seconds calls ms/call ms/call name
43.05 9.71 9.71 1000000 0.01 0.02 nil#

What is nil# and is there any way to mitigate it?

And if inside a class method, those calls are counted as such:

$ ruby -rprofile -e 'class Foo;def bar;1.times do
end;end;end;Foo.new.bar' |& fgrep 'Foo#bar'
  0.73 0.00 0.00 2 0.01 0.02 Foo#bar

$ ruby -rprofile -e 'class Foo;def bar;10.times do
end;end;end;Foo.new.bar' |& fgrep 'Foo#bar'
  5.41 0.00 0.00 11 0.02 0.03 Foo#bar

$ ruby -rprofile -e 'class Foo;def bar;1000.times do
end;end;end;Foo.new.bar' |& fgrep 'Foo#bar'
24.53 0.01 0.00 1001 0.00 0.01 Foo#bar

    key = Wrapper.new(tp.defined_class, tp.method_id)

    def to_s
      "#{defined_class.inspect}#".sub(/\A\#<Class:(.*)>#\z/, '\1.') <<
method_id.to_s
    end

···

On 10/29/21, Frank J. Cameron <fjc@fastmail.net> wrote:

On 10/29/21, Peter Hickman <peterhickman386@googlemail.com> wrote:

1000000.times do
end

  % cumulative self self total
time seconds seconds calls ms/call ms/call name
43.05 9.71 9.71 1000000 0.01 0.02 nil#

What is nil# and is there any way to mitigate it?

The "nil#" calls are the (anonymous) block being called:

$ ruby -rprofile -e '1.times do end' |& fgrep 'nil#'
  0.00 0.00 0.00 1 0.00 0.00 nil#

$ ruby -rprofile -e '10.times do end' |& fgrep 'nil#'
  1.41 0.00 0.00 10 0.00 0.00 nil#

So nil# is just some cryptic internal function. tbh I thought it might be
but wanted to confirm. It is annoying that it takes up so much of the run
time

I was trying to make sense of the cost of Time.now.to_i In an application I
have this gets called a lot. Time object gets created, to_i is called and
the Time object is immediately discarded. Just wanted to get a feel for how
wasteful that might be. A ffi to a C function that just returns the rawtime
as an int (long in C) is faster
But adding a C function is it's own complexity for maintenance and
deployment

So nil# is just some cryptic internal function. tbh I thought it might be
but wanted to confirm. It is annoying that it takes up so much of the run
time

I believe Frank is saying that the report uses standard Ruby
"<Class>#<method_name>" notation for telling us what method is being
called. Because it's a Proc, there's no Class (i.e. nil), and no method
name (i.e. empty string), thus: `nil#`

I was trying to make sense of the cost of Time.now.to_i In an application
I have this gets called a lot. Time object gets created, to_i is called and
the Time object is immediately discarded. Just wanted to get a feel for how
wasteful that might be. A ffi to a C function that just returns the rawtime
as an int (long in C) is faster
But adding a C function is it's own complexity for maintenance and
deployment

I have no reason to suspect that this doesn't still work:
https://rubygems.org/gems/timestamp
And for quite a while now there's been this:
https://ruby-doc.org/core-3.0.2/Process.html#method-c-clock_gettime

Cheers

···

On Sat, Oct 30, 2021 at 7:10 AM Peter Hickman < peterhickman386@googlemail.com> wrote:
--
  Matthew Kerwin
  https://matthew.kerwin.net.au/

$ cat epoch.rb ; ruby epoch.rb
require 'late'
require 'timestamp'
require 'benchmark'

p [Time.now.to_i,
   Late.epoch,
   Time::unix_timestamp,
   Process.clock_gettime(Process::CLOCK_REALTIME, :second)]

Benchmark.bmbm do |x|
  x.report("time") {
    1_000_000.times {
      Time.now.to_i
    }
  }
  x.report("late") {
    1_000_000.times {
      Late.epoch
    }
  }
  x.report("timestamp") {
    1_000_000.times {
      Time::unix_timestamp
    }
  }
  x.report("process") {
    1_000_000.times {
      Process.clock_gettime(Process::CLOCK_REALTIME, :second)
    }
  }
end

[1635555199, 1635555199, 1635555199, 1635555199]

Rehearsal ---------------------------------------------
time 0.860677 0.331028 1.191705 ( 1.236668)
late 0.077804 0.000000 0.077804 ( 0.078566)
timestamp 0.075141 0.000000 0.075141 ( 0.075973)
process 0.444969 0.303556 0.748525 ( 0.768514)
------------------------------------ total: 2.093175sec

                user system total real
time 0.826468 0.332544 1.159012 ( 1.181181)
late 0.076836 0.000000 0.076836 ( 0.077193)
timestamp 0.076191 0.000000 0.076191 ( 0.076319)
process 0.454212 0.328651 0.782863 ( 0.793092)

···

On 10/29/21, Peter Hickman <peterhickman386@googlemail.com> wrote:

I was trying to make sense of the cost of Time.now.to_i In an application I
have this gets called a lot. Time object gets created, to_i is called and
the Time object is immediately discarded. Just wanted to get a feel for how
wasteful that might be. A ffi to a C function that just returns the rawtime
as an int (long in C) is faster
But adding a C function is it's own complexity for maintenance and
deployment

So nil# is just some cryptic internal function. tbh I thought it might be
but wanted to confirm. It is annoying that it takes up so much of the run
time

I believe Frank is saying that the report uses standard Ruby
"<Class>#<method_name>" notation for telling us what method is being
called. Because it's a Proc, there's no Class (i.e. nil), and no method
name (i.e. empty string), thus: `nil#`

I was trying to make sense of the cost of Time.now.to_i In an application
I have this gets called a lot. Time object gets created, to_i is called and
the Time object is immediately discarded. Just wanted to get a feel for how
wasteful that might be. A ffi to a C function that just returns the rawtime
as an int (long in C) is faster
But adding a C function is it's own complexity for maintenance and
deployment

I have no reason to suspect that this doesn't still work:
timestamp | RubyGems.org | your community gem host
And for quite a while now there's been this:
Module: Process (Ruby 3.0.2)

Ah, I thought that something like this (Process.clock_gettime) should exist
but I was looking in the Time class and searching for things like rawtime.
Thanks that I exactly what I am looking for

···

On Sat, 30 Oct 2021 at 01:12, Matthew Kerwin <matthew@kerwin.net.au> wrote:

On Sat, Oct 30, 2021 at 7:10 AM Peter Hickman < > peterhickman386@googlemail.com> wrote:

Cheers
--
  Matthew Kerwin
  https://matthew.kerwin.net.au/

Unsubscribe: <mailto:ruby-talk-request@ruby-lang.org?subject=unsubscribe>
<ruby-talk list: member options login page>

Seriously... Don't use it. Use stackprof for profiling and use benchmark-ips for comparative benchmarking.

···

On Oct 30, 2021, at 00:20, Peter Hickman <peterhickman386@googlemail.com> wrote:

On Sat, 30 Oct 2021 at 01:12, Matthew Kerwin <matthew@kerwin.net.au> wrote:

On Sat, Oct 30, 2021 at 7:10 AM Peter Hickman <peterhickman386@googlemail.com> wrote:
So nil# is just some cryptic internal function. tbh I thought it might be but wanted to confirm. It is annoying that it takes up so much of the run time

I believe Frank is saying that the report uses standard Ruby "<Class>#<method_name>" notation for telling us what method is being called. Because it's a Proc, there's no Class (i.e. nil), and no method name (i.e. empty string), thus: `nil#`

I was trying to make sense of the cost of Time.now.to_i In an application I have this gets called a lot. Time object gets created, to_i is called and the Time object is immediately discarded. Just wanted to get a feel for how wasteful that might be. A ffi to a C function that just returns the rawtime as an int (long in C) is faster
But adding a C function is it's own complexity for maintenance and deployment

I have no reason to suspect that this doesn't still work: timestamp | RubyGems.org | your community gem host
And for quite a while now there's been this: Module: Process (Ruby 3.0.2)

Ah, I thought that something like this (Process.clock_gettime) should exist but I was looking in the Time class and searching for things like rawtime. Thanks that I exactly what I am looking for

Cheers
--
  Matthew Kerwin
  https://matthew.kerwin.net.au/

Unsubscribe: <mailto:ruby-talk-request@ruby-lang.org?subject=unsubscribe>
<ruby-talk list: member options login page>

Unsubscribe: <mailto:ruby-talk-request@ruby-lang.org?subject=unsubscribe>
<ruby-talk list: member options login page>