概要
原著者の許諾を得て翻訳・公開いたします。
- 英語記事: 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 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プロセスのpidは1でした。
$ 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の方がユーザーフレンドリーだからです。
他にも便利なスニペットをご存知でしたらぜひお知らせください。本記事に追加したいと思います。