AppSyncを運用していて、各リゾルバーごとのレイテンシーを比較することがあったため、CloudWatch Logs InsightsでAppSyncのリゾルバーごとのレイテンシーを出すクエリを書いてみました。

概要

• CloudWatch Logs InsightsでAppSyncのリゾルバーごとのレイテンシーを一覧で出す

パターン

以下の2パターンを書いてみました。

1. リゾルバーごとのレイテンシー一覧（実行時刻順）
2. リゾルバーごとのレイテンシー一覧（レイテンシー順）

CloudWatch Logs Insightsクエリ

リゾルバーごとのレイテンシー一覧（実行時刻順）

fields @timestamp, @message, requestId
| parse @message /^(?<reqId>[[0-9]|a-z|A-Z|-]*?) .*/
| fields concat(requestId, reqId) as sum_request_id
| stats
    earliest(path.0) as main_resolver,
    max(latency) / 1000000000 as latency_sec, 
    # (max(toMillis(@timestamp)) - min(toMillis(@timestamp))) / 1000 as latency_sec, 
    min(@timestamp) as start_time, 
    max(@timestamp) as end_time
    by sum_request_id 
| filter !isempty(main_resolver) 
| sort start_time desc #### 実行時刻でソート

• concat(requestId, reqId) as sum_request_id
  • リクエストIDから始まる非構造化ログと、JSON形式で格納される半構造化ログで分かれているため、リクエストIDを統合して一つのカラムで表している
• latencyが1種類のログタイプでしか存在しないからたまたまmax(latency)(minでも良い)で出せるのですが、少し無理矢理ではあります
  • CASE文とかが使えればもっとうまく表せるんですけどね・・・
  • コメントアウトの方の書き方でも出せるが少し誤差あり

リゾルバーごとのレイテンシー一覧（レイテンシー順）

fields @timestamp, @message, requestId
| parse @message /^(?<reqId>[[0-9]|a-z|A-Z|-]*?) .*/
| fields concat(requestId, reqId) as sum_request_id
| stats
    earliest(path.0) as main_resolver,
    max(latency) / 1000000000 as latency_sec, 
    # (max(toMillis(@timestamp)) - min(toMillis(@timestamp))) / 1000 as latency_sec, 
    min(@timestamp) as start_time, 
    max(@timestamp) as end_time
    by sum_request_id 
| filter !isempty(main_resolver) 
| sort latency_sec desc #### 実行時間でソート

• 1.のクエリのsortカラムを変えているだけです。

注意

1リクエスト1クエリずつの実行を想定しています。

例えばAppSyncのコンソールなどでGraphQLクエリを1回で複数叩けますが、その場合、1クエリ目の計測結果に2クエリ目の計測結果も含められてしまいます。

最後に

AppSyncのリゾルバーごとにパフォーマンスを調べて改善するため、レイテンシーの比較をCloudWatch Logs Insightsで行ってみました。