この記事は NewRelicアドベントカレンダー2022 の 25日目の記事です。

はじめに

Chatwork のサーバーサイド開発部の @shi_no_oit です

現在 Chatwork では、PHPでのシステムを EC2 → Kubernetes に移行する取り込みを行なっております。

以前からシステムの大部分は Kubernetes 環境への移行が完了していたのですが、バッチ周りのシステムがまだ EC2 環境に残されており、移行に伴ってバッチのメトリクスを収集するための NewRelic Agent（NewRelic APM Agent 以降は NewRelic Agent と記載）をどのようにデプロイするか？を公式ブログにも投稿されている、コンテナ環境におけるPHPエージェントの構成パターンを元に検証したものです

検証と並行して記事を執筆しているため、まだプロダクション環境での運用は始まっていないという前提で読んでいただけると幸いです

現在のインフラ構成

参考に Chatwork でのインフラ構成は記載しておきます、あくまでPHP部分のみですが、以下のようになっています

EC2 環境
- 複数プロセスで起動できるもの、シングルプロセスでしか起動できないもの等、形式に応じて EC2 サーバーで実行されています
- 同じようにスケールしないサーバーが複数あるのは、処理の重いものはサーバーとして分離しているためです
Kubernetes（EKS）環境
- 現在はバッチは EC2 で実行しているため、Webサーバーのみ
- Kubernetes は EKS で運用中
- 1つの Node に対して複数の Web アプリケーションがありますが、接続先の NewRelic Agent は同じです

本記事には不要のため、アプリケーションサーバーのみ記載してますが実際には RDS や DynamoDB、Redis、SQS 、PHP以外で書かれたマイクロサービス等様々なものを利用しています

前提条件

はじめにに記載のある通り、現在検証中でプロダクション環境で動作させたものではありません
現行のシステムではPHPのアプリケーションのログの収集に、NewRelic を利用していています
Webシステムはすでに Kubernetes 上で運用されており、DeamonSet で NewRelic Agent が各ノードにデプロイされている
バッチ（キューワーカー、ワンショットのジョブ等）だけがEC2で運用されており、これを Kubernetes に移行して NewRelic でメトリクスを計測したい

実現したいこと

実現したいことは非常にシンプルで、キューワーカーのメッセージの処理数や1メッセージの処理にかかる時間を計測したい、NewRelic上でエラーを把握したいといったものになります

処理したメッセージ数の計測については、移行期間は EC2 環境と Kubernetes 環境で並行してキューワーカーを起動させ、不具合がないことや1プロセスで捌くことができるメッセージ数の見積もりに利用しようと考えています

また、newrelic_notice_error という関数でアプリケーション上から NewRelic にエラーを通知できますが、こちらはトランザクション内でコールする必要があるため、エラーを送るには計測範囲に含まれている必要があります

ワンショットのジョブは場合によっては1トランザクションしか存在しないため必ず計測結果が送られていることが望ましいです

構成を変更しようとした経緯

Webアプリケーションを監視する NewRelic Agent は Kubernetes の各Node上に DeamonSet でデプロイされていたため、移行を始めた当初は同じように接続する予定でした

しかし NewRelic の PHP Agent には送信できるトランザクション数に制限があり、10,000/分以上のトランザクションが発生すると、データが消失する仕様となっているため、各 Node に展開される Pod の組み合わせ次第ではこの上限を超えることから、バッチ環境のみ NewRelic Agent を別の構成にするとどのようになるかを検証することになりました

※ リアルタイム・ストリーミングのページに言語によって送信されるイベント数（NewRelic ではトランザクションはイベントの1種になる）の最大が異なること、1分間に送信できる最大のイベント数が10,000件であることが書かれてます。 PHP の場合は公式のGithubのコードにもそのように思える記述がありますがここは確証はございません。送信制限を超えた場合はデータがサンプリングされることが APM およびモバイル監視のイベント制限とサンプリングに記載されています

コンテナ環境であることから、NewRelic Agent とアプリケーションコンテナは、それぞれ別のコンテナとしてデプロイする前提で進めています

構築のパターンは、 NewRelic の公式ブログにも投稿されている、コンテナ環境におけるPHPエージェントの構成パターンを参考にしました

各パターンを試す

1. NewRelic Agent とアプリケーションを同じコンテナに入れる

このパターンについてはすでに EC2 環境で採用されていたパターンでした

引用：コンテナ環境におけるPHPエージェントの構成パターン 1. 同一コンテナパターン

ただし、

コンテナ環境で実行されるキューワーカーがプロセスとして常駐すること
デプロイに伴う Pod のローリングアップデート、HPA におけるオートスケール、Node の drain 等によって、アプリケーションでシグナルを受け取って、Graceful Shutdown を行う必要があること
コンテナのメモリやCPUが、NewRelic Agent と共有するため必要な Pod のリソース量を見つもりづらい

ということから、1コンテナ、1プロセスの原則を守った方が良いと考え、このパターンは不採用としました

2. 別コンテナ（デーモン共通化）パターン

ロードバランサで NewRelic Agent を共有するパターンのようです

引用：コンテナ環境におけるPHPエージェントの構成パターン 2. 別コンテナ（デーモン共通化）パターン

このパターンでは Pod ごとに NewRelic Agent をデプロイすることがなく、アプリケーションは NewRelic Agent の接続先だけを知っていればアプリケーションコンテナを独立してデプロイできます

しかし、過去に社内の別システムで内部LBを使って分散した時に、リクエストが均等に分散されずに負荷に偏りがでるという問題が発生したことがありました。

そのためこのパターンを採用するには、均等に各エージェントにリクエストが分散されるアルゴリズムが必要という社内での見解になりました

現在の Kubernetes クラスターはEKSで運用しているため、NLB等を利用してリクエストを均等に分散できれば、NLBへの総リクエスト数を監視してスケールすることで上限をオーバーせず、トランザクションを計測できるものと思われます

3. NewRelic をサイドカーコンテナとしてデプロイする

Kubernetes で運用しているため、一番最初に検討したパターンでした

サイドカーで NewRelic Agent をデプロイするため、「別コンテナ（デーモン共通化）パターン」と同じくアプリケーションの独立性を保つことができ、1Pod（1コンテナ）で捌くことができるメッセージ数が上限を超えなければ確実に計測することが可能です

図3 引用：コンテナ環境におけるPHPエージェントの構成パターン Option構成. サイドカーパターン

このパターンについては、NewRelic Agnet の挙動の確認を兼ねて検証した時に幾つか考慮すべき点がありました

デプロイ時にバッチのアプリケーションが NewRelic Agent が起動するまで待つ必要がある

PHPのバッチでは、アプリケーションコンテナのエントリーポイントでPHPのバッチのアプリケーションを起動させていました。そのため、NewRelic にトランザクション等のデータが送信されるにはアプリケーションコンテナから、NewRelic Agent へ接続できる必要があります

PHP用の NewRelic Agent は newrelic/php-daemon として、DockerHub で配布されているので図3 のように PHP と NewRelic Agent を 1つの Pod とデプロイするのですが、NewRelic Agent は起動するまでに少し時間を要します

実際に1つの Pod として、デプロイしてみると以下のようにエントリーポイントが先に実行されています

※ コンテナ名は公開用に置き換えています

2022-12-20T03:48:15.084282211Z test-worker [info] Start Worker.
2022-12-20T03:48:15.306845884Z newrelic-agent 2022/12/20 03:48:15.306733 (1) Info: New Relic daemon version 10.3.0.315-4571e4f3699a [listen="test-worker:31339" startup=init pid=1 ppid=0 uid=0 euid=0 gid=0 egid=0 runtime="go1.9.7" GOMAXPROCS=8 GOOS=linux GOARCH=amd64]
2022-12-20T03:48:15.336791375Z newrelic-agent 2022/12/20 03:48:15.336722 (19) Info: New Relic daemon version 10.3.0.315-4571e4f3699a [listen="test-worker:31339" startup=init pid=19 ppid=1 uid=0 euid=0 gid=0 egid=0 runtime="go1.9.7" GOMAXPROCS=8 GOOS=linux GOARCH=amd64]
2022-12-20T03:48:15.336812244Z newrelic-agent 2022/12/20 03:48:15.336768 (19) Info: collector configuration is &{CAFile: CAPath: Proxy:}
2022-12-20T03:48:15.337667752Z newrelic-agent 2022/12/20 03:48:15.337587 (19) Info: daemon listening on :31339
2022-12-20T03:48:56.770788397Z newrelic-agent 2022/12/20 03:48:56.770714 (19) Info: Reporting to:{NewRelicのURL}
2022-12-20T03:48:56.771282612Z newrelic-agent 2022/12/20 03:48:56.771230 (19) Info: app '{アプリケーション名}' connected with run id {NewRelicのID}

この場合 Kubernetes では、Probe （Liveness Probe、Readiness ProbeおよびStartup Probeを使用する）やコンテナライフサイクルイベント等の機能を用いて、依存されている側のコンテナの起動を待って、処理を開始する必要があるのですが、バッチという性質上コンテナのエントリーポイントでアプリケーションを起動するため、Probe やコンテナライフサイクルイベントの結果を待たずに先にエントリーポイントで定義されているアプリケーションが起動してしまいます

そのため、厳密に起動順を制御するにはアプリケーションのエントリーポイントで NewRelic Agent へ接続できることを確認してからバッチを起動する必要があります

この待ち時間の検証を PHP のコードを使ってしまうと自動で NewRellic の PHP拡張から接続を試行してしまうので検証の際はシェルスクリプトで起動待ちを行うことにしました

社内では ArgoCD ベースで EKS にデプロイしているため、レプリカ数を0にした上でキューにメッセージを追加し、レプリカを起動してみました

シェルスクリプト

until nc -zv localhost 31339; do
  echo 'Waiting for connection to NewRelic...'
  sleep 5
done

echo 'Successfully connected to NewRelic.'

echo 'Start worker.'

// 実際のPHPのバッチ（キューワーカー）を起動

しかしこの方法ではNewRelic にトランザクションは計測されてませんでした、アプリケーションのログを見る限り接続されているように見受けられます

// アプリケーション
2022-12-20T11:53:14.492693719Z test-worker Ncat: Connection to ::1 failed: Connection refused.
2022-12-20T11:53:14.492704530Z test-worker Ncat: Trying next address...
2022-12-20T11:53:14.492706810Z test-worker Ncat: Connection refused.
2022-12-20T11:53:14.500656541Z test-worker Waiting for connection to NewRelic...
2022-12-20T11:53:19.505508919Z test-worker Ncat: Version 7.80 ( https://nmap.org/ncat )
2022-12-20T11:53:19.510448916Z test-worker Ncat: Connected to ::1:31339.
2022-12-20T11:53:19.510467427Z test-worker Ncat: 0 bytes sent, 0 bytes received in 0.01 seconds.
2022-12-20T11:53:19.511131155Z test-worker Successfully connected to NewRelic.
2022-12-20T11:53:19.511143108Z test-worker Start worker.
2022-12-20T11:53:19.625255371Z test-worker [info] 2022-12-20 20:53:19 Start Worker.
2022-12-20T11:53:19.824560983Z test-worker [info] Id: 174 の処理が完了しました！
2022-12-20T11:53:19.913721359Z test-worker [info] Id: 175 の処理が完了しました！

// NewRelic Agent
2022-12-20T11:53:14.781711687Z newrelic-agent 2022/12/20 11:53:14.781627 (1) Info: New Relic daemon version 10.3.0.315-4571e4f3699a [listen="test-worker:31339" startup=init pid=1 ppid=0 uid=0 euid=0 gid=0 egid=0 runtime="go1.9.7" GOMAXPROCS=8 GOOS=linux GOARCH=amd64]
2022-12-20T11:53:14.812309860Z newrelic-agent 2022/12/20 11:53:14.812242 (20) Info: New Relic daemon version 10.3.0.315-4571e4f3699a [listen="test-worker:31339" startup=init pid=20 ppid=1 uid=0 euid=0 gid=0 egid=0 runtime="go1.9.7" GOMAXPROCS=8 GOOS=linux GOARCH=amd64]
2022-12-20T11:53:14.812337005Z newrelic-agent 2022/12/20 11:53:14.812289 (20) Info: collector configuration is &{CAFile: CAPath: Proxy:}
2022-12-20T11:53:14.813479580Z newrelic-agent 2022/12/20 11:53:14.813406 (20) Info: daemon listening on :31339
2022-12-20T11:53:20.812699211Z newrelic-agent 2022/12/20 11:53:20.812608 (20) Info: Reporting to: https://rpm.newrelic.com/accounts/{アカウントID}/applications/{アプリケーションID}
2022-12-20T11:53:20.813322887Z newrelic-agent 2022/12/20 11:53:20.813259 (20) Info: app '{アプリケーション名}' connected with run id '{ID}'
2022-12-20T11:53:20.900447961Z newrelic-agent 2022/12/20 11:53:20.900370 (20) Info: Reporting to: https://rpm.newrelic.com/accounts/{アカウントID}/applications/{アプリケーションID}
2022-12-20T11:53:20.900992749Z newrelic-agent 2022/12/20 11:53:20.900926 (20) Info: app '{アプリケーション名}' connected with run id '{ID}'

PHP Agent のログは以下のようになっています

※ ログの保存先はトラブルシューティングのためのログの生成 (PHP)を参考にしてください

ユーザー名@コンテナ名:/$ cat /var/log/newrelic/php_agent.log
2022-12-20 11:53:19.523 +0000 (19 19) info: attempt daemon connection via 'localhost:31339'
2022-12-20 11:53:19.523 +0000 (19 19) info: New Relic 9.17.1.301 ("xigua" - "6498785b65c7") [daemon='localhost:31339'  php='8.0.11' zts=no sapi='cli'  pid=19 ppid=7 uid=65534 euid=65534 gid=65534 egid=65534 backtrace=yes startup=init os='Linux' rel='5.4.209-116.367.amzn2.x86_64' mach='x86_64' ver='#1 SMP Wed Aug 31 00' node='test-worker']

1件目のトランザクションが報告されない問題

検証途中にハマったのが、NewRelic の PHP Agent では1件目のトランザクションを報告しないという仕様でした

参考：最初のPHPトランザクションは報告されない

そのため、最初のトランザクションが報告されるようにするには実際の計測部分より前にどのようなものでも良いので、ダミーのトランザクションを作成して、バッチの1件目のトランザクションが実際には2件目になるようにしておく必要があります

最初のダミーのトランザクションを送信しても、少し待たないと送信されない

これはバッチ処理で次のトランザクションが発生するのが比較的早いからなのかは分かりませんが、この仕様に対処するためにダミーのトランザクションを送信した後に10秒ほど sleep を入れることにしました

そうすることでイベントが計測されるようになりました

2022-12-20T11:03:20.360086789Z test-worker Ncat: Connection to ::1 failed: Connection refused.
2022-12-20T11:03:20.360097402Z test-worker Ncat: Trying next address...
2022-12-20T11:03:20.360160762Z test-worker Ncat: Connection refused.
2022-12-20T11:03:20.360623926Z test-worker Waiting for connection to NewRelic...
2022-12-20T11:03:25.362943049Z test-worker Ncat: Version 7.80 ( https://nmap.org/ncat )
2022-12-20T11:03:25.367876428Z test-worker Ncat: Connected to ::1:31339.
2022-12-20T11:03:25.367885378Z test-worker Ncat: 0 bytes sent, 0 bytes received in 0.01 seconds.
2022-12-20T11:03:25.368530298Z test-worker Successfully connected to NewRelic.
2022-12-20T11:03:25.368532576Z test-worker Start worker.
2022-12-20T11:03:25.487642593Z test-worker [info] 2022-12-20 20:03:25 [info] Start Worker.
2022-12-20T11:03:35.488587882Z test-worker [info] 2022-12-20 20:03:35 [info] トランザクションを送信するために10秒待ちます
2022-12-20T11:03:35.697621454Z test-worker [info] 2022-12-20 20:03:35 [info] Id: 175 の処理が完了しました！ [info]
2022-12-20T11:03:35.796987323Z test-worker [info]2022-12-20 20:03:35 [info] Id: 174 の処理が完了しました！ [info]

同じ時間に計測されている

接続待ちを行わない場合にトランザクションを送信するとどうなるのか？

接続待ちを行わない場合は接続に成功したタイミングで送信されていなかったトランザクションが送信されるのか？というところが気になり実際に試してみました

接続確認を行なっても少し待たないと接続されないため、結果的に近いものになりますがこちらも送信されませんでした

NewRelic の PHP Agent のログから接続に失敗している旨が伺えます

ユーザー名@アプリケーションコンテナ名 $ cat /var/log/newrelic/php_agent.log
2022-12-20 11:25:31.840 +0000 (7 7) info: attempt daemon connection via 'localhost:31339'
2022-12-20 11:25:31.840 +0000 (7 7) info: New Relic 9.17.1.301 ("xigua" - "6498785b65c7") [daemon='localhost:31339'  php='8.0.11' zts=no sapi='cli'  pid=7 ppid=1 uid=65534 euid=65534 gid=65534 egid=65534 backtrace=yes startup=init os='Linux' rel='5.4.209-116.367.amzn2.x86_64' mach='x86_64' ver='#1 SMP Wed Aug 31 00' node='test-worker']
2022-12-20 11:25:31.851 +0000 (7 7) warning: failed to connect to the newrelic-daemon.  The agent expects a daemon to be started externally. Please refer to: https://newrelic.com/docs/php/newrelic-daemon-startup-modes#daemon-external
2022-12-20 11:25:31.946 +0000 (7 7) warning: daemon connect(fd=6 host=localhost, port=31339) returned -1 errno=ECONNREFUSED. Failed to connect to the newrelic-daemon. Please make sure that there is a properly configured newrelic-daemon running. For additional assistance, please see: https://newrelic.com/docs/php/newrelic-daemon-startup-modes

アプリケーションのログ

2022-12-20T11:25:31.946719352Z test-worker [info] Start Worker.
2022-12-20T11:25:41.947179256Z test-worker [info] トランザクションを送信するために10秒待ちます
2022-12-20T11:25:42.148346584Z test-worker [info] Id: 176 の処理が完了しました！
2022-12-20T11:25:42.245980770Z test-worker [info] Id: 174 の処理が完了しました！
2022-12-20T11:29:30.473454239Z test-worker [info] Id: 175 の処理が完了しました！

2022-12-20T11:25:32.000594593Z newrelic-agent 2022/12/20 11:25:32.000501 (1) Info: New Relic daemon version 10.3.0.315-4571e4f3699a [listen="test-worker:31339" startup=init pid=1 ppid=0 uid=0 euid=0 gid=0 egid=0 runtime="go1.9.7" GOMAXPROCS=8 GOOS=linux GOARCH=amd64]
2022-12-20T11:25:32.030092142Z newrelic-agent 2022/12/20 11:25:32.030026 (18) Info: New Relic daemon version 10.3.0.315-4571e4f3699a [listen="test-worker:31339" startup=init pid=18 ppid=1 uid=0 euid=0 gid=0 egid=0 runtime="go1.9.7" GOMAXPROCS=8 GOOS=linux GOARCH=amd64]
2022-12-20T11:25:32.030125846Z newrelic-agent 2022/12/20 11:25:32.030072 (18) Info: collector configuration is &{CAFile: CAPath: Proxy:}
2022-12-20T11:25:32.030354842Z newrelic-agent 2022/12/20 11:25:32.030305 (18) Info: daemon listening on :31339
2022-12-20T11:25:43.404467555Z newrelic-agent 2022/12/20 11:25:43.404355 (18) Info: Reporting to: https://rpm.newrelic.com/accounts/{アカウントID}/applications/{アプリケーションID}
2022-12-20T11:25:43.404892496Z newrelic-agent 2022/12/20 11:25:43.404838 (18) Info: app '{アプリケーション名}' connected with run id '{ID}'

ただし、最初に接続されていなくても接続可能になった時点からデータは送信されるようでした

NRQL で確認したデータ

おそらく推測ですが、「トランザクションを送信するために10秒待ちます」で Sleep をかける前にダミーのトランザクションを送信しているので、最初の処理のトランザクションは時間的には送信されているように見えますが、NewRelic Agent 的には送信されない1件目のトランザクションとなってしまっているのだと思います

Podの制御が複雑になる

NewRelic Agent に接続できない状態で、アプリケーションコンテナが実行され続けるとデータが NewRelic に送信されなくなるため、NewRelic Agent のコンテナが落ちた場合や接続できない場合は起動までバッチの処理を続けない等の対策が必要になります

このケースでも起動順序の制御と同様に Probe 等のヘルスチェック的な監視では Pod のステータスが runnning にならないだけでエントリーポイントのアプリケーションは起動し続けるため、厳密にデータを送りたい場合は、アプリケーションコードで直接 NewRelic Agent への接続を確認し続ける必要があり、アプリケーションと密結合になってしまうためにサイドカーパターンとしては少し使いづらいように感じました

結論

今のところは 2の「別コンテナ（デーモン共通化）パターン」を採用するを使ってみようと思っています

実際にこのパターンを試すかは今も移行を続けている段階になるため今後の検討事項になりますが、メッセージ数が多いバッチについてはあえて全件計測しないという方法を採用する可能性もあります

Webアプリケーションの場合は、ステータスが Probe のヘルスチェックが通らないとロードバランサのリクエストが割り振られないため、 Kubernetes の機能だけを使って制御することもできそうですがエントリーポイントで起動するバッチのケースだと扱いづらなぁという感想でした

どなたか知見をお持ちの方がいればコメント頂けると嬉しいです