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 でサクッと実現可能です。

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 は日常的に叩いているのですが、今回の件はかなり感動的で、
改めて強力さを実感しました！