Skip to content

Instantly share code, notes, and snippets.

@lutter
Last active September 20, 2024 20:04
Show Gist options
  • Select an option

  • Save lutter/f0e95f0c4a77c38c6c3cf1411595fed0 to your computer and use it in GitHub Desktop.

Select an option

Save lutter/f0e95f0c4a77c38c6c3cf1411595fed0 to your computer and use it in GitHub Desktop.
Better tracing

Better tracing

The build for commit 515a7d95 is based on the branch lutter/stuff. The branch backports these changes to v0.34.1:

The build for commit c266a0ca is based on the same branch but only contains the first three changes from the list.

Details of the new query traces

Query tracing is enabled by setting the environment variable GRAPH_GRAPHQL_TRACE_TOKEN to some string value. A GraphQL query that contains the HTTP header X-GraphTraceQuery with that string value will contain additional data in the response. The response will have two new entries besides data: trace and http.

All times in the query trace are walltimes, i.e., include possible waits caused by a task having to wait because there are other tasks that need to be scheduled.

Queries are processed by splitting the toplevel GraphQL query fields by block constraints. Each of these groups is run as one unit. When parallel query execution is turned on, these groups are run in parallel; when not, they are run one after the other. For each group, we first check the cache if we already have that result. If not, each group needs to acquire a query semaphore before starting to run database queries. By default, the semaphore has as many permits as the database connection pool has connections. With that, each group has a reasonable chance of getting the connections it needs even if there are a lot of other queries happening at the same time. The environment variable GRAPH_EXTRA_QUERY_PERMITS can be set to increase the number of permits. Setting this to something very large, say 100,000 will effectively disable the semaphore.

The additional response fields contain the following:

{
  "trace": {
    "query": "<graphql query>",
    "query_id": "<query id>",
    # Overall time for executing the query; excludes parsing and
    # serializing the result
    "elapsed_ms": "..",
    # Time for getting the GraphQL schema for the subgraph, checking where
    # its head is and some other bookkeeping
    "setup_ms": 63,
    # Time for parsing the HTTP request into the AST we use to represent
    # the GraphQL query
    "query_parsing_ms": 12,
    # Rollup of times for all SQL queries that were run
    "db": {
      # Total time spent sending a SQL query to the database and waiting
      # for the result
      "elapsed_ms": 82,
      # Total time spent waiting to get a database connection
      "conn_wait_ms": 19,
      # Total time waiting for the query semaphore
      "permit_wait_ms": 0,
      # Total number of entities returned from the database
      "entity_count": 200,
      # Number of by-block-constraint groups that actually queried the database
      "query_count": 200,
      # Number of by-block-constraint groups that were found in the cache
      "cached_count": 0
    },
    # One entry for each by-block-constraint group
    "blocks": [
      {
        "trace": {
          # The block at which queries in this group ran
          "block": 10600242,
          # Total time spent executing all queries for this block. Includes
          # all the times listed for each query below
          "elapsed_ms": 16,
          # One entry for each toplevel query for this block, labeled with
          # the GraphQL response key
          "<response key>": {
            "query": "<SQL query with bind variables>",
            # Time for sending query to database and receiving result
            "elapsed_ms": 1,
            # Time for getting a database connection prior to running a query
            "conn_wait_ms": 0,
            # Time for aquiring the query semaphore
            "permit_wait_ms": 0,
            # Number of entities for this query
            "entity_count": 1
          },
          "permit_wait_ms": 0
        },
        # Whether the query was run against the database or served from
        # cache. Possible values:
        #  miss:   run against database, result not added to cache
        #  insert  run against database, result added to cache
        #  hit:    served from cache; query timings will be from when the
        #          query was executed against the database
        #  shared: identical query was running simultaneously; we waited
        #          for that one to finish and use its result. Query timings
        #          from the execution against the database
        "cache": "insert"
      },
      ...
    ]
  },
  "http": {
    # Time it took to serialize the response from the internal
    # representation to JSON
    "to_json": "351.743µs",
    # Size in bytes of the internal representation
    "cache_weight": 11272
  }
}

Query caching

GraphQL queries can be repetitive in that the same query is made many times by different clients. To help reducing the load on the database in htese cases,graph-node has a builtin cache for query results. The cache operates at the level of toplevel fields in the GraphQL query grouped by block constraints: for a query with two block constraints, toplevel fields are grouped by them and each group is cached independently. Toplevel fields without block constraints have an implicit block constraint for the latest block that the subgraph has indexed.

The cache can be turned off completely by setting GRAPH_CACHED_SUBGRAPH_IDS=none. It defaults to *, which means all queries are eligible for caching. It is also possible to only cache queries for specific subgraphs by setting this to a comma-separated list of IPFS hashes.

The cache consists of two distinct caches: one for queries against recent blocks, and one for queries against historical blocks. The recent block cache in turn is split into one cache per network. The historical cache contains entries across all networks in one big table. The setting GRAPH_QUERY_CACHE_BLOCKS determines when a query for a block is considered recent. The recent blocks cache caches queries for the last GRAPH_QUERY_CACHE_BLOCKS. It defaults to 1, but a slightly higher value, like 6 is probably more useful.

There is actually a third caching mechanism, the herd cache. That is used when a query is made while the exact same query is still being processed. In that case, it is better to wait for the first query to finish and reuse its result rather than querying the database almost simultaneously. That's what the her cache does. That cache is also turned off through the GRAPH_CACHED_SUBGRAPHS.

The setting GRAPH_QUERY_CACHE_MAX_MEM controls the size of the query cache and is expressed in megabytes. It defaults to 1000 (1GB). The amount of memory used for caching is several times that: the recent block cache can use this much memory for each network, and the historical block cache can use this much memory again.

Both the recent blocks cache and the historical cache are sharded to reduce lock contention for cache lookups. For the recent blocks cache, the setting GRAPH_QUERY_BLOCK_CACHE_SHARDS controls how many shards that cache has. It defaults to 128 which is likely too high, especially for moderate query load. For the historical cache, the setting GRAPH_QUERY_LFU_CACHE_SHARDS controls the number of shards. It defaults to GRAPH_QUERY_BLOCK_CACHE_SHARDS. Setting that to 0 turns off the historical cache. The environment variable GRAPH_LOCK_CONTENTION_LOG_THRESHOLD_MS can be set to spot log contention: any attempt to acquire a lock that takes longer than this will result in a warning in the logs with the message Mutex lock took a long time to acquire with an id of the forms query_block_cache_*, query_herd_cache, or query_lfu_cache.

The recent blocks cache evicts entries by dropping the entire cache for a block when that block is more than GRAPH_QUERY_CACHE_BLOCKS behind the most recent block that was queried. The historical cache uses a least-frequently-used strategy and periodically removes entries to stay within the configured size. Those evictions happen every GRAPH_QUERY_CACHE_STALE_PERIOD queries for each cache shard separately.

This needs this PR Individual query results can be quite large. To prevent an enormous query result from filling up the cache, the setting GRAPH_QUERY_CACHE_MAX_ENTRY_RATIO, which defaults to 3, can be used to limit the size of results that will be cached. The size in bytes is calculated as the size of a cache shard divided by this. Each cache shard has size GRAPH_QUERY_CACHE_MAX_MEM divided by the number of shards.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment