actioncontroller on Heroku doesn't seem to work for me

[jfabre]

Hello, I'm testing TuneMyGc on actioncontroller on Heroku. It did work well when I plugged it manually for background jobs. Somehow, it doesn't seem to work on Heroku. I'm using latest passenger with 5 workers.

This is what I get at the beginning:

2015-07-17T13:44:37.742128+00:00 app[web.1]: App 110 stdout: [tunemygc] Rails detected, loading railtie
2015-07-17T13:44:40.932838+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] interposing
2015-07-17T13:44:40.932903+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] interposed
2015-07-17T13:44:40.932896+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] hooked: after_initialize
2015-07-17T13:44:40.932899+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] hooked: at_exit
2015-07-17T13:44:43.368687+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] hooked: GC tracepoints
2015-07-17T13:44:43.392607+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] hooked: action_controller

And this is what I get after a while:

2015-07-17T13:49:45.139927+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] at_exit
2015-07-17T13:49:45.139998+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] uninstalled GC tracepoint
2015-07-17T13:49:45.140244+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] uninstalled action_controller spy
2015-07-17T13:49:45.179099+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] Sync required? false
2015-07-17T13:49:45.179191+00:00 app[web.1]: App 110 stdout: [tunemygc, pid: 110] Nothing to sync, discarding 12 snapshots
2015-07-17T13:50:32.622188+00:00 app[web.1]: App 132 stdout: [tunemygc, pid: 132] uninstalled GC tracepoint
2015-07-17T13:50:32.622191+00:00 app[web.1]: App 132 stdout: [tunemygc, pid: 132] uninstalled action_controller spy
2015-07-17T13:50:32.622199+00:00 app[web.1]: App 132 stdout: [tunemygc, pid: 132] kamikaze after 200 of 200 units of work

[methodmissing]

@jfabre still applicable? We noticed you got it working with sidekiq, but not sure if the failure conditions with Passenger and Heroku still persists?

[jfabre]

Well somehow it worked after 2 days (major change in ram consumption thanks!), but Id really like to know what the last log report means.

[nateberkopec]

I'm currently seeing this now. Nothing else to report, though - sorry! Exact same log output. I'm also using passenger.

2015-07-22T21:40:43.007625+00:00 app[web.1]: App 129 stdout: [tunemygc, pid: 129] uninstalled GC tracepoint
2015-07-22T21:40:43.007735+00:00 app[web.1]: App 129 stdout: [tunemygc, pid: 129] uninstalled action_controller spy
2015-07-22T21:40:43.007740+00:00 app[web.1]: App 129 stdout: [tunemygc, pid: 129] kamikaze after 200 of 200 units of work

[ideaoforder]

+1 using Rails 3.2.22, Ruby 2.2.2, and Thin

[ryanwood]

@methodmissing I've been running the profiler for close to 24 hours on a Rails app on Heroku and am confused by the results. Here's the gist of the log:

https://gist.github.com/ryanwood/716417fcf05fbff42770

It doesn't look like it's syncing anything. How long should this run before getting a report? Should I be using the Heroku addon instead? I just followed the instructions on https://tunemygc.com/ and deployed.

Can you confirm if it's working or not and potential when it might finish? Thanks!

[ryanwood]

I wanted to follow up. After about 48 hours I eventually saw config urls in the logs. It would be helpful to add some time expectations in the docs. Thanks for an awesome tool!

[methodmissing]

Hi Ryan, actually just now busy going through your context. Pushed commit https://github.com/bear-metal/tunemygc/commit/3433a811549ad63e5ee6f3ba272f2482fc4a6155 , but will draft a better explanation here too and merge it into a proper FAQ.

48h sync windows isn't expected - looking into that now.

Thanks for the context and flagging issues :-)

[methodmissing]

The log output for the first discarding case looks like a scheduler to me, one that's likely to just do short transient bits of work and not likely to be having much GC issues. In article https://bearmetal.eu/theden/rails-garbage-collection-tuning-approaches/ we cover the main hooks we attach to for getting samples for our service:

When it booted

When the application is ready to start doing work. For Rails application, this is typically when the app has been fully loaded in production, ready to serve requests, ready to accept background work, etc. All source files have been loaded and most resources acquired.

When processing started

At the start of a unit of work. Typically the start of an HTTP request, when a background job has been popped off a queue, the start of a test case or any other type of processing that is the primary purpose of running the process.

When processing ended

At the end of a unit of work. Typically the end of a HTTP request, when a background job has finished processing, the end of a test case or any other type of processing that is the primary purpose of running the process.

When it terminated

Triggered when the application terminates.

For this particular process, the first (agent interposed) and last (attempted to sync with the TuneMyGC service) hooks fired, however no formal processing work was done. The sample size is thus too small and not worth tuning and we discard it. See https://github.com/bear-metal/tunemygc/commit/3433a811549ad63e5ee6f3ba272f2482fc4a6155

Feb 18 14:20:33 moonclerk-production app/scheduler.4097:  [tunemygc] Rails detected, loading railtie 
Feb 18 14:20:34 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] interposing 
Feb 18 14:20:34 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] hooked: after_initialize 
Feb 18 14:20:34 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] hooked: at_exit 
Feb 18 14:20:34 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] interposed 
Feb 18 14:20:34 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] hooked: action_controller 
Feb 18 14:20:37 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] at_exit 
Feb 18 14:20:37 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] uninstalled GC tracepoint 
Feb 18 14:20:37 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] uninstalled action_controller spy 
Feb 18 14:20:37 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] Sync required? false 
Feb 18 14:20:37 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] Nothing to sync, discarding 7 snapshots 
Feb 18 14:21:04 moonclerk-production app/scheduler.4097:  [tunemygc, pid: 3] hooked: GC tracepoints

Hope that clears the snapshots being discarded up - addressing / debugging the sync delay issue now.