What is the base latency mesh is expected to add to a request for grahql sources (without caching)

[ntziolis]

UPDATE
For anyone finding this discussion. The answer to the question is mesh base latency added in the bare scenario outlined below is on average ~2.5ms.

The increased latency we saw was due to our networking setup (docker host bridge related). For details see here: #2102 (reply in thread)

Original Question

Its absolutely expected to see some latency added when introducing any form of gateway. The goal of this post is to compare the baseline we are seeing with others. As well as identifying if there is a need / possibility to reduce this base latency.

This is not about a specific scenario, but about the base latency that mesh will add no matter what when using in front of other graphql sources (without a cache).

In the following setup:

• One downstream graphql data source
  • schema / operation headers are specified in the config
• No Filters or transforms either on the source no on root level
• Everything runs locally
  • db (postgres)
  • downstream graphql source (hasura)
  • mesh

Test:

• Use a really simple query that does not tax the database to exclude db perf impact
  • We are talking really simple query {employee{id first_name}} with only 2 rows in the employee table
• Run the query ~20 times
  • hasura console (uses graphiql) to get a base line
  • mesh graphiql to get data we can compare to the baseline

Result:

• hasura console => 2-3ms
  • true from the first run
• mesh graphiql => 12-19ms (with more results above 15ms than below)
  • on first run / and any run after a cooldown period => 200-300ms

Note:

• We tested this with subscription and got pretty much the same result

Further info:

• We added time tracing inside the url loader just before and after the request is made
  • Results where returned in <1ms for every request, while in graphiql the response time was 12-20ms
  • This means that we can exclude the downstream data source as culprit for the added latency
• Also when when we added the following filters and renames

     - filterSchema:
         mode: wrap
         # use filter but include everything
         filters:
           - Query.*
           - Mutation.*
           - Subscription.*
     - rename:
         mode: wrap
         renames:
           - from:
               type: query_root
             to:
               type: Query
           - from:
               type: mutation_root
             to:
               type: Mutation
           - from:
               type: subscription_root
             to:
               type: Subscription       

• We saw NO difference in latency times (maybe 1ms, but neglectable). This is great as we expected a much bigger for using wrap transforms.

From the above the following questions arise:

• Is it expected to see the 10-20ms increase in latency even if there are no filters / transforms present?
• What causes the initial very significant latency increase?
  • Could this be mitigated with some sort of "i dont care about memory load everything on start" flag?
• What causes a cooldown which in turn causes similar significant latency increases as seen with first request
  • Is there any way to disable this cooldown behavior?

@ardatan I'd be really interested in your take on this.

[ntziolis]

See attached profiler image for where time is spend. this represents exactly one of the querying executed against through mesh:

[ardatan]

@ntziolis Maybe it would be better to do the same tests on a different environment.

[ntziolis]

Sure thing, I will wip something up. It will take me a moment though.

That said, can I take it that your general expectation is for mesh to add significantly less than ~12-20ms in such a bare setup?

[Urigo]

maybe it might be a good idea to add these scenarios as benchmarks and run them in the repo's CI?

[ntziolis]

I setup a Ubuntu 20.04.2 (non virtualized) to rerun the scenario:

• Initially I did not see a significant difference in performance 1-2ms less in Linux but still 6-9ms total
• Then I realized that the culprit was the host bridge in the docker docker networking setup
• The network path in the original setup was
  • The following containers run in a single docker network: dev, hasura, postgres
  • The dev container hosts the mesh
  • Mesh GraphiQL was being access on host via exposed port from container
    • request got routed from host to dev container
  • Mesh config was pointed to the hasura instance hasura via host.docker.internal:port
    • request gets routed from dev container to host to hasura container
  • The delays on the request path also apply to the response path
• After realizing this I changed the test setup to ensure that no traffic leaves the internal docker network by:
  • mesh config pointing to the hasura container directly vs host
  • and running curl inside the dev container, instead of using graphiql
  • this reduced the end to end time of a request by by >2x
• After this change Mesh only adds about 2-3ms to each request in a bare setup
  • hasura response time: 1.7-2.6ms
  • mesh response time: 3.9-5.5ms
• this makes sense and means that
  • not docker generally or node I/O in docker that was the problem
  • but setting up a network path that involved leaving the docker internal network is the issue
• While it generally does make sense I was a bit surprised by the magnitude of the delay introduced

In regards to Windows / Linux I retested in windows and the results are now on par with linux adding with mesh adding 2-3ms to a request

• hasura response time: 2-2.3ms
• mesh response time: 4.4-4.9ms

In addition:
I can also confirm that the latency did not increase noticeably (maybe 0.1 or 0.2 ms) when adding back in the filters and renames.

Bottomline:
As long as one stays inside the internal docker network there should be no in response times.

For reference I used a very bare bone script for this, posting it here for quick review, lmk if there are any red flags:

query='{"query":"query {employee{id last_name}}\n\n","variables":{}}'
count=100

hasura () {
    hasuraUrl="http://hasura:8080/v1/graphql"
    hasuraSecret="our-secret"    
    totalTime=0

    for i in $(seq $count); do    
        respTime=$(curl "$hasuraUrl" \
            -H 'Content-Type: application/json' \
            -H "x-hasura-admin-secret: $hasuraSecret" \
            --data-raw "$query" \
            --compressed \
            -s -o /dev/null -w "%{time_starttransfer}\n")
        totalTime=$(echo "scale=6; $totalTime+$respTime" | bc)
    done

    echo hasura: $(echo "scale=6; $totalTime/$count*1000" | bc)
}

mesh(){
    meshUrl="http://127.0.0.1:4000/graphql"
    totalTime=0

    for i in $(seq $count); do        
        respTime=$(curl "$meshUrl" \
             -H 'Content-Type: application/json' \
             --data-raw "$query" \
             --compressed \
             -s -o /dev/null -w "%{time_starttransfer}\n")             
        totalTime=$(echo "scale=6; $totalTime+$respTime" | bc)
    done

    echo mesh: $(echo "scale=6; $totalTime/$count*1000" | bc)
}

# tried different order, results stayed the same
mesh
hasura

Note:

• The reason we use host.docker.internal in most places is that some of our devs don't like working in dev containers
• This way they can run the solution without dev containers as well
• That said given these results I will be rethinking our strategy to enable outside devcontainer development

[ntziolis]

I wane thank you guys for jumping right in. Sry if you invested time in this since it was a setup error on our end. I have updated the original question with a simplified answer and reference to my last post for others to easily an answer what an expected base line for graphql-mesh should be expected.

If there is interest in adding a performance section outlining expected baselines etc. on the doc site I'd be happy to assist in setting up the necessary testing environment.

Personal note:
I'm very impressed with the mere ~2.5ms, I was expecting significantly more.