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

AWS AppSync CloudWatch

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で行ってみました。