概要

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

• 英語記事:Debugging Ruby processes in Kubernetes · Kir Shatrov
• 原文公開日: 2018/04/13
• 著者:Kir Shatrov --Shopifyのプロダクションエンジニアです。

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 podsNAME                         READY     STATUS    RESTARTS   AGEsecretland-c796bf9df-gmt97   1/1       Running   0          13dsecretland-4a145b44d-6xw11   1/1       Running   0          13d

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

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

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

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

$ kubectl exec -i -t secretland-c796bf9df-gmt97 /app/bin/rails consoleLoading 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/v1beta1kind: Deploymentmetadata:  name: secretland  labels:    app: secretlandspec:  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プロセスのpidは1でした。

$ kubectl exec -i -t secretland-8dc689458-jstp2 /bin/bashroot@secretland-8dc689458-jstp2:/app# rbspy record --pid 1Time since start: 9s. Press Ctrl+C to stop.Summary of profiling data so far:% self  % total  name100.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 NodeNode:           gke-kirs-jobs-default-pool-4a145b44-t690/10.128.0.3Node-Selectors:  <none>$ gcloud compute ssh gke-kirs-jobs-default-pool-4a145b44-t690 --zone us-central1-akir@gke-kirs-jobs-default-pool-4a145b44-t690 ~ $ docker psCONTAINER ID        IMAGE                                                                                                                    COMMAND                  CREATED             STATUS              PORTS               NAMESfc10153238a0        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/bashroot@secretland-8dc689458-jstp2:/app# ps auxUSER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMANDroot         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/bashroot        53  0.0  0.0  36636  2808 ?        R+   02:31   0:00 ps auxroot@secretland-8dc689458-jstp2:/app# gdb --pid 1GNU 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:185185     ../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でメモリアロケーションをプロファイリングする（翻訳）

関連記事