Node-RED 2.1の新機能: HTTP Requestノードのログ機能強化

はじめに

Node-REDのHTTP Requestノードを使うと、他のWebサービスの情報を取得したりREST APIを呼び出したりということが簡単にできます。しかし、これらを多用するようになると、「なぜか反応が悪い」「どこかで固まっているようだ」などのトラブルに見舞われることも増えてきます。

このような時は、ログなどを使って何が原因なのかを調べることになるのですが、今までのNode-REDではあまり詳しいログを出力することができませんでした。このため、たとえばフレームグラフを出力して調査するなどの手のかかる方法で調査をする必要があります。

Node-RED 2.1では、HTTP Requestノードのメトリックログ機能が強化され、HTTP要求を行った際の詳細なタイミングのログが取れるようになりました。これによって、例えばDNSの名前解決が遅いのでHTTP要求に時間がかかっている、などの詳細な分析が簡単に行えるようになります。

以下にて、これまでのログ出力との比較を行いながら、強化されたログ機能を説明していきます。

これまでのHTTP Requestノードのメトリックログ

Node-REDでは、settings.jsに下記の記述を行うことで各種のメトリックログが出力されるようになります。

logging: {
  console: {
    metrics: true,  // true: メトリックログを出力する。
  }
}

この設定を行うと、各ノードがメッセージを送受信した時刻や処理を終了した時刻がコンソールに出力されるようになります。

29 Nov 11:15:47 - [metric] {"level":99,"nodeid":"4fdc8a7892920b4e","event":"node.inject.receive","msgid":"cf882bc9529ae5e6","timestamp":1638152147678}
29 Nov 11:15:47 - [metric] {"level":99,"nodeid":"4fdc8a7892920b4e","event":"node.inject.send","msgid":"cf882bc9529ae5e6","timestamp":1638152147679}
29 Nov 11:15:47 - [metric] {"level":99,"nodeid":"4fdc8a7892920b4e","event":"node.inject.done","msgid":"cf882bc9529ae5e6","timestamp":1638152147679}
29 Nov 11:15:47 - [metric] {"level":99,"nodeid":"3bba6bc06f8f299d","event":"node.debug.receive","msgid":"cf882bc9529ae5e6","timestamp":1638152147680}
29 Nov 11:15:47 - [metric] {"level":99,"nodeid":"3bba6bc06f8f299d","event":"node.debug.done","msgid":"cf882bc9529ae5e6","timestamp":1638152147681}

例えばnode.ノード名.receiveは、メッセージを受信したイベントが、メッセージIDとタイムスタンプ(Unix epochからの経過ミリ秒)ととも記録されます。これを使うことにより、ノードにおいて特定のメッセージに関する処理がいつ行われ、どれだけの時間を要したかがわかるようになります。

また15秒おきにNode-REDランタイムのメモリ消費状況も出力されます。

29 Nov 11:19:40 - [metric] {"level":99,"event":"runtime.memory.rss","value":85643264,"timestamp":1638152380377}
29 Nov 11:19:40 - [metric] {"level":99,"event":"runtime.memory.heapTotal","value":37392384,"timestamp":1638152380377}
29 Nov 11:19:40 - [metric] {"level":99,"event":"runtime.memory.heapUsed","value":35748864,"timestamp":1638152380377}

ノードによっては、そのノード独自の情報が出力されます。例えば、HTTP Requestノードでは下記の情報が出力されます。

26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.duration.millis","msgid":"7ee3cb22fcf570f5","value":"785.963","timestamp":1637893427419}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.size.bytes","msgid":"7ee3cb22fcf570f5","value":151917,"timestamp":1637893427419}

この情報により、HTTP要求全体でどれだけの時間がかかったか、また送受信したデータ量がどれくらいだったのかがわかります。ただ、node.http request.duration.millisをみれば全体で786msほどかかっていことはわかりますが、それがどのような内訳になっているかはわかりません。

詳細なタイミングログ

Node-RED 2.1以降では、メトリックログを有効にした状態でsettings.jsに下記の設定を加えると、詳細なタイミングのログが出力されるようになります。

httpRequestTimingLog: true,

各HTTP要求ごとに出力されるログの例を示します。

26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.start","msgid":"7ee3cb22fcf570f5","value":1637893426660,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.socket","msgid":"7ee3cb22fcf570f5","value":1637893426734,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.lookup","msgid":"7ee3cb22fcf570f5","value":1637893426734,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.connect","msgid":"7ee3cb22fcf570f5","value":1637893426734,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.secureConnect","msgid":"7ee3cb22fcf570f5","value":1637893426764,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.upload","msgid":"7ee3cb22fcf570f5","value":1637893426764,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.response","msgid":"7ee3cb22fcf570f5","value":1637893427374,"timestamp":1637893427420}
26 Nov 11:23:47 - [metric] {"level":99,"nodeid":"ed79aba73c6884f5","event":"node.http request.timings.end","msgid":"7ee3cb22fcf570f5","value":1637893427418,"timestamp":1637893427420}

node.http request.timings.*の各イベントにおけるvalueの意味は下記の通りです:

• start: HTTP要求が発行された時刻
• socket: ソケットが割り当てられた時刻
• lookup: DNS名前解決が完了した時刻
• connect: TCP接続確立が完了した時刻
• secureConnect: TLD接続確立が完了した時刻
• upload: HTTP要求を送信完了した時刻
• response: HTTP応答を受信し始めた時刻
• end: HTTP応答を自身し終わった時刻

(注: timestampは、メトリックログを出力した時刻を示すので混同しないように)

このように、HTTP要求から返答完了までの細かいタイミングがわかるので、例えばHTTP要求にかかる時間の大半が名前解決の為の時間に使われている、などということがわかるようになります。

上記のログを使って、どこにどれだけの時間がかかっているかをグラフ化してみましょう。

HTTP要求を送り終えた後、実際に応答の最初の1バイトが返ってくるまでの時間が大半を占めています。よって、全体の性能改善にはNode-RED側での何らかの改善をするよりHTTPサーバ側での対応が必要であることがわかります。

おわりに

Node-RED 2.1の新機能の一つである、HTTP requestノードのログ機能強化について解説しました。Node-REDで、いろいろなITシステムを連携させるときにHTTP requestノードを使っている方も多いかと思います。もし、性能改善やトラブルシュートの際にHTTP要求の詳しいタイミングが必要となったときには本記事の内容を試してみてください。

Node-RED 2.1の新機能紹介

• Node-RED2.1の新機能: フローおよびグループに対する環境変数の定義
• Node-RED 2.1の新機能: HTTP Requestノードのログ機能強化(本記事)
• Node-RED 2.1の新機能: ツアー機能

Node-RED: Node-REDは，OpenJS Foundationの米国およびその他の国における登録商標または商標である。