TL;DR
New Relic Query Language (NRQL) の capture(), numeric(), sum() 関数を利用すると、New Relic Logs にある、ログメッセージ内に処理時間が含まれたログから、処理時間を簡単に合計できます。
はじめに
New Relic で利用できる NRQL (New Relic Query Language) は超強力です。
頻繁に確認するようなデータは Dashboard にまとめておくとして、随時必要になったデータを探しに行くとき、UI から辿るよりも NRQL をサクッと書いた方が早かったりします。
そんなわけで、基本 Dashboard を見つつ NRQL を叩くというのが、筆者の New Relic の使い方になっています。
最近のアップデートで、クエリビルダーがタブ機能に対応したのには大歓喜しました🎉
さて、今回はその NRQL で感動的に便利なことが最近あったので共有したいと思います。
やりたかったこと
ログに各処理の処理時間が出力されているシステムがありました。
イメージとしてはこんな感じです。
2024-12-25T09:00:00+09:00 [INFO] Process "hoge" successfully completed. [123 ms]
2024-12-25T09:00:01+09:00 [INFO] Process "fuga" successfully completed. [456 ms]
このログをベースに、 「処理が走っていた合計時間を取得したい」 というのが今回の目的になります。
上記の例でいうと、hoge 123ミリ秒 + fuga 456ミリ秒 = 579ミリ秒 を取得したいという感じです。
素直にやろうとすると、ログ件数が多いだけでなく、ログファイルも複数サーバの複数ディレクトリに散らばっており、ファイル加工して云々……など気が遠くなるような作業です。
しかし、幸いなことにログは New Relic Logs に収集していたため、New Relic の NRQL で集計が可能でした。
NRQL で簡単に実現できました
やりたいことを平たく言うと、 ログのメッセージから処理時間の部分だけを抜き出して合計する ということです。
例にはなりますが、以下のような NRQL でサクッと実現可能です。
FROM Log
SELECT sum(numeric(capture(message, r'.+ successfully completed\. \[(?P<time>\d+) ms\]')))
WHERE logtype = 'example'
SINCE 30 minutes ago
WHERE 句や SINCE 句はあくまで例なので、適宜変更してください。
やっていることとしては、
-
capture()関数を使い、ログ内の処理時間部分のみをキャプチャ -
numeric()でキャプチャした文字列を数値に変換 -
sum()で数値を合計
になります。
ポイントとなる capture() の使い方は、リファレンスにも説明があるほか、Qiita の New Relic Organization で公開されている下記の記事もわかりやすいですね。
NRQL 上の注意点としては、
- 正規表現文字列の前には
rプリフィックスが必要だった - 正規表現のキャプチャグループには名前が必要(上記の例の
<time>の部分)だった
といったところでしょうか。
(RE2 構文に慣れている方は迷わないのでしょうが、筆者はハマりかけました)
おわりに
今回のシステムの場合、素直にやると、各サーバからのログファイル集めから始めなければならず、最低数時間はかかったと思います。
New Relic Logs と NRQL を利用したことで、(クエリの書き方を調べる時間を含め)数分で実現できました。
冒頭にも書いた通り NRQL は日常的に叩いているのですが、今回の件はかなり感動的で、
改めて強力さを実感しました！