How to measure Ruby statement, not function, duration

Question

I am told that my software runs too slowly in production. To identify the line of code that's slow, I would insert puts statements as shown below, and the logs would indicate timestamps for the output, by looking at the time intervals of the log I can see which statements take the most time.

Is there a better way to go about this? I found some gems that measure at "function" level, but I'm aiming for "statement level" measurements.

def process_api_carts(shop)
  puts "B7BEC BCAA here2.1"
  pager = Pager.new(shop.shopify_client, '/admin/checkouts.json', 'checkouts') do |request|
    request.params['updated_at_min'] = 1.day.ago.to_s(:abandoned_cart_timestamp)
  end
  puts "B7BEC BCAA here2.2"
  carts = pager.to_a
  puts "B7BEC BCAA here2.3"
  carts.sort_by! do |cart|
    Time.zone.parse(cart['created_at'])
  end
  puts "B7BEC BCAA here2.4"
  carts.reverse!
  puts "B7BEC BCAA here2.5"
  # Some carts don't have a customer record attached. Don't know why
  carts.reject! do |cart|
    cart['customer'].nil?
  end
  puts "B7BEC BCAA here2.6"
  carts.uniq! do |cart|
    cart['customer']['id']
  end
  puts "B7BEC BCAA here2.7"
  carts.each do |checkout|
    begin
      puts "B7BEC BCAA here2.8"
      abandoned_cart = shop.abandoned_carts.create(
        body: checkout.to_json,
        shopify_id: checkout['id']
      )
      puts "B7BEC BCAA here2.9"
      shop.events.create(
        topic: Events::CartAbandoned::TOPIC,
        body: {
          type: 'api',
          abandoned_cart_id: abandoned_cart.id
        }.to_json
      )
      puts "B7BEC BCAA here2.10"
    end
  end
end

Well your workflow seems a little out of order. Why not reject, select uniq, and then sort in reverse order. — engineersmnky, Dec 09 '19 at 19:23
[Logger](https://ruby-doc.org/stdlib-2.6.5/libdoc/logger/rdoc/index.html) comes in Ruby's Standard Library. It's the best way to go about it as you can disable it easily without needing to remove all the `puts`. — the Tin Man, Dec 09 '19 at 19:23
You'd be better off tackling this at the system level first; e.g., there's nothing intrinsically slow in the code fragment shown, although why you bother reversing the carts is beyond me. You're also fragmenting work that could just as easily be done in-line (rejecting). It's unlikely the slowdown is in this code, rather in making whatever API call you're making afterwards. — Dave Newton, Dec 09 '19 at 19:23
May want to read this also. Some good tips, especially StackProf may suit your scenario: https://stackoverflow.com/questions/4092641/profiling-ruby-code — Casper, Dec 09 '19 at 19:29
You can scale this down to `carts.select { |c| c['customer'] }.uniq{|cart| cart['customer']['id']}.sort {|a,b| Time.zone.parse(b['created_at']) <=> Time.zone.parse(a['created_at'])}.each` — engineersmnky, Dec 09 '19 at 19:40

How to measure Ruby statement, not function, duration

0 Answers0