Allow retrieving query traces over HTTP

core/tests/interfaces.rs

@@ -25,7 +25,7 @@ async fn insert_and_query(
 
     let document = graphql_parser::parse_query(query).unwrap().into_static();
     let target = QueryTarget::Deployment(subgraph_id, Default::default());
-    let query = Query::new(document, None);
+    let query = Query::new(document, None, false);
     Ok(execute_subgraph_query(query, target)
         .await
         .first()
@@ -1481,12 +1481,12 @@ async fn derived_interface_bytes() {
         id: Bytes!,
         trades: [Trade!]! @derivedFrom(field: "pool")
       }
-      
+
       interface Trade {
        id: Bytes!
        pool: Pool!
       }
-      
+
       type Sell implements Trade @entity {
           id: Bytes!
           pool: Pool!

docs/environment-variables.md

@@ -123,7 +123,14 @@ those.
 - `SILENT_GRAPHQL_VALIDATIONS`: If `ENABLE_GRAPHQL_VALIDATIONS` is enabled, you are also able to just
   silently print the GraphQL validation errors, without failing the actual query. Note: queries
   might still fail as part of the later stage validations running, during GraphQL engine execution.
-- `GRAPH_GRAPHQL_DISABLE_BOOL_FILTERS`: disables the ability to use AND/OR filters. This is useful if we want to disable filters because of performance reasons.
+- `GRAPH_GRAPHQL_DISABLE_BOOL_FILTERS`: disables the ability to use AND/OR
+  filters. This is useful if we want to disable filters because of
+  performance reasons.
+- `GRAPH_GRAPHQL_TRACE_TOKEN`: the token to use to enable query tracing for
+  a GraphQL request. If this is set, requests that have a header
+  `X-GraphTraceQuery` set to this value will include a trace of the SQL
+  queries that were run. Defaults to the empty string which disables
+  tracing.
 
 ### GraphQL caching
 
@@ -201,7 +208,7 @@ those.
   identified as unused, `graph-node` will wait at least this long before
   actually deleting the data (value is in minutes, defaults to 360, i.e. 6
   hours)
-- `GRAPH_ALLOW_NON_DETERMINISTIC_IPFS`: enables indexing of subgraphs which 
+- `GRAPH_ALLOW_NON_DETERMINISTIC_IPFS`: enables indexing of subgraphs which
   use `ipfs.cat` as part of subgraph mappings. **This is an experimental
   feature which is not deterministic, and will be removed in future**.
 - `GRAPH_STORE_BATCH_TARGET_DURATION`: How long batch operations during

graph/src/components/store/mod.rs

@@ -435,6 +435,8 @@ pub struct EntityQuery {
 
     pub query_id: Option<String>,
 
+    pub trace: bool,
+
     _force_use_of_new: (),
 }
 
@@ -453,6 +455,7 @@ impl EntityQuery {
             range: EntityRange::first(100),
             logger: None,
             query_id: None,
+            trace: false,
             _force_use_of_new: (),
         }
     }

graph/src/data/query/query.rs

@@ -132,14 +132,16 @@ pub struct Query {
     pub shape_hash: u64,
     pub query_text: Arc<String>,
     pub variables_text: Arc<String>,
+    pub trace: bool,
     _force_use_of_new: (),
 }
 
 impl Query {
-    pub fn new(document: q::Document, variables: Option<QueryVariables>) -> Self {
+    pub fn new(document: q::Document, variables: Option<QueryVariables>, trace: bool) -> Self {
         let shape_hash = shape_hash(&document);
 
-        let (query_text, variables_text) = if ENV_VARS.log_gql_timing()
+        let (query_text, variables_text) = if trace
+            || ENV_VARS.log_gql_timing()
             || (ENV_VARS.graphql.enable_validations && ENV_VARS.graphql.silent_graphql_validations)
         {
             (
@@ -158,6 +160,7 @@ impl Query {
             shape_hash,
             query_text: Arc::new(query_text),
             variables_text: Arc::new(variables_text),
+            trace,
             _force_use_of_new: (),
         }
     }

graph/src/data/query/result.rs

@@ -78,6 +78,14 @@ impl QueryResults {
     pub fn traces(&self) -> Vec<&Trace> {
         self.results.iter().map(|res| &res.trace).collect()
     }
+
+    pub fn errors(&self) -> Vec<QueryError> {
+        self.results
+            .iter()
+            .map(|r| r.errors.clone())
+            .flatten()
+            .collect()
+    }
 }
 
 impl Serialize for QueryResults {
@@ -91,7 +99,14 @@ impl Serialize for QueryResults {
         if has_errors {
             len += 1;
         }
-
+        let first_trace = self
+            .results
+            .iter()
+            .find(|r| !r.trace.is_none())
+            .map(|r| &r.trace);
+        if first_trace.is_some() {
+            len += 1;
+        }
         let mut state = serializer.serialize_struct("QueryResults", len)?;
 
         // Serialize data.
@@ -127,6 +142,9 @@ impl Serialize for QueryResults {
             state.serialize_field("errors", &SerError(self))?;
         }
 
+        if let Some(trace) = first_trace {
+            state.serialize_field("trace", trace)?;
+        }
         state.end()
     }
 }

graph/src/data/query/trace.rs

@@ -3,15 +3,18 @@ use std::{
     time::Duration,
 };
 
-use serde::Serialize;
+use serde::{ser::SerializeMap, Serialize};
 
-use crate::env::ENV_VARS;
+use crate::{components::store::BlockNumber, prelude::CheapClone};
 
-#[derive(Debug, Serialize)]
+#[derive(Debug)]
 pub enum Trace {
     None,
     Root {
         query: Arc<String>,
+        variables: Arc<String>,
+        query_id: String,
+        block: BlockNumber,
         elapsed: Mutex<Duration>,
         children: Vec<(String, Trace)>,
     },
@@ -31,10 +34,19 @@ impl Default for Trace {
 }
 
 impl Trace {
-    pub fn root(query: Arc<String>) -> Trace {
-        if ENV_VARS.log_sql_timing() || ENV_VARS.log_gql_timing() {
+    pub fn root(
+        query: &Arc<String>,
+        variables: &Arc<String>,
+        query_id: &str,
+        block: BlockNumber,
+        do_trace: bool,
+    ) -> Trace {
+        if do_trace {
             Trace::Root {
-                query,
+                query: query.cheap_clone(),
+                variables: variables.cheap_clone(),
+                query_id: query_id.to_string(),
+                block,
                 elapsed: Mutex::new(Duration::from_millis(0)),
                 children: Vec::new(),
             }
@@ -74,4 +86,58 @@ impl Trace {
             }
         }
     }
+
+    pub fn is_none(&self) -> bool {
+        match self {
+            Trace::None => true,
+            Trace::Root { .. } | Trace::Query { .. } => false,
+        }
+    }
+}
+
+impl Serialize for Trace {
+    fn serialize<S>(&self, ser: S) -> Result<S::Ok, S::Error>
+    where
+        S: serde::Serializer,
+    {
+        match self {
+            Trace::None => ser.serialize_none(),
+            Trace::Root {
+                query,
+                variables,
+                query_id,
+                block,
+                elapsed,
+                children,
+            } => {
+                let mut map = ser.serialize_map(Some(children.len() + 2))?;
+                map.serialize_entry("query", query)?;
+                if !variables.is_empty() && variables.as_str() != "{}" {
+                    map.serialize_entry("variables", variables)?;
+                }
+                map.serialize_entry("query_id", query_id)?;
+                map.serialize_entry("block", block)?;
+                map.serialize_entry("elapsed_ms", &elapsed.lock().unwrap().as_millis())?;
+                for (child, trace) in children {
+                    map.serialize_entry(child, trace)?;
+                }
+                map.end()
+            }
+            Trace::Query {
+                query,
+                elapsed,
+                entity_count,
+                children,
+            } => {
+                let mut map = ser.serialize_map(Some(children.len() + 3))?;
+                map.serialize_entry("query", query)?;
+                map.serialize_entry("elapsed_ms", &elapsed.as_millis())?;
+                map.serialize_entry("entity_count", entity_count)?;
+                for (child, trace) in children {
+                    map.serialize_entry(child, trace)?;
+                }
+                map.end()
+            }
+        }
+    }
 }

graph/src/env/graphql.rs

@@ -87,6 +87,11 @@ pub struct EnvVarsGraphQl {
     /// Set by the flag `GRAPH_GRAPHQL_DISABLE_BOOL_FILTERS`. Off by default.
     /// Disables AND/OR filters
     pub disable_bool_filters: bool,
+    /// Set by `GRAPH_GRAPHQL_TRACE_TOKEN`, the token to use to enable query
+    /// tracing for a GraphQL request. If this is set, requests that have a
+    /// header `X-GraphTraceQuery` set to this value will include a trace of
+    /// the SQL queries that were run.
+    pub query_trace_token: String,
 }
 
 // This does not print any values avoid accidentally leaking any sensitive env vars
@@ -132,6 +137,7 @@ impl From<InnerGraphQl> for EnvVarsGraphQl {
             error_result_size: x.error_result_size.0 .0,
             max_operations_per_connection: x.max_operations_per_connection,
             disable_bool_filters: x.disable_bool_filters.0,
+            query_trace_token: x.query_trace_token,
         }
     }
 }
@@ -179,4 +185,6 @@ pub struct InnerGraphQl {
     max_operations_per_connection: usize,
     #[envconfig(from = "GRAPH_GRAPHQL_DISABLE_BOOL_FILTERS", default = "false")]
     pub disable_bool_filters: EnvVarBoolean,
+    #[envconfig(from = "GRAPH_GRAPHQL_TRACE_TOKEN", default = "")]
+    query_trace_token: String,
 }

graphql/src/execution/execution.rs

@@ -204,6 +204,9 @@ where
 
     /// Records whether this was a cache hit, used for logging.
     pub(crate) cache_status: AtomicCell<CacheStatus>,
+
+    /// Whether to include an execution trace in the result
+    pub trace: bool,
 }
 
 pub(crate) fn get_field<'a>(
@@ -236,6 +239,7 @@ where
 
             // `cache_status` is a dead value for the introspection context.
             cache_status: AtomicCell::new(CacheStatus::Miss),
+            trace: ENV_VARS.log_sql_timing(),
         }
     }
 }

graphql/src/query/mod.rs

@@ -27,6 +27,9 @@ pub struct QueryExecutionOptions<R> {
     pub max_skip: u32,
 
     pub load_manager: Arc<LoadManager>,
+
+    /// Whether to include an execution trace in the result
+    pub trace: bool,
 }
 
 /// Executes a query and returns a result.
@@ -49,6 +52,7 @@ where
         max_first: options.max_first,
         max_skip: options.max_skip,
         cache_status: Default::default(),
+        trace: options.trace,
     });
 
     if !query.is_query() {

graphql/src/runner.rs

@@ -123,6 +123,7 @@ where
             .unwrap_or(state);
 
         let max_depth = max_depth.unwrap_or(ENV_VARS.graphql.max_depth);
+        let trace = query.trace;
         let query = crate::execution::Query::new(
             &self.logger,
             schema,
@@ -168,6 +169,7 @@ where
                     max_first: max_first.unwrap_or(ENV_VARS.graphql.max_first),
                     max_skip: max_skip.unwrap_or(ENV_VARS.graphql.max_skip),
                     load_manager: self.load_manager.clone(),
+                    trace,
                 },
             )
             .await;