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

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%使い切っていたのです。🧙‍の最初のお手柄でした。

関連記事

はじめての正規表現とベストプラクティス10: 危険な「Catastrophic Backtracking」前編

TestProf: Ruby/Railsの遅いテストを診断するgem（翻訳）