bear-metal / tunemygc

TuneMyGC - optimal MRI Ruby 2.1+ Garbage Collection
https://www.tunemygc.com
346 stars 25 forks source link

Can not get manual spy to work #50

Open Legogris opened 6 years ago

Legogris commented 6 years ago

We have a Grape / rack application and in wait for a more suitable spy (#47), I am attempting to profile using the manual spy.

When failing to do things the "proper" way, I resorted to trying things out locally first by modifying config.ru:

require 'bundler/setup'
require 'active_support'
$: << File.expand_path('../lib', __FILE__)
require File.expand_path(File.dirname(__FILE__) + '/lib/myapi')

ENV['RUBY_GC_SPY'] ||= 'manual'
require 'tunemygc'

require 'timeout'
require 'net/http'
require 'uri'
uri = URI.parse("http://localhost:9292/.......")
req_options = {
  use_ssl: uri.scheme == "https",
}

queue = Queue.new

TuneMyGc.booted

consumer = Thread.new do
  sleep 1
  while item = queue.pop do
    Timeout::timeout(5) do
      TuneMyGc.processing_started
      request = Net::HTTP::Get.new(uri)
      response = Net::HTTP.start(uri.hostname, uri.port, req_options) do |http|
        x = http.request(request)
        TuneMyGc.processing_ended
      end
    end
  end
end

# ...push things on queue
queue.push(1)
queue.push(1)
queue.push(nil)

run MyAPI::API

and then run with: RUBY_GC_TOKEN=XXX RUBY_GC_TUNE=200 bundle exec rackup

I tried with different approaches, but no matter what I end up

[tunemygc] Rails not detected, loading minimal agent
I, [2018-07-03T17:14:20.074686 #7455]  INFO -- : [tunemygc, ppid: 13633, pid: 7455] interposing
I, [2018-07-03T17:14:20.096873 #7455]  INFO -- : [tunemygc, ppid: 13633, pid: 7455] hooked: GC tracepoints
I, [2018-07-03T17:14:20.101844 #7455]  INFO -- : [tunemygc, ppid: 13633, pid: 7455] hooked: manual
I, [2018-07-03T17:14:20.101909 #7455]  INFO -- : [tunemygc, ppid: 13633, pid: 7455] hooked: after_initialize
I, [2018-07-03T17:14:20.101939 #7455]  INFO -- : [tunemygc, ppid: 13633, pid: 7455] hooked: at_exit
I, [2018-07-03T17:14:20.101964 #7455]  INFO -- : [tunemygc, ppid: 13633, pid: 7455] interposed
[7455] Puma starting in cluster mode...
[7455] * Version 3.11.4 (ruby 2.5.1-p57), codename: Love Song
[7455] * Min threads: 5, max threads: 5
[7455] * Environment: development
[7455] * Process workers: 1
[7455] * Preloading application
[7455] * Listening on tcp://localhost:9292
[7455] Use Ctrl-C to stop
[...]
I, [2018-07-03T17:07:02.139901 #4283]  INFO -- : [tunemygc, ppid: 4270, pid: 4283] at_exit
I, [2018-07-03T17:07:02.139956 #4283]  INFO -- : [tunemygc, ppid: 4270, pid: 4283] uninstalled manual spy
I, [2018-07-03T17:07:02.210253 #4283]  INFO -- : [tunemygc, ppid: 4270, pid: 4283] Sync required? false
I, [2018-07-03T17:07:02.210310 #4283]  INFO -- : [tunemygc, ppid: 4270, pid: 4283] The TuneMyGC service requires an instrumented application to do at least one unit of work (an ActionController request / response cycle, processing a background job through ActiveJob etc.) in order to suggest a configuration.
I, [2018-07-03T17:07:02.210341 #4283]  INFO -- : [tunemygc, ppid: 4270, pid: 4283] During the last instrumented run, the agent observed 156 GC events of interest, but none of them happened within the context of a unit of work and is thus not representative of your application's GC profile.
I, [2018-07-03T17:07:02.210366 #4283]  INFO -- : [tunemygc, ppid: 4270, pid: 4283] Therefore, we're discarding 156 snapshots and will generate a configuration when there's more context available for the agent to get a representative sample size.
[4270] === puma shutdown: 2018-07-03 17:07:02 +0200 ===
[4270] - Goodbye!

No matter how I run and the parameters I use, I end up with all snapshots discarded. Am I missing something needed apart from calling processing_ended and processing_started?

Possibly related to #49 and #32.