問題

graphqlのqueryでActiveRecordの呼び出し部分は問題がないが、各fieldの呼び出しapp/graphql_types/*_type.rbでどうも遅い。だけどfieldでより時間がかかっているのか？、どのぐらい呼び出されているのかわからない。

解決

GraphQL::Tracing::ActiveSupportNotificationsTracingを使って、呼び出し毎の処理状況をログに落とし込む。

config/initializers/active_support_notifications.rb

logfile = Pathname(Rails.root.join("log/graphql.tsv"))

ActiveSupport::Notifications.subscribe(
  /graphql/
) do |name, started, finished, unique_id, data|
  # 古いgraphql-ruby（graphql (1.9.17)）使っているので、データのアクセス方法は違うかも
  next unless data[:context]

  operation_name = data[:context].query.operation_name
  name = data[:context].field.name
  type = data[:context].field.type
  duration = ((finished - started) * 1000).round(2)

  logfile.write(
    [
      Time.current.strftime("%Y-%m-%d %H:%M:%S"),
      operation_name,
      name,
      type,
      duration,
      "\n"
    ].join("\t"),
    mode: "a"
  )
end

app/graphql/app_schema.rb

class AppSchema < GraphQL::Schema
  # config/initializers/active_support_notifications.rbが呼ばれる
  tracer(GraphQL::Tracing::ActiveSupportNotificationsTracing)

  # ...
  # ...
end

出力ログ

これによりRails.root.join("log/graphql.tsv")へログが逐次出力され

出力日時
Queryの名前
field名
処理時間

がタブ区切りで記録される。このTSVをgoogle spreadsheetなどにインポートしてピボットテーブルなどで集計して原因を探る。

例

query Test{
  test{
    id
    name
    product {
      id
      name
      price
    }
  }
}

などとあった場合、

app/log/graphql.tsv

2024-11-30 6:29:41	Test	id	0.01
2024-11-30 6:29:41	Test	name	0.01
...

みたいな感じで出力される。