Rails: productionでCPU usageが100%になる問題をデバッグする(翻訳)

概要 原著者の許諾を得て翻訳・公開いたします。 英語記事: Debugging 100% CPU usage in production Ruby on Rails systems 原文公開日: 2018/01/18 著者: Sam Saffron — Discourseの共同創業者であり、Stack Overflowでの開発経験もあります。 Rails: productionでCPU usageが100%になる問題をデバッグする(翻訳) production環境のRailsシステムでCPU usageの上昇をデバッグするときはどうやっていますか? 今日、ある顧客のコンテナでCPU usageが異常に高くなっていることに気づきました。 # top -bn1 190 discour+ 20 0 2266292 205128 15656 S 86.7 0.3 9377:35 ruby # ps aux discour+ 190 19.4 0.3 2266292 207096 ? Sl 2017 9364:38 sidekiq 5.0.5 discourse [1 of 5 busy] どうもsidekiqのジョブが詰まっているようです。 詰まっている場所はどこでしょうか。 普通ならそこで話はおしまいで、次のような他の疑問に進むところです。 staging環境やdevelopment環境で再現できるか? 最近変更されたコードはどれか? perf traceでろくな情報が取れないのはなぜか? Sidekiqのログ出力はどのぐらいイケてるか? 魔法の占い杖はどこかにないのか? Julia Evansが取り組んでいる素敵なプロファイラを使えば、この種の問題の回答をたちどころに得ることができます。しかしそれまでの間、さしあたって何か打つ手はないものでしょうか? rbtrace + stackprof DiscourseのGemfileにはrbtraceとstackprofが常備されています。 gem ‘rbtrace’ gem ‘stackprof’, require: false 私たちのproduction環境ではrbtraceを常備しているので、多種多様なデバッグをproductionレベルで行えます。stackprofは必要に応じて読み込みます。 今回のような場合なら以下を実行すれば一発です。 # rbtrace -p 190 -e ‘Thread.new{ require “stackprof”; StackProf.start(mode: :cpu); sleep 2; StackProf.stop; StackProf.results(“/tmp/perf”); }’ これでstackprofをグローバルに有効にする新しいスレッドが1つ注入され、最終的に/tmp/perfにパフォーマンスデータが出力されます。 ダンプの解析は簡単です。 # stackprof /tmp/perf ================================== Mode: cpu(1000) Samples: 475 (0.63% miss rate) GC: 0 (0.00%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 473 (99.6%) 473 (99.6%) #<Class:0x00007fac08218020>::Typography.to_html_french 4 (0.8%) 1 (0.2%) #<Module:0x00007fac080c3620>.reap_connections 実は、stackprofではバックトレースの収集はもちろん、フレームグラフまで生成できるので、READMEをしっかり読んでおくことを強くおすすめします。 いたいた、犯人はこんなところにいました。 text.gsub(/(\s|)+([!?;]+(\s|\z))/, ‘ \2\3’) 正規表現がproductionでCPUを100%使い切っていたのです。🧙‍の最初のお手柄でした。 関連記事 TestProf: Ruby/Railsの遅いテストを診断するgem(翻訳)