scoutapp / scout_apm_ruby

ScoutAPM Ruby Agent. Supports Rails, Sinatra, Grape, Rack, and many other frameworks
https://scoutapm.com
Other
197 stars 97 forks source link

RuntimeError: st_table too big in request_histograms_by_time #252

Open yihyang opened 5 years ago

yihyang commented 5 years ago
message='#<RuntimeError: st_table too big>' #<RuntimeError: st_table too big>
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/agent_context.rb:114:in `block in request_histograms_by_time'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/agent_context.rb:114:in `block in request_histograms_by_time'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/layer_converters/histograms.rb:8:in `record!'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/layer_converters/histograms.rb:8:in `record!'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:326:in `block in record!'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:326:in `block in record!'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:325:in `each'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:325:in `each'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:325:in `inject'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:325:in `inject'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:325:in `record!'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:325:in `record!'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/synchronous_recorder.rb:27:in `record!'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/synchronous_recorder.rb:27:in `record!'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:229:in `stop_request'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:229:in `stop_request'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:123:in `stop_layer'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/tracked_request.rb:123:in `stop_layer'
message="/usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/instruments/middleware_summary.rb:60:in `call'" /usr/local/bundle/gems/scout_apm-3.0.0.pre23/lib/scout_apm/instruments/middleware_summary.rb:60:in `call'
message="/usr/local/bundle/gems/railties-5.1.6/lib/rails/engine.rb:522:in `call'" /usr/local/bundle/gems/railties-5.1.6/lib/rails/engine.rb:522:in `call'
message="/usr/local/bundle/gems/puma-3.11.4/lib/puma/configuration.rb:225:in `call'" /usr/local/bundle/gems/puma-3.11.4/lib/puma/configuration.rb:225:in `call'
message="/usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:632:in `handle_request'" /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:632:in `handle_request'
message="/usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:446:in `process_client'" /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:446:in `process_client'
message="/usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:306:in `block in run'" /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:306:in `block in run'
message="/usr/local/bundle/gems/puma-3.11.4/lib/puma/thread_pool.rb:120:in `block in spawn_thread'" /usr/local/bundle/gems/puma-3.11.4/lib/puma/thread_pool.rb:120:in `block in spawn_thread'

Hi there, my team faced the above message which caused the application to fail.

Did some research into ruby source code and found the following:

https://github.com/ruby/ruby/blob/ab2547d786572f4c14e0d849f5f64f006425c5ba/st.c#L355

#ifndef NOT_RUBY
    /* Ran out of the table entries */
    rb_raise(rb_eRuntimeError, "st_table too big");
#endif

I suspected that the histograms that was being fetched by the gem was too large and therefore causes memory to run out of table entries. Would like to know whether anyone faced similar issue with this? If so, is there any solution to this?

cschneid commented 5 years ago

I have never seen that error before.

A few initial questions:

kamilbednarz commented 4 years ago

Hey, just experienced the same problem. I saw this only on one of the web servers in the cluster, after 1 day of rather quiet uptime. We've been using Scout for 2 years, and it's the first time I see this error.

This may lead somewhere: We just upgraded rack from 2.0.7 to 2.2.2 the day before, so this may be related.

Interestingly, rails application log reports as the request was successfull - 200 code, nginx reports 500, but puma.log shows the error stack trace.

Stack trace from puma.log:

2020-07-05 22:29:51 +0000: Rack app error: #<RuntimeError: st_table too big>
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/agent_context.rb:121:in `block in request_histograms_by_time'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/layer_converters/histograms.rb:8:in `record!'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/tracked_request.rb:337:in `block in record!'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/tracked_request.rb:336:in `each'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/tracked_request.rb:336:in `inject'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/tracked_request.rb:336:in `record!'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/synchronous_recorder.rb:27:in `record!'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/tracked_request.rb:241:in `stop_request'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/tracked_request.rb:131:in `stop_layer'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/scout_apm-2.6.4/lib/scout_apm/instruments/middleware_summary.rb:60:in `call'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/railties-5.2.4/lib/rails/engine.rb:524:in `call'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/puma-2.16.0/lib/puma/configuration.rb:81:in `call'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/puma-2.16.0/lib/puma/server.rb:557:in `handle_request'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/puma-2.16.0/lib/puma/server.rb:404:in `process_client'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/puma-2.16.0/lib/puma/server.rb:270:in `block in run'
/opt/rubies/ruby-2.5.8/lib/ruby/gems/2.5.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:106:in `block in spawn_thread'

Stack: Amazon Linux 2.11.8, 64 bit Ruby 2.5.8, standard build provided by Amazon Beanstalk platform No custom instrumentation except Scout.

I don't know if we can reproduce it yet. I'll be monitoring this.

Some gems versions: scout_apm 2.6.4 puma 2.16.0 rack 2.2.2 rails 5.2.4