#phpconkagawa レガシーコードにもオブザーバビリティを 〜少しずつ始めるサービス監視〜

2024/5/11 PHPカンファレンス香川2024
#phpconkagawa

https://fortee.jp/phpconkagawa-2024/proposal/adf74428-3316-444c-9680-fea1b2e42d0c

Transcript

1. レガシーコードにもオブザーバビリティを 〜少しずつ始めるサービス監視〜 in PHPカンファレンス香川2024 @yamato_sorariku #phpconkagawa 1
2. 自己紹介 @yamato_sorariku / 足利 大和 株式会社 PR TIMES バックエンドエンジニア PHPer。必要なこと、なんでもやります 推しのマネージドサービス Google Cloud - Cloud Run 猫が好き コーヒーも好き 飛行機も好き #phpconkagawa 2
3. 今回のトークの背景情報 #phpconkagawa 3
4. 今回のトークの背景情報 私がジョインしたとあるプロダクトで起きたこと/やってきたことを題材としています。 このプロダクトは 提携しているメディアサイトの記事データを収集（クロール） cronを使った定期実行 ユーザが入力したキーワードを元に自動で記事リストを作成し日次レポーティング ユーザが入力したキーワードで記事データを検索し、リストを画面に表示 といった機能をもつものです。 #phpconkagawa 4
5. 今回のトークの背景情報 記事データの収集（クロール）処理の流れ 3step ユーザが設定したキーワードを元に「分析用データ」で検索 記事リストを作成するという処理フロー #phpconkagawa 5
6. 今回のトークの背景情報 このプロダクトですが 歴史がそれなりに長いコードベース あまり整った状態とは言えない。いわゆるレガシーコード テストコードもあまりない テストコードの追加も大変 でもサービスは運用され、きちんと売上をあげていた という状態。 #phpconkagawa 6
7. 今回のトークのターゲット #phpconkagawa 7
8. 今回のトークのターゲット ・監視ってCPUとメモリとディスクの空きとかを見ることでは？と思っている方 #phpconkagawa 8
9. 今回のトークのターゲット ・監視ってCPUとメモリとディスクの空きとかを見ることでは？と思っている方 ・エラーログが出たら通知すればよい！と思っている方 #phpconkagawa 9
10. 今回のトークのターゲット ・監視ってCPUとメモリとディスクの空きとかを見ることでは？と思っている方 ・エラーログが出たら通知すればよい！と思っている方 それ、サービスが正しく提供できているかを監視できてますか？ #phpconkagawa 10
11. 今回のトークのターゲット ・監視ってCPUとメモリとディスクの空きとかを見ることでは？と思っている方 ・エラーログが出たら通知すればよい！と思っている方 それ、サービスが正しく提供できているかを監視できてますか？ 今回は、サービスの監視が不足していたプロダクトへ少しずつ監視を追加し、 オブザーバビリティを少しずつ獲得していた流れをお話します #phpconkagawa 11
12. オブザーバビリティってなに？ #phpconkagawa 12
13. オブザーバビリティってなに？ 日本語でいうと「可観測性」と呼ばれます。 システム上で何らかの異常が起こった際に、 それを通知するだけでなく、どこで何が起こったのか、 なぜ起こったのかを把握する能力を表す指標、あるいは仕組みを指します。 一般的な意味での監視とは、システム全体や一部のコンポーネントの動き、 出力を観察し続けることです。あらかじめ監視項目としきい値を設定しておき、 しきい値を超えたところでアラートを出すという仕組みです。 OSリソース監視、プロセス監視、ログ監視、死活監視なども、すべてその仕組みです。 引用元: https://newrelic.com/jp/blog/best-practices/what-is-observability-difference-from-monitoring #phpconkagawa 13
14. 例えばこのCPU使用率のグラフ #phpconkagawa 14
15. 例えばこのCPU使用率のグラフ 3回ほど、CPU使用率が80%を超えている #phpconkagawa 15
16. 例えばこのCPU使用率のグラフ 3回ほど、CPU使用率が80%を超えている しきい値を80%に設定している #phpconkagawa 16
17. 例えばこのCPU使用率のグラフ 3回ほど、CPU使用率が80%を超えている しきい値を80%に設定している しきい値を超えているのでアラートを発報！ #phpconkagawa 17
18. 例えばこのCPU使用率のグラフ 3回ほど、CPU使用率が80%を超えている しきい値を80%に設定している しきい値を超えているのでアラートを発報！ 担当者 サービスは普通に稼働してます！ CPU使用率は高いけど、問題ありません！ #phpconkagawa 18
19. 例えばこのCPU使用率のグラフ 3回ほど、CPU使用率が80%を超えている しきい値を80%に設定している しきい値を超えているのでアラートを発報！ 担当者 サービスは普通に稼働してます！ CPU使用率は高いけど、問題ありません！ これが監視 #phpconkagawa 19
20. 例えばこのグラフ #phpconkagawa 20
21. 例えばこのグラフ これは記事データの取得件数を表すグラフ #phpconkagawa 21
22. 例えばこのグラフ これは記事データの取得件数を表すグラフ 取得する記事の数が激減している #phpconkagawa 22
23. 例えばこのグラフ これは記事データの取得件数を表すグラフ 取得する記事の数が激減している 何が起こっているのか？ #phpconkagawa 23
24. 例えばこのグラフ これは記事データの取得件数を表すグラフ 取得する記事の数が激減している 何が起こっているのか？ 前段の記事リストを取得する処理も同時に右肩下がりに なっていた #phpconkagawa 24
25. 例えばこのグラフ これは記事データの取得件数を表すグラフ 取得する記事の数が激減している 何が起こっているのか？ 前段の記事リストを取得する処理も同時に右肩下がりに なっていた 前段の記事リストの取得処理が出力するログを確認 サイト側の新着記事が0件だった なので問題なし #phpconkagawa 25
26. 例えばこのグラフ これは記事データの取得件数を表すグラフ 取得する記事の数が激減している 何が起こっているのか？ 前段の記事リストを取得する処理も同時に右肩下がりに なっていた 前段の記事リストの取得処理が出力するログを確認 サイト側の新着記事が0件だった なので問題なし これがオブザーバビリティ #phpconkagawa 26
27. 始まりのお話 #phpconkagawa 27
28. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた #phpconkagawa 28
29. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた メディアサイトから記事データ収集する「クロール処理」が実行できず、 大部分のデータの収集が止まってしまった。 #phpconkagawa 29
30. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた ・cronで定義されたコマンド実行に失敗。 #phpconkagawa 30
31. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた ・cronで定義されたコマンド実行に失敗。 ・エラーログは出ていないという状況。 （終了コードが0じゃない) #phpconkagawa 31
32. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた ・cronで定義されたコマンド実行に失敗。 ・エラーログは出ていないという状況。 （終了コードが0じゃない) ・cronで実行したときの終了コードが監視できておらず、 　失敗していることに気づけなかった。 #phpconkagawa 32
33. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた このときの再発防止 #phpconkagawa 33
34. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた このときの再発防止 Mackerelのwrapを利用して、プロセスの終了コードを監視 0以外が応答されたとき、Slack通知するように。 Mackerel wrapについて https://mackerel.io/ja/docs/entry/howto/mkr/wrap #phpconkagawa 34
35. cronで定期実行している記事データ収集処理が失敗し、 データ収集が止まっていた このときの再発防止 Mackerelのwrapを利用して、プロセスの終了コードを監視 0以外が応答されたとき、Slack通知するように。 Mackerel wrapについて https://mackerel.io/ja/docs/entry/howto/mkr/wrap 日次の担当者による記事データ収集処理のログ確認運用を追加 毎朝ログを確認して、収集処理が動作していることを目視確認 #phpconkagawa 35
36. しかし悲劇は続く #phpconkagawa 36
37. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた #phpconkagawa 37
38. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた 収集した記事データの付加情報（※ 1）を収集する処理が失敗し、 処理が止まってしまった。 ※ 1: どれくらい波及された記事だったのかという情報 #phpconkagawa 38
39. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた ・cronで定義されたコマンド実行に失敗。 （終了コードが0じゃない） （前回の問題とは全然違う場所のcronだったためwrapが追加できておらず、検知できず） #phpconkagawa 39
40. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた ・cronで定義されたコマンド実行に失敗。 （終了コードが0じゃない） （前回の問題とは全然違う場所のcronだったためwrapが追加できておらず、検知できず） ・エラーログは出ていたが、設定がなくログ通知などできていなかった。 #phpconkagawa 40
41. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた このときの再発防止 #phpconkagawa 41
42. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた このときの再発防止 Mackerelのcheck-logプラグインを使って、エラーログを監視 エラーログが出力されたらSlack通知するように。 check-logプラグインについて https://mackerel.io/ja/docs/entry/plugins/check-log #phpconkagawa 42
43. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた このときの再発防止 Mackerelのcheck-logプラグインを使って、エラーログを監視 エラーログが出力されたらSlack通知するように。 check-logプラグインについて https://mackerel.io/ja/docs/entry/plugins/check-log Mackerelのwrapを利用して、プロセスの終了コードを監視 #phpconkagawa 43
44. cronで定期実行している記事の付加情報収集処理が失敗し、 処理が止まっていた このときの再発防止 Mackerelのcheck-logプラグインを使って、エラーログを監視 エラーログが出力されたらSlack通知するように。 check-logプラグインについて https://mackerel.io/ja/docs/entry/plugins/check-log Mackerelのwrapを利用して、プロセスの終了コードを監視 日次の担当者によるログ確認運用を追加 #phpconkagawa 44
45. このままではもぐらたたきゲーム……どうにかしなくてはならん #phpconkagawa 45
46. cronで実行するすべての処理に horenso を導入 #phpconkagawa 46
47. cronで実行するすべての処理に horenso を導入 コマンド実行した際の 終了コード、実行開始日時、実行完了日時、標準出力、標準エラー出力、etc... をJSONL形式でログファイルに書き出し。 このログをNew Relicに転送し、終了コードが 0(正常終了)じゃない場合はSlack通知 https://github.com/Songmu/horenso #phpconkagawa 47
48. cronで実行するすべての処理に horenso を導入 副次効果で、バッチたちの実行時間も同時に可視化！ -> パフォーマンス問題の検出で活躍 #phpconkagawa 48
49. cronで実行するすべての処理に horenso を導入 実行時間を計算するNRQL substring関数を使って、開始時刻・終了時刻をマイクロ秒に揃えて toTimestamp関数を使って、開始時刻・終了時刻をタイムスタンプに変換 その差を取って、処理時間を算出 SELECT MAX( ( toTimestamp(substring(endAt, 0, 26), 'yyyy-MM-dd\'T\'HH:mm:ss.SSSSSS') - toTimestamp(substring(startAt, 0, 26), 'yyyy-MM-dd\'T\'HH:mm:ss.SSSSSS') ) / 1000 ) AS ` 処理時間( 秒)` #phpconkagawa 49
50. サービスが正しく提供できてるか監視できてる……？ #phpconkagawa 50
51. サービスが正しく提供できてるか監視できてる……？ サーバのCPUやメモリ、ディスク使用量は監視されていてアラートもある。 cronで実行する処理はhorensoですべて監視対象にした。 正常終了しなければ通知もされる。 エラーログもある分はNew Relicに転送して監視した。 でもこれ、サービスが正しく稼働しているかを監視できているのか？ 価値をユーザに提供できていることを確認できているのか？ #phpconkagawa 51
52. まだ「もぐらたたきゲーム的なシステム監視」だった？ 想定される問題が起きたことを検知することができるが、 未知のバグでサービスに影響が出ていることを検知ができない。 #phpconkagawa 52
53. 尊敬する某氏に相談してみた yamato「監視ってどうやればいいんですかね」 #phpconkagawa 53
54. 尊敬する某氏に相談してみた yamato「監視ってどうやればいいんですかね」 某氏「サービスに起きてほしくないことを洗い出し、それが起きてないかを見れるようにしてはどう？」 #phpconkagawa 54
55. 尊敬する某氏に相談してみた yamato「監視ってどうやればいいんですかね」 某氏「サービスに起きてほしくないことを洗い出し、それが起きてないかを見れるようにしてはどう？」 yamato「なるほど」 #phpconkagawa 55
56. サービスに起きてほしくないことを検出する仕組みづくりを開始 #phpconkagawa 56
57. サービスに起きてほしくないことを検出する仕組みづくりを開始 起きてほしくないこと #phpconkagawa 57
58. サービスに起きてほしくないことを検出する仕組みづくりを開始 起きてほしくないこと 原因はなんであれ、記事データの収集処理（クローラー）が停止してしまうこと まずここに焦点を当てた #phpconkagawa 58
59. サービスに起きてほしくないことを検出する仕組みづくりを開始 起きてほしくないこと 原因はなんであれ、記事データの収集処理（クローラー）が停止してしまうこと まずここに焦点を当てた クローラーが正しく稼働しているかを観測するためのメトリクスログを追加 #phpconkagawa 59
60. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 #phpconkagawa 60
61. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 「クローラーが稼働していること」を観測できるように、 メトリクス用のログ出力を追加。 #phpconkagawa 61
62. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 「クローラーが稼働していること」を観測できるように、 メトリクス用のログ出力を追加。 サービスには影響を与えないようにシンプルなコードで でも必要な情報を書き出し（メディア名や記事のURLなどクローラーに関する情報など） #phpconkagawa 62
63. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 「クローラーが稼働していること」を観測できるように、 メトリクス用のログ出力を追加。 サービスには影響を与えないようにシンプルなコードで でも必要な情報を書き出し（メディア名や記事のURLなどクローラーに関する情報など） ログファイルに書き出し MonologのJsonFormatterを使ってJSONL形式でログ出力 New Relicなので分析しやすくするため テキストログだと正規表現で抽出するのが大変…… #phpconkagawa 63
64. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 # こんな雰囲気ですってコード class MetricsLogger { public static function action_name($context){ $log = new Logger('metrics'); $stream = new StreamHandler('logs/metrics.log', Logger::INFO); $stream->setFormatter(new JsonFormatter()); $log->pushHandler($stream); $log->info('metrics log', $context); } } #phpconkagawa 64
65. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 # こんな雰囲気ですってコード MetricsLogger::action_name([ 'media_name' => XXXX, 'crawler_type' => YYYY, 'url' => $url, 'status' => 'success', ]); #phpconkagawa 65
66. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 構成図 #phpconkagawa 66
67. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 #phpconkagawa 67
68. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 #phpconkagawa 68
69. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 記事が何件収集できているのかをビジュアライズし、状況がつかめるように。 #phpconkagawa 69
70. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 クローラーがどれくらい記事リストを取得しているか クローラーがどれくらい記事データを取得しているか クローラーがどれくらい記事データを分析データに投入しているか クローラーがどれくらい記事データの付加情報を取得しているか これからが観測できるようになったことで、 クローラー全体の稼働状況を把握できるように！ #phpconkagawa 70
71. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 迅速にクローラーで発生した問題を把握できるように #phpconkagawa 71
72. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 迅速にクローラーで発生した問題を把握できるように 実際に「分析データに投入された記事情報」が少ないことを検知した際には このメトリクスログから作成したダッシュボードを確認することで クローラーのどこで問題が起きていてが止まっているのかを判断でき、迅速な対応ができた。 #phpconkagawa 72
73. クローラーが正しく稼働しているかを観測するための メトリクスログを追加 迅速にクローラーで発生した問題を把握できるように 実際に「分析データに投入された記事情報」が少ないことを検知した際には このメトリクスログから作成したダッシュボードを確認することで クローラーのどこで問題が起きていてが止まっているのかを判断でき、迅速な対応ができた。 少しずつではあるが、オブザーバビリティの高まりを実感！ #phpconkagawa 73
74. 現状出力しているログを活用し、稼働状態を可視化する #phpconkagawa 74
75. 現状出力しているログを活用し、稼働状態を可視化する ログの中には 2024-05-11 16:00:00+0900 INFO XXXX Success: 20 などのようなINFOログが出力されているケースがあった #phpconkagawa 75
76. 現状出力しているログを活用し、稼働状態を可視化する ログの中には 2024-05-11 16:00:00+0900 INFO XXXX Success: 20 などのようなINFOログが出力されているケースがあった このログをNRQLを使って集計しダッシュボード化。 見た目で正常に稼働していることを確認できるように。 #phpconkagawa 76
77. 現状出力しているログを活用し、稼働状態を可視化する capture関数でテキストログから値を抽出 numeric関数で抽出した値を数値に変換 SUM関数で集計 # ログ（New Relic 上にあるもの） { "hostname" : "xxxxxxxxx", "level": "INFO" "message": "2024-05-11 16:00:00+0900 INFO XXXX Success: 20" } SELECT SUM( numeric( capture(`message`, r'.*Success: (?P<success>[0-9]+)') ) ) AS success, #phpconkagawa 77
78. 現状出力しているログを活用し、稼働状態を可視化する #phpconkagawa 78
79. 現状出力しているログを活用し、稼働状態を可視化する エラーは無いけど、成功数が0件が継続した際にはアラート発報が可能に。 処理が止まったことに気付けないという問題も少しずつ検知できるように！ #phpconkagawa 79
80. 今後: メトリクスログをDevOpsに活用 #phpconkagawa 80
81. 今後: メトリクスログをDevOpsに活用 クロール処理のモニタリングを開発チームだけに閉じるのではなく 関係するエンジニア以外の運用メンバーにも把握できる状態にしたい。 #phpconkagawa 81
82. 今後: メトリクスログをDevOpsに活用 クロール処理のモニタリングを開発チームだけに閉じるのではなく 関係するエンジニア以外の運用メンバーにも把握できる状態にしたい。 エンジニア以外の運用メンバーも巻き込み、 全員が自律的にサービスの状態を観測し改善していける状態を作りたい #phpconkagawa 82
83. メトリクスログをBigQueryに転送/可視化 #phpconkagawa 83
84. メトリクスログをBigQueryに転送/可視化 メトリクスログをJSONL形式書き出しているため そのまま bq load なのでBigQueryに転送することが可能。 #phpconkagawa 84
85. メトリクスログをBigQueryに転送/可視化 メトリクスログをJSONL形式書き出しているため そのまま bq load なのでBigQueryに転送することが可能。 運用視点で確認したいことなどをヒアリングし、 転送したログをLooker Studioを使ってビジュアライズしてダッシュボードを作成 #phpconkagawa 85
86. メトリクスログをBigQueryに転送/可視化 メトリクスログをJSONL形式書き出しているため そのまま bq load なのでBigQueryに転送することが可能。 運用視点で確認したいことなどをヒアリングし、 転送したログをLooker Studioを使ってビジュアライズしてダッシュボードを作成 まだお試し段階なので、きちんと運用できて成果が出たらどこかしらで発表します #phpconkagawa 86
87. まとめ #phpconkagawa 87
88. まとめ サービスは監視するだけではなく、どのようなことが起きているのかを把握 できるようにするためのオブザーバビリティが重要 #phpconkagawa 88
89. まとめ サービスは監視するだけではなく、どのようなことが起きているのかを把握 できるようにするためのオブザーバビリティが重要 レガシーコードだったとしても、売上を上げている立派な資産 レガシーコードだからオブザーバビリティを上げられないとことはなく、 できることを少しずつ小さく初めていくことが大切 #phpconkagawa 89
90. まとめ サービスは監視するだけではなく、どのようなことが起きているのかを把握 できるようにするためのオブザーバビリティが重要 レガシーコードだったとしても、売上を上げている立派な資産 レガシーコードだからオブザーバビリティを上げられないとことはなく、 できることを少しずつ小さく初めていくことが大切 オブザーバビリティというガードレールを使ってレガシーコードの改善を進め、 より高い価値を提供できるサービスを作っていこう #phpconkagawa 90
91. ご清聴ありがとうございました。 #phpconkagawa 91
92. おまけ #phpconkagawa 92
93. Metabaseもいいぞ #phpconkagawa 93
94. Metabase #phpconkagawa 94
95. Metabase ブラウザ上でSQLを書いて実行できる #phpconkagawa 95
96. Metabase 実行時に変えたい部分をパラメータ化できる #phpconkagawa 96
97. Metabase 結構いろいろなデータソースに接続できる #phpconkagawa 97
98. Metabase ダッシュボードもつくれる #phpconkagawa 98
99. Metabase エンジニアが作成したSQLを保存しておける -> エンジニア以外がパラメータを入力してSQLを実行できる #phpconkagawa 99
100. Metabase エンジニアが作成したSQLを保存しておける -> エンジニア以外がパラメータを入力してSQLを実行できる CSを担当されている方がSQLを書き始めてくれる嬉しいことも！ #phpconkagawa 100
101. Metabase エンジニアが作成したSQLを保存しておける -> エンジニア以外がパラメータを入力してSQLを実行できる CSを担当されている方がSQLを書き始めてくれる嬉しいことも！ #phpconkagawa 101
102. Metabase エンジニアが作成したSQLを保存しておける -> エンジニア以外がパラメータを入力してSQLを実行できる CSを担当されている方がSQLを書き始めてくれる嬉しいことも！ インシデントが起きたときに頻出なSQLを事前に登録するのも便利 #phpconkagawa 102
103. ご清聴ありがとうございました。 #phpconkagawa 103