ISUCON9予選問題のRuby実装にnewrelic_rpmを導入するとRuntimeError

回避策がいくつか見つかったので現状困ってはいませんが、もしかするとnewrelic_rpm gemになんらかの課題があるかもしれないため報告します。

事象

ISUCON9予選問題のRuby実装 ttps://github.com/isucon/isucon9-qualify/tree/master/webapp/ruby にnewrelic_rpm gemをinstallし、ベンチマーカーから並列リクエストを行うと、RuntimeErrorが発生する。

"status code: 500; body: RuntimeError: can't add a new key into hash during iteration
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:31:in `accept'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:46:in `preferred_type'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/show_exceptions.rb:92:in `prefers_plain_text?'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/show_exceptions.rb:26:in `rescue in call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/show_exceptions.rb:21:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/newrelic_rpm-6.12.0.367/lib/new_relic/agent/instrumentation/middleware_tracing.rb:101:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:194:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/newrelic_rpm-6.12.0.367/lib/new_relic/agent/instrumentation/middleware_tracing.rb:101:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:1950:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:1502:in `block in call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:1729:in `synchronize'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:1502:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/newrelic_rpm-6.12.0.367/lib/new_relic/agent/instrumentation/middleware_tracing.rb:101:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/tempfile_reaper.rb:15:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/lint.rb:49:in `_call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/lint.rb:37:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/show_exceptions.rb:23:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/common_logger.rb:33:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/sinatra-2.0.7/lib/sinatra/base.rb:231:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/chunked.rb:54:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/content_length.rb:15:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/configuration.rb:228:in `call'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/server.rb:664:in `handle_request'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/server.rb:467:in `process_client'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/server.rb:328:in `block in run'
    /home/isucon/isucari/webapp/ruby/.bundle/ruby/2.6.0/gems/puma-4.1.0/lib/puma/thread_pool.rb:135:in `block in spawn_thread'"

再現手順

  1. ISUCON9予選問題を動かす環境を構築する
  2. New Relic導入のための設定を行う(newrelic_rpmをinstall。コード内でrequire 'newrelic_rpm。'newrelic.ymlを配置)
  3. ベンチマーカーを実行

詳しくは ttps://ohbarye.hatenablog.jp/entry/2020/07/22/newrelic-is-cool-for-isucon にまとめているのでご参照ください。

期待する挙動

同一の手順を実行した際に、RuntimeErrorが発生しない。

その他わかっていること

  • rackupコマンドで起動時にサーバをpumaでなくwebrickを指定すると再現しない
  • rackupコマンドで起動時に環境をdevelopment以外に指定すると再現しない
  • web server起動時にrackupコマンドでなくpumaコマンドを利用すると再現しない

rackupdevelopment 環境で起動した際にのみ足されるRack middlewaresと、newrelic_rpm の組み合わせ、かつマルチスレッド環境下でのみ再現すると推測。

2 Likes

@ohbarye さん、投稿ありがとうございます。

APM Agentをセットアップした際に発生した予期せぬ挙動については、Agentのログレベルをdebugに設定し、その際のログに詳細が記録されている可能性があります。
https://docs.newrelic.co.jp/docs/agents/ruby-agent/troubleshooting/generating-logs-troubleshooting-ruby

すでに回避できているとのことなので手間になってしまいますが、事象が発生した際はdebugレベルのAgentのログファイルをいただけますでしょうか。

@ttanaka さん、返信ありがとうございます。

環境を再構築して再現し、ログファイル(newrelic_agent.log)をdebugレベルで取得してみました。
こちらはどのように共有すればよいでしょうか?(ライセンスキーも含まれるためpublicな場所に配置するのは良くないかなと思いまして)

RuntimeError: can't add a new key into hash during iterationというメッセージのエラーはマルチスレッド環境下でhashに対する競合が起きたときに発生すると考えられます。いくつかの原因が考えられますが、例えば env を反復処理している箇所が考えられます。似たようなエラーは報告されておりますが、newrelic_apm にそのような箇所がなく、3rd partyのgemなどに含まれていると考えております。今回のケースであれば、おそらくdevelopment時に追加されるrack middlewareにそのようなコードがあるのではないかと推測されます。
現状、New Relic APMはそのようなコードが起因となる問題を直接的には対応できません。その代わりに、newrelic.yml にて disable_middleware_instrumentation をtrueにすることで、ミドルウェアの計測を無効化し、このエラーを発生しないようにすることができます。
https://docs.newrelic.co.jp/docs/agents/ruby-agent/configuration/ruby-agent-configuration#disabling

調査ありがとうございます。
disable_middleware_instrumentation 設定については存じてなかったので参考になりました。

クローズさせていただきますね。