Rails: Kubernetes内のRubyプロセスをrbspyでデバッグする(翻訳)

概要

原著者の許諾を得て翻訳・公開いたします。

Rails: Kubernetes内のRubyプロセスをrbspyでデバッグする(翻訳)

コンテナ化されていないアプリのデバッグはまったくもって簡単です。ホストにssh接続してプロセスに対してrbspyだのstraceだのgdbだのを駆使するもよし、rails consoleでproduction環境で何かを再現するもよしです。

Kubernetesだとデバッグがつらくなる理由

プロセスがコンテナ内で実行されていると、デバッグが少しばかり面倒になります。最初にdocker exec--interactive --ttyの追加も忘れずに!)でコンテナに入る必要がありますし、実行中のプロセスのinspectはコンテナ内でないとできません。

Docker内でrbspyを使おうとする場合はさらにトリッキーになります。ptrace(rbspyが依存しているシステムコールの一種)はデフォルトではコンテナ内で利用できないからです。--cap-add=SYS_PTRACEを指定してコンテナを実行しておく必要があり、そうしておかないとdocker execで入ってrbspyを実行できません。

Kubernetesの便利スニペット

続いて、Kubernetesについてちょっとしたコツをご説明します。本記事は、私が毎日利用しているスニペットのコレクションをご紹介するという形で書かれており、Rubyプロセスを実行して状態を調べる必要が生じた場合にはこれらのスニペットを使っています。

$ kubectl get pods
NAME                         READY     STATUS    RESTARTS   AGE
secretland-c796bf9df-gmt97   1/1       Running   0          13d
secretland-4a145b44d-6xw11   1/1       Running   0          13d

前回の記事で用いたsecretlandアプリの複製が2つあります。

コンテナに入ってみましょう。

$ kubectl exec -i -t secretland-c796bf9df-gmt97 /bin/bash
root@secretland-c796bf9df-gmt97:/app# ls
Dockerfile  Gemfile  Gemfile.lock  README.md  Rakefile  app  bin  config  config.ru  db  lib  log  package.json  public  script  storage  test  tmp  vendor
root@secretland-c796bf9df-gmt97:/app# bin/rails console
Loading production environment (Rails 5.2.0.rc2)
irb(main):001:0>

次のようにRailsコンソールを直接実行することもできます。

$ kubectl exec -i -t secretland-c796bf9df-gmt97 /app/bin/rails console
Loading production environment (Rails 5.2.0.rc2)
irb(main):001:0>

rbspy

rbspyは、先ごろJulia Evansが公開したRubyプログラム向けのサンプリングプロファイラです。rbspyはRuby世界でここ数年求められていた素晴らしいツールであり、Juliaのおかげでこうした作業がとても快適になりました。

あるKubernetes Pod内で実行中のプロセスに対してrbspyを使う方法をご説明します。最初に、rbspyがptrace(3)に依存していることを知っておく必要があります。ptraceが有効になっているコンテナを実行するには、コンテナにSYS_PTRACE特権を付与する必要があります。Deployment specのsecurityContext.capabilitiesフィールドをご覧ください。

apiVersion: extensions/v1beta1
kind: Deployment
metadata:
  name: secretland
  labels:
    app: secretland
spec:
  selector:
    matchLabels:
      app: secretland
  template:
    metadata:
      labels:
        app: secretland
    spec:
      containers:
      - image: kirshatrov/secretland:v1
        name: rails
        ports:
        - containerPort: 3000
        securityContext:
          capabilities:
            add:
            - SYS_PTRACE # <-- この特権

低速なエンドポイントをエミュレーションするために、フィボナッチ数を計算するサンプルアクションを作成しました。このようにして、Ruby世界でどのプロセスが時間を使っているかを観察できます。

新しいDeployment specが配置されれば、そのWebコンテナにexecをかけてrbspyを試せます。少なくとも私の場合、Pumaプロセスのpid1でした。

$ kubectl exec -i -t secretland-8dc689458-jstp2 /bin/bash
root@secretland-8dc689458-jstp2:/app# rbspy record --pid 1
Time since start: 9s. Press Ctrl+C to stop.
Summary of profiling data so far:
% self  % total  name
100.00   100.00  <c function> - unknown
  0.00    79.41  block in start! - /usr/local/bundle/gems/puma-3.11.3/lib/puma/thread_pool.rb
  0.00    20.59  run_internal - /usr/local/bundle/gems/puma-3.11.3/lib/puma/reactor.rb
  0.00    20.59  block in run_in_thread - /usr/local/bundle/gems/puma-3.11.3/lib/puma/reactor.rb

ブラウザで/slowpathエンドポイントを表示すると、このプロファイルが変化します。

% self  % total  name
 70.56   100.00  <c function> - unknown
 29.44    29.44  fibonacci - /app/app/controllers/helloworld_controller.rb
  0.00    67.89  block in start! - /usr/local/bundle/gems/puma-3.11.3/lib/puma/thread_pool.rb
  0.00    32.11  block in spawn_thread - /usr/local/bundle/gems/puma-3.11.3/lib/puma/thread_pool.rb
  0.00    30.97  process_client - /usr/local/bundle/gems/puma-3.11.3/lib/puma/server.rb
  0.00    30.97  block in run - /usr/local/bundle/gems/puma-3.11.3/lib/puma/server.rb
  0.00    29.44  tagged - /usr/local/bundle/gems/activesupport-5.2.0.rc2/lib/active_support/tagged_logging.rb
  0.00    29.44  slow - /app/app/controllers/helloworld_controller.rb
  0.00    29.44  serve - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_dispatch/routing/route_set.rb
  0.00    29.44  serve - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_dispatch/journey/router.rb
  0.00    29.44  send_action - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_controller/metal/basic_implicit_render.rb
  0.00    29.44  run_callbacks - /usr/local/bundle/gems/activesupport-5.2.0.rc2/lib/active_support/callbacks.rb
  0.00    29.44  process_action - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_controller/metal/rescue.rb
  0.00    29.44  process_action - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_controller/metal/rendering.rb
  0.00    29.44  process_action - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_controller/metal/params_wrapper.rb
  0.00    29.44  process_action - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/action_controller/metal/instrumentation.rb
  0.00    29.44  process_action - /usr/local/bundle/gems/actionpack-5.2.0.rc2/lib/abstract_controller/callbacks.rb

やった!動きました。

Dockerに到達するには

Dockerデーモンを直接触りたい場合はどうすればよいでしょうか?describe podすると、Dockerデーモンが実行中のNodeが表示されるので、そのインスタンスにsshで接続します。

$ kubectl describe pod secretland-8dc689458-jstp2 | grep Node
Node:           gke-kirs-jobs-default-pool-4a145b44-t690/10.128.0.3
Node-Selectors:  <none>

$ gcloud compute ssh gke-kirs-jobs-default-pool-4a145b44-t690 --zone us-central1-a

kir@gke-kirs-jobs-default-pool-4a145b44-t690 ~ $ docker ps
CONTAINER ID        IMAGE                                                                                                                    COMMAND                  CREATED             STATUS              PORTS               NAMES
fc10153238a0        kirshatrov/secretland@sha256:2e6d8341f51ebe7393d2a7c770c29fbaf959e3317b628d0dc5ebbb19c923d29c                            "rails server -b 0

私はGoogle Cloudを使っていますので、直接sshする代わりにgcloud compute sshを使っています。

gdb

gdbは、MRIコールスタックをダンプする場合(Rubyプロセスが立ち往生してしまう理由を調べたい場合など)に役に立つことがあります。同僚のScottが作成したコールスタックダンプ用のscriptをご覧ください。

私はKubernetes Podからgdbを正しく実行する方法をまだ見つけられずにいます。gdbがRubyのシンボルを探索できないためです。

$ kubectl exec -i -t secretland-8dc689458-jstp2 /bin/bash
root@secretland-8dc689458-jstp2:/app# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  1.5 709816 58080 ?        Ssl  Apr07   0:08 puma 3.11.3 (tcp://0.0.0.0:3000) [app]
root        43  0.0  0.0  18204  3280 ?        Ss   02:29   0:00 /bin/bash
root        53  0.0  0.0  36636  2808 ?        R+   02:31   0:00 ps aux
root@secretland-8dc689458-jstp2:/app# gdb --pid 1
GNU gdb (Debian 7.12-6) 7.12.0.20161007-git
...
Attaching to process 1
[New LWP 6]
...
[New LWP 16]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
185     ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S: No such file or directory.

とは言うものの、最近リリースされたrbspyのおかげで、gbdを前ほど頻繁には使わなくなるのではないかと思えます。rbspyはgdbと違ってプロセスを一時停止しませんし、rbspyの方がユーザーフレンドリーだからです。

他にも便利なスニペットをご存知でしたらぜひお知らせください。本記事に追加したいと思います。

関連記事

Rails 5.2のcredential機能をKubernetesで使う(翻訳)

Ruby: eBPFでメモリアロケーションをプロファイリングする(翻訳)

デザインも頼めるシステム開発会社をお探しならBPS株式会社までどうぞ 開発エンジニア積極採用中です! Ruby on Rails の開発なら実績豊富なBPS

この記事の著者

hachi8833

Twitter: @hachi8833、GitHub: @hachi8833 コボラー、ITコンサル、ローカライズ業界、Rails開発を経てTechRachoの編集・記事作成を担当。 これまでにRuby on Rails チュートリアル第2版の半分ほど、Railsガイドの初期翻訳ではほぼすべてを翻訳。その後も折に触れてそれぞれ一部を翻訳。 かと思うと、正規表現の粋を尽くした日本語エラーチェックサービス enno.jpを運営。 実は最近Go言語が好き。 仕事に関係ないすっとこブログ「あけてくれ」は2000年頃から多少の中断をはさんで継続、現在はnote.muに移転。

hachi8833の書いた記事

週刊Railsウォッチ

インフラ

ActiveSupport探訪シリーズ