こんにちはSREの三橋です！
本日はRedashのアプリケーションログをNew Relicダッシュボードでいい感じに可視化することができたため、その内容とチャート作成の過程について記載いたします。
はじめに
背景
ヤプリでは障害調査やデータ分析を目的に社内ツールとしてRedash(https://github.com/getredash/redash)を利用しています。導入当初は少なかった利用者も徐々に増え、利用バリエーションも増えてきたことでRedashの重要性が増し、監視の仕組みが必要になりました。
これまでログ監視を行う際は特定文字列を含むログを検知できるようにするだけだったのですが、もう少し有用な情報が得られるのではないかと思い、ログの可視化を行ってみることにしました。
想定する読者
- Redashの利用状況を可視化、分析したいと考えている方
- New Relicで何ができるか興味がある方
- New Relicでのログの可視化方法について興味がある方
- NRQLを勉強している方
- インフラ監視ではなく、アプリケーション寄りの監視をしてみたい方
- ヤプリの裏側に興味がある方
完成したダッシュボード
完成したダッシュボードは下記の画像の通りです。
Redashクエリの実行頻度や実行時間、ジョブ登録状況、エラー発生状況など様々なことが、このダッシュボードから確認することができます。
利用したNew Relicの新NRQL関数および新機能
aparse()関数
aparse()は2022年10月に利用可能になった関数で、正規表現で任意の文字列を取得することができる関数です。
従来はcapture()という関数で正規表現で文字列を取得することができましたが、aparse()を利用することでよりシンプルにクエリを記述できるようになりました。
今回は主にこの関数を利用してログから文字列を取得し可視化しています。
aparse()関数に関するNew Relicブログはこちらです。
newrelic.com
テンプレート変数
テンプレート変数は2022年11月に利用可能になった機能で、ダッシュボード上で変数に値を入れることで各チャートで利用しているNRQLを動的に変更することができるというものです。
こちらについてはまだ十分に活用してきれていませんが、実行失敗しているログ調査を目的として今回は利用しています。
テンプレート変数に関するNew Relicブログはこちらです。 newrelic.com
ヤプリにおけるRedash構成
ダッシュボードを構成するチャートの説明に入る前に、前提としてヤプリにおけるRedashの構成をご紹介しておきます。
詳細については割愛いたしますが、下図に示すようにヤプリのRedashはECSサービス上で動作しており、大きくServerとWorkerにわけています。
Server側ではRedashのWebページを表示するためのコンポーネントを動かしており、Worker側ではクエリを実行するためのコンポーネントを動かしています。また、それぞれのアプリケーションログはNew RelicのLogs in Context機能を利用するため、New Relic APMエージェントでEnrichmentを行い、ログフォワーダー(Fluent Bit)によりKinesis Data Firehoseを介してNew Relicに転送しています。CloudWatch Logsを利用していないのはコスト削減のためです。
アプリケーションログの転送周りについては以前のブログに記載しています。
tech.yappli.io
ログ仕様確認の手順
ログを可視化するには事前にログの仕様(フォーマット)を把握しておく必要があります。ここではログの仕様を確認するまでに実際に行った手順について記載します。ダッシュボード構成チャートについてのみご興味のある方は読み飛ばしていただいて問題ございません。
ソースコードを読み解くことでも仕様を理解することは可能ですが、今回は実際のログを見ながら仕様を確認するアプローチをとっています。
まずNew Relic側にどのような形式でログが送られてくるか確認し、ログの送信元(コンテナ)を特定する方法を考えます。
New Relic側に送られてくるデータは以下のようなフォーマットになっています。
entity.guidもしくはcontainer_nameでログの送信元を特定することができそうです。
entity.guidはNew Relic APMエージェントが付与する属性でありリソースごとに一意な値です。(参考: https://docs.newrelic.com/jp/docs/new-relic-solutions/new-relic-one/core-concepts/what-entity-new-relic/ )ですが、今回はクエリの可読性を考慮しcontainer_nameを利用する方向で考えます。
この値はFireLensログドライバーにより付与されるようです。(参考: Fluent Bitを利用したログルーティング - 入門編 - ISID テックブログ)
続いてRedashのアプリケーションログの仕様について確認し、どのようなことが可視化できそうか考えます。
先ほどのデータフォーマットよりmessageにログが格納されていることがわかるため、対象のコンテナごとに下記のようなクエリを実行しRedashログのフォーマットを調査します。
SELECT message FROM Log WHERE container_name = 'prod-redash-server'
それぞれのコンテナのログは以下のようになっています。
redash-server
ログは正規化されており、リクエストURI、メソッド、HTTPステータスコードなどの情報が得られそうです。
redash-worker
ログは正規化されている部分とされていない部分がありそうですが、クエリやジョブの実行状況がわかりそうです。
redash-scheduler
それほど有益な情報を得ることはできなさそうです。
以上のことからredash-server, redash-workerそれぞれのアプリケーションログを使用することで、アプリケーションの実行状況を可視化できそうであることがわかりました。
このように少しづつ条件を加えながらログを分析し、出現パターンを特定していきます。
ダッシュボード構成チャート
ここではダッシュボードを構成する各チャートの説明とそのクエリを記載します。量が多いため5つのみご紹介いたします。
クエリID別実行頻度
このチャートは実行頻度が支配的なクエリがないか確認することを目的に作成したものです。 実行頻度が高く、実行時間が長いクエリはリソースに負荷をかけるためこちらの情報をもとに是正対応を行うことが可能になっています。
NRQLは以下の通りです。
WITH aparse(message, '%func_name=* job.id=* job=execute_query state=* % query_id=* username=*') as (funcName, jobId, state, queryId, userName) SELECT count(*) FROM Log WHERE container_name = 'prod-redash-worker' AND funcName = 'redash.tasks.queries.execution.execute_query' AND state = 'executing_query' FACET queryId SINCE 1 day ago
Redash Workerのログには実行している関数名が記載されています。redash.tasks.queries.execution.execute_query関数はクエリの実行処理を行なう関数であり、stateが変化するたびにそのログを出力します。
state=executing_queryはクエリが実行中であることを示すため、この値が含まれるログをqueryId別に見ることで目的を達成しています。
ジョブ別実行時間
このチャートは実行時間が異様に長いジョブがないか確認することを目的に作成したものです。クエリとジョブは1:Nの関係になっており、同一クエリでも実行時間にバラつきが出ることがあるためジョブごとに実行時間を見ています。
NRQLは以下の通りです。
WITH aparse(message, '%func_name=* job.id=* job=execute_query state=* % query_id=* username=*') as (funcName, jobId, state, queryId, userName)
SELECT (MAX(timestamp) - MIN(timestamp)) / 1000 / 60 AS duration FROM Log WHERE container_name = 'prod-redash-worker' WHERE funcName = 'redash.tasks.queries.execution.execute_query' AND state IN ('executing_query', 'finished') FACET jobId, queryId, userName SINCE 1 day ago LIMIT MAX
先ほどと同様にredash.tasks.queries.execution.execute_query関数で、state=executing_queryまたはstate=finishedが記載されるログの最後の時刻と最初の時刻の差分で実行時間を計測しています。jobIdは実行ごとに一意なIDが割り振られるため、FACET句にこのIDを入れることで目的を達成しています。LIMIT MAXとしてるのはデフォルトでは表示件数が10件で降順に標準されることが保証されていないためです。(FACETとORDER BYでは期待する結果が得られませんでした。)
このチャートの欠点は実行中のクエリについては実行時間を可視化することができないということです。
クエリ実行数と実行完了数
このチャートは実行数と実行完了数に乖離がないか確認することを目的に作成しています。あまりに乖離がある場合は何かしらの障害が発生しているため、この情報をもとに調査を実施するか判断することができます。
NRQLは以下の通りです。
WITH aparse(message, '%func_name=* job.id=* job=execute_query state=* % query_id=* %') as (funcName, jobId, state, queryId) SELECT count(*)
FROM Log WHERE container_name = 'prod-redash-worker' AND funcName = 'redash.tasks.queries.execution.execute_query' AND state IN ('executing_query', 'finished') FACET IF(state = 'executing_query', '実行数', '完了数')
FACET IFを使用しグループ名を指定することで、何を意味しているかわかりやすくしています。SINCE句は特に指定していませんが範囲を広げるため1 month agoなどを指定した方がよいかもしれません。またTIMESERIES句を加え時系列形式にするのもよいです。
ジョブ登録数
このチャートはジョブの登録が集中している時間帯を確認することを目的に作成しています。ジョブがあまりに集中している場合にはスケジュールジョブの実行時間を調整するなどして、リソースの負荷が偏らないようにします。またメンテナンスのタイミングを計る際の参考情報にもなります。
NRQLは以下の通りです。
SELECT count(*) as registerd_jobs FROM Log WHERE container_name = 'prod-redash-worker' WHERE message LIKE '%Created new job%' TIMESERIES AUTO
任意のクエリID調査用のログテーブル
ダッシュボード上から任意のクエリIDのログ調査ができるようにテンプレート変数を埋め込めんだログテーブルを用意しています。
NRQLは以下の通りです。
SELECT message FROM Log WHERE container_name = 'prod-redash-worker' WHERE aparse(message, '%query_id=* %') = {{query_id}} SINCE 1 day ago LIMIT MAX
{{ }}で囲まれた部分が変数となり、この部分が動的に変更されます。(残念ながらチャートのタイトルは変わってくれませんでした。)
ダッシュボード上の変数定義では以下のようにQuery Typeでクエリを設定しています。
このようにすることで、下図のようにダッシュボード上からquery_idを指定する際に選択肢として上記クエリ結果を表示させることが可能になります。
まとめ
Redashログを可視化したダッシュボードの説明とNew Relicでのログの可視化方法をご紹介いたしました。ログが正規化されている場合、正規表現を使用することでログから様々な情報が得られることがわかりました。ぜひ皆様もログの可視化に挑戦してみてはいかがでしょうか。
この記事がどなたかの一助になれますと幸いです。