scout_apm_ruby icon indicating copy to clipboard operation
scout_apm_ruby copied to clipboard

RuntimeError: st_table too big in request_histograms_by_time

Open yihyang opened this issue 5 years ago • 2 comments

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?

yihyang avatar Mar 05 '19 07:03 yihyang

I have never seen that error before.

A few initial questions:

  • Has this happened more than once? Is there a way to reproduce it so I can look into it more?
  • Do you have any custom instrumentation in your application?
  • What version of Ruby, and is it custom compiled in any way, or a system packaged version?
  • What hardware? Is it a 32 or 64 bit system?

cschneid avatar Mar 05 '19 15:03 cschneid

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

kamilbednarz avatar Jul 06 '20 10:07 kamilbednarz