Performance of handling data fetcher response data

Hi,

While performance testing our application (a JEE application running in WildFly, where a Servlet accepts client requests and processes them using graphql-java), we noticed a request throughput decrease from a source we didn't expect: if we simply return 'null' in our data fetcher(s) but do perform all other processing (parse the incoming request, do all processing in the data fetcher in order to construct the resulting response object, etc.), the throughput of our application increases significantly (usually at least doubling compared to when we do actually return a response in the data fetcher). While we did expect some overhead to be generated by the GraphQL parsing and processing, we didn't expect the impact to be this big.
(Note: the limiting factor during our load tests was the available CPU. Our application works on in-memory data, so in most cases, we're not waiting on database access or request to other systems in order to process client requests. The CPU was always at 100% while executing tests.)

As a test, I created a simple stand-alone web application for verification. It uses a simple GraphQL schema (located in src/main/resources) that contains some simple nested types and queries to retrieve them. A dedicated data fetcher is available for each of these queries. A compiled .war file of the web application can be found in the target directory of the attached zip.

In order to test the impact of different parts of the application, certain parts can be enabled or disabled in the test servlet:

returnData: when 'true', the data fetcher implementations will return pre-generated instances of the correct type. If 'false', no data will be returned by the data fetchers (i.e. this is where we noticed the performance impact in our application)
returnResponse: when 'true', the result of the GraphQL processing will be transformed into JSON and written into the client response. When 'false', the GraphQL result will not be converted. Using this setting, it can be made sure that the JSON transformation that is usually done after the GraphQL processing is not influencing the measured throughput.
cpuLoadSize: Some simple list-manipulation code (sort & randomize) will simulate the actual CPU processing that a normal application would have to perform in order to generate response objects. This setting will specify the size of the list that is being used (and as such the amount of processing simulated). During the tests on my PC, I used a list size of 4096, which usually resulted in 1 or 2 millisecs of processing when going at max throughput.

These settings can be changed at runtime using an HTTP GET request. As an example, http://localhost:8080/graphql/graphql?returnData=true&returnResponse=false&cpuLoadSize=4096 would cause the data fetchers to return actual responses, CPU processing is simulated using a list with 4096 items, and the GraphQL processing result is not transformed into JSON, and not returned to the client.

I executed four test queries (which can be found under src/test/resources) on my PC using this application (using WildFly as web server):

queryOne.txt: Retrieves the TypeOne instance with all its properties and all children with all their properties
queryOne-min.txt: Retrieves the TypeOne instance with all its children, but doesn't retrieve any of the simple properties
queryTwo.txt: Retrieves the TypeTwo instance with all its properties and children
queryThree.txt: Retrieves the TypeThree instance with all its properties.

In the attached results.pdf, the troughput that I measured on my system when executing these queries in different scenarios can be found:

In Test 1, all functionality is enabled, so this simulates a fully active application.
Test 2 will (compared to test 1) just disable the conversion of the GraphQL result into JSON. All other tests will also have the JSON conversion disabled, so that it doesn't influence the measured throughput.
In Test 5, nothing is enabled, so the application is only parsing the incoming GraphQL query, and calling the datafetchers. No data is actually returned by the data fetchers, no response is returned to the client and no CPU load is simulated, resulting in the maximum throughput that can be achieved when doing no processing.
Test 4 will (compared to test 5) simulate CPU load that would be needed to construct the data that is being requested in the data fetcher. No data is being returned by the data fetchers however.
Test 3 will (compared to test 5) return a pre-generated object in the data fetcher, but will not simulate any additional CPU load that may be needed to create this response data.

Is it expected that the handling of data fetcher responses consumes this much of the CPU, especially where more complex responses are needed? I do understand that processing is needed on the data (e.g. in case any of the child properties returned needs further processing by another registered data fetcher, which is something that we do actually use in our full application), but the impact of this additional processing (which in this example application should only result in 'simple' property-getters being invoked) does seem more significant that we expected.
graphlperftest.zip
results.pdf

Thanks for the thoughtful and considered issue. You have put a lot of effort in this and we appreciate that.

if we simply return 'null' in our data fetcher(s) but do perform all other processing (parse the incoming request, do all processing in the data fetcher in order to construct the resulting response object, etc.), the throughput of our application increases significantly (usually at least doubling compared to when we do actually return a response in the data fetcher). While we did expect some overhead to be generated by the GraphQL parsing and processing, we didn't expect the impact to be this big.

The parsing and validation of a graphql query is pretty fast - the ANLTR code is simple string processing into AST nodes and the validation is running over those nodes in a visitor pattern and enforcing graphql rules (eg all variables must be used etc...)

Most queries have very small ASTs and hence it takes very little compute power. And for the record there is no asynchronous behavior - its all CPU bound.

So we have an expectation that the data fetching is ALWAYS the slowest part by a large margin

I had a look at your test harness and I can see some problems in the sense that I am not convinced you are testing the real world well enough.

As you say its completely CPU bound. You use no threading at all and hence your graphql queries per request execute ONLY on that request thread. This keeps things simple but it does not represent a typical graphql field call to a database say or local disk in some way where there is IO and hence threading opportunities on multi processors.

For the record graphql-java results CAN return CompletableFuture values and hence you can use executor services such as https://docs.oracle.com/javase/8/docs/api/java/util/concurrent/ForkJoinPool.html

So what you are really testing here is the PropertyDataFetcher which is the code in graphql-java that runs over a POJO and maps "field names" to POJO values.

https://github.com/graphql-java/graphql-java/blob/master/src/main/java/graphql/schema/PropertyDataFetcher.java

It does use Reflection for this eg name field maps to a getName call on the POJO. However we have made specific fixes to this to cache resolved getter methods and hence call costs in a future call.

#1012
#1013

The Flame graphs dramatically improved with these fixes.

For the record ProperyDataFetcher can also work over Maps and these are much faster than POJOs but untyped maps suck. However if your downstream call (say to the database / network) can be a Map then you are best to leave it as a Map (eg dont use Jackson to make it a POJO say since it will be made back into a map later during execution)

I am assuming you want to get some assurances of the performance aspects of your future graphql based system and hence this test. However you are only really testing that ProperyDataFetcher in this test.

In the real world the mapping of POJO/Map properties to fields is likely to be the smaller cost compared to database calls and network calls.

I urge you to do a performance test where there is real IO. You will likely see that the PropertyDataFetcher times are orders of magnitude slower than the IO times.

And then one with a ExecutorService backed system versus a blocking request per web request thread and see your results.

Also if you want to get some anecdotal comfort about real world applications using graphql-java. here at Atlassian where I work, the Jira View Issue screen is powered by a graphql-java end point (lovingly named /gira) and it takes millions of request per day and View Issue has a dedicated performance team looking into all aspects of its performance. And never once has the graphql-java ProperyDataFetcher come up as bottle neck nor the graphql-java engine execution in general. The performance challenges are always in the "data" layers (eg database / network calls)

However I will not discount that we may have a performance problem in our ProperyDataFetcher and we would love to see more specific information and findings around it.

Hi Brad,

Thank you for the response. Some remarks however:

As you say, when other IO is involved (network, database, ...), these are indeed more likely to become a performance bottleneck than the CPU that is utilised in the simple example web app I attached. I created the example in this way however since it simulates the case we have on our project. While there are some queries (or usually in our project: mutations) that do depend on other systems (i.e. network traffic to a different server that also does processing), the queries that I was testing are generating responses for the clients purely based on data that we have cached in memory within the application: some static data that is shared between all clients is stored in one set of maps/caches, and some data that is client-specific and is stored in another cache (all cached data is stored in memory, no external caching is used). This static data and client-specific data needs to be combined in order to generate a reply that is for the requesting client, hence the CPU processing. During the throughput testing of those queries on our application, it was indeed the CPU that was the bottleneck (being used nearly 100%). That's why I added the 'cpuLoadSize' setting to the example web app: simulate the CPU processing that we have to do inside the datafetcher in order to generate the client response data. A larger cpuLoadSize results in a larger list used for CPU processing simulation, results in more work done in the data fetcher.

Note that the example web app wasn't created as a proof of concept to measure the performance, but was created as a very simplified version of the application that we're currently performance testing. While there were other areas in our code that were impacting the performance and have been updated, and there is probably more optimization that can be done on the processing side, the fact that not returning the generated response object in the datafetcher caused the throughput to usually about double surprised me.
This did result into me looking for a short while at the graphql-java code, and I did indeed notice that PropertyDataFetcher would have to use reflection to retrieve the data from the java objects. As a test to see if that influenced performance, I also did a test with some code that would (using reflection and based on the GraphQL schema) in advance register a dedicated data fetcher for each property of each type that could be retrieved retrieved, where the datafetcher would know in advance with which java.lang.reflect.Method instance to retrieve the property. This did not result in a significant performance difference however. Note that since each property had a datafetcher registered in this case, I would assume that during this test, the PropertyDataFetcher wouldn't be used anymore? So I assume that that is not the source of the performance dip we're seeing.
While looking at the PropertyDataFetcher code, I did indeed also notice that the PropertyDatFetcher could handle Maps as response objects instead of POJOs. So as a different test, I also tried (in our full application) to convert our POJOs into map instances (using Jackson) before returning them from the data fetcher that was involved in the test. Here once more, I didn't see a significant difference. In this case, I assume that the additional processing by Jackson to convert the POJOs into maps probably took up enough of the performance gain in the PropertyDataFetcher so that the end result wasn't that big of a performance gain anymore? Since I already did another test on the performance of the JSON conversion of response data using Jackson (which can also be done with the 'response=true/false' setting in the example web app), the results of those tests made me conclude that while Jackson does require some processing to convert POJOs, the amount of this processing in the overall processing time wasn't a worry at this time.

Kind regards,

-Johan

So we have an expectation that the data fetching is ALWAYS the slowest part by a large margin
...
As you say its completely CPU bound. You use no threading at all and hence your graphql queries per request execute ONLY on that request thread. This keeps things simple but it does not represent a typical graphql field call to a database say or local disk in some way where there is IO and hence threading opportunities on multi processors.
...
In the real world the mapping of POJO/Map properties to fields is likely to be the smaller cost compared to database calls and network calls.

A late follow up to this.

The problem with this view is you're essentially hoping the rest of the system is so slow that the framework overhead doesn't matter.

I don't think these are safe or reasonable assumptions about the real world usage of the framework. I've worked on several real world APIs that serialize primarily from data structures in memory (which are kept up to date in background threads), each with hundreds of thousands of concurrent users.

I've also worked on graphql APIs backed by fast database storage (Redis) where the GQL java layer still remained the bottleneck.

In addition, to achieve parallel processing, a common and often simpler solution is to leave each request single threaded, allowing the HTTP layer to process many requests in parallel.

And never once has the graphql-java ProperyDataFetcher come up as bottle neck nor the graphql-java engine execution in general. The performance challenges are always in the "data" layers (eg database / network calls)

Atlassian's use case is clearly different, and the overheads elsewhere significant enough that the framework overhead isn't worth addressing. But I just want to add a counterpoint, having built and optimised several Java GQL APIs over the last 5 years where scalability and performance was important: in every case the graphql-java engine overhead has come up as the bottleneck.

(edit: aside from this aspect, in every case the library has also been a pleasure to develop and deliver with, in case this comes across as overly critical).

the overheads elsewhere significant enough that the framework overhead isn't worth addressing.

There is a mild implication above is that we are doing nothing to address framework overhead. That's simply not true. The last 3-4 releases of graphql-java have concerned themselves more with performance and micro optimisations than they have in features.

The reason for that is the library has reach a maturity peak and the consumers of the library have grown in ambition.

Twitter (and others) for example have made contributions around performance areas brought on by large schemas and we are trying right now to build a "JMH" regression capability for that tests we have. We moved to Immutable collections because of the list copying inherent in graphql for performance reasons and we try to embrace lazy patterns for some of our more expansive API features like field sub selection.

I will agree with you that IF you have lightning faster data fetching layer - then the graphql framework will start to dominate the cpu overhead. The graphql spec is rich and the "code must visit every field" nature of it means that graphql as an API strategy as a certain overhead (compared to say REST where its take request and echo back some object no questions asked or checked)

The practical implications of this are that you would not use graphql for cases where you need absolute speed ( high frequency stock trading say).

Thanks for following up - yes somewhat unfair of me to reply to a comment that is over 3 years old, and have been excited to see the performance changes in the last few releases.

The graphql spec is rich and the "code must visit every field" nature of it means that graphql as an API strategy as a certain overhead (compared to say REST where its take request and echo back some object no questions asked or checked)

I don't actually think inherently there has to be any more overhead than REST at a per-request level. Because the schema can't change at runtime, a concept of "compiling" the schema on startup could theoretically move that complexity and processing out of the per-request chain. Even more so if you can take advantage of most high volume services dealing with the same set of queries.

Obviously that's a significant engineering challenge, but as a huge GraphQL proponent, I just think it's a pity if we have a mindset of "GraphQL will always be slower".

Anyway, rather than just comment from the sidelines, hopefully I get bandwidth to create some PRs for some low hanging fruit I've observed in our profiling, which is generally around the repetitive per-field overhead when serializing large arrays of simple record-type objects.

Even more so if you can take advantage of most high volume services dealing with the same set of queries.

note that we have the graphql.execution.preparsed.PreparsedDocumentProvider which allows you to cache the parsing and validation of queries you have seen before. We used in Atlassian and saved upwards of 7-15ms for some of the large queries.

a concept of "compiling" the schema on startup could theoretically move that complexity and processing out of the per-request chain.

how do you see this compilation happening. Is this a priori knowledge known at system build time or general purpose calculated by the graphql engine say? Can you expand this statement.

which is generally around the repetitive per-field overhead when serializing large arrays of simple record-type objects.

Again can you expand this statement more and the use case -

Guessing at this I think you might mean trusting that a returned Java object from a DataFetcher can be trusted to have all the fields underneath it and hence skip further processing - is that right? I might be off track here.

how do you see this compilation happening. Is this a priori knowledge known at system build time or general purpose calculated by the graphql engine say? Can you expand this statement.

General purpose, based on the schema and the types/interface of the implementing resolvers/fetchers. I only say "compilation" in an abstract sense, I don't have any informed view on the implementation, but it's a matter of taking advantage of :

knowledge of the schema, at startup
knowledge of the interface/types of the implementing resolver/fetchers, at startup

With a goal to making the per-request framework overhead very low (similar to a REST framework, for example).

Again can you expand this statement more and the use case -
Guessing at this I think you might mean trusting that a returned Java object from a DataFetcher can be trusted to have all the fields underneath it and hence skip further processing - is that right? I might be off track here.

I believe it's a combination of many things. Let's say I have a type with 5 scalar fields representing a movie. And a query in the schema that returns a list of 100 movies, so a query from a client might end up with a JSON response with 500 fields. My movie type is implemented in Java with a simple DTO type object. Maybe my step to retrieve the list of movies is async, but I would expect once I provide the engine with List<DumbMovieRecord>, from there it should be very fast at turning this into a response.

However, it's not. #2605 is probably a significant factor here - I believe the engine acts as if every getter on my movie object might be async, even though it never can be (for my particular implementation, which is known at compile and startup), and wraps each one in a CompletableFuture.

But there are also more basic overheads too. On every one of those 500 serialized values (representing a list of 100 of a single type with 5 scalar fields), that are ultimately mapped to a simple getter, a lot is happening:

type/field definitions are repeatedly looked up in every iteration through the list
instrumentation context objects are created and passed to no-op instrumentations (we disable instrumentation to reduce overhead)
a new DataFetchingEnvironment is created, despite never being ultimately used
data fetcher factory environment and field coordinates are recreated
... etc etc

Some of these are probably simple micro-optimisations (eg a continuation of the existing lazy supplier patterns), others not so simple.

But there are also more basic overheads too. On every one of those 500 serialized values (representing a list of 100 of a single type with 5 scalar fields), that are ultimately mapped to a simple getter, a lot is happening:

This is just thinking aloud here on this. I suspect we would need some sort of "opt in mechanism" for a DF to return a completed list of objects. Some sort of signal to the engine to skip what it might normally do.

Spitballing it might be something like

DataFetcher df = env -> {
   ...
   return DataFetcherResult.ofFinalisedData(bigList);
}

This requires opt in from the DF itself say otherwise the engine would not know to perform some optimisation on how to treat data.

The price of this is that the safe guards put into place by the graphql spec and engine would be skipped.

For example imagine a DateTime scalar and some attribute in the bigList being declared as a DateTime. If the DF gets it wrong - there will be no coercing happening that would notice the bad datetime value say.

Similarly a field could be declared as String but the POJO might returns an Integer - this will go on the wire as "strField" : 45678 and not "strField" : "45678" because no coercing happened.

And other areas like non null field checking would be skipped - eg fieldX : String! would not be checked that it is indeed non null and hence nullable values for non nullable fields could escape.

I bring this up because this is the price of such an optimisation. It is indeed more like REST because the type system is being subverted. In REST for example you might say in Swagger that a object attr is {"type" : "integer" } but nothing checks that it really is and hence its a good hint and if everything is perfect then it works - until it doesnt.

But one can imagine that in order to achieve the maximum output speed of graphql data, an implementation may choose to lower the type system safety and hence get throughput at the expense of correctness

I don't believe you'd have to (or want to) give up type safety, that seems drastic.

In my example, if I declare my Movie class with standard types that maps cleanly to scalars (rather than a bunch of methods returning CompletableFuture<Object> or something), after a single set of reflection calls on startup, you can guarantee it can never return odd types. Even if it did, surely something in the chain would throw an exception as the coercing failed.

Some of this is perhaps complicated by the boundary/contract of graphql-java and frameworks like kickstarter that are providing reflection based fetchers that map to classes etc, the exact split between I'm admittedly a bit vague on.

Null checks seem mandatory until Java has proper consistent compile time null/not null checks.

I'm not commenting from a position of any real in-depth knowledge of the framework though.

I had an investigation / spike on what it might take to stop execution of the engine and not run the usual steps but rather accept a result as is

#2950

It's nearly 2 orders of magitude faster (for certain data) but the type safety / sub selection is very low

In my example, if I declare my Movie class with standard types that maps cleanly to scalars (rather than a bunch of methods returning CompletableFuture or something), after a single set of reflection calls on startup, you can guarantee it can never return odd types.
.................

I have been exploring something related in https://github.com/jord1e/graphql-java-asm-datafetcher

The first time the DataFetcher returns a non-null type it generates bytecode to act like you have written a class for every method in a class and compiled it.

When you call for field name on a person object it will no longer use reflection. It will instead generate a temporary class (that is reused):

public String forgotTheName(DataFetchingEnvironment dfe) {
  Object source = dfe.getSource();
  if (source == null) {
    return null;
  }
  return ((Person) source).getName();
}

The code sucks at the moment and the generated bytecode can be optimised (with maps and annotations specifying behaviour/configuration on classes/GraphQL definitions etc.). Will probably work on that in the future.

It balances between compile-time generation and generating on the first datafetcher call (so lazily). The second one is much easier to perform.

Performance increase already was 9x-10x last time I checked. But it really needs improvement before it is production-ready.

Hi,

Any update on this ? , we are facing a similar issue as well. To give some context, we built an aggregator service using Graphql (using Kickstart library) which will call multiple downstream service and serves the data. (There is no DB call involved).We use dataloaders a lot. We are seeing significant CPU usage here. On analyzing the thread dump, we can see a similar issue reported above. Sharing a few for reference,

These are the state that was captured when CPU was high.

GraphQL thread

"graphql-exec-11" #245 prio=5 os_prio=0 tid=0x00007fbfe4018800 nid=0x69ec runnable [0x00007fbfb25a3000]
   java.lang.Thread.State: RUNNABLE
	at graphql.execution.instrumentation.ChainedInstrumentation$ChainedInstrumentationState.getState(ChainedInstrumentation.java:218)
	at graphql.execution.instrumentation.ChainedInstrumentation$ChainedInstrumentationState.access$000(ChainedInstrumentation.java:208)
	at graphql.execution.instrumentation.ChainedInstrumentation.getState(ChainedInstrumentation.java:64)
	at graphql.execution.instrumentation.ChainedInstrumentation.lambda$beginField$6(ChainedInstrumentation.java:124)
	at graphql.execution.instrumentation.ChainedInstrumentation$$Lambda$1051/907445286.apply(Unknown Source)
	at graphql.collect.ImmutableKit.map(ImmutableKit.java:84)
	at graphql.execution.instrumentation.ChainedInstrumentation.beginField(ChainedInstrumentation.java:123)
	at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:206)
	at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60)
	at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667)
	at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454)
	at graphql.execution.ExecutionStrategy.completeValueForList(ExecutionStrategy.java:546)
	at graphql.execution.ExecutionStrategy.completeValueForList(ExecutionStrategy.java:500)
	at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:439)
	at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404)
	at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212)
	at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
	at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
	at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
	at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211)
	at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60)
	at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667)
	at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454)
	at graphql.execution.ExecutionStrategy.completeValueForList(ExecutionStrategy.java:546)
	at graphql.execution.ExecutionStrategy.completeValueForList(ExecutionStrategy.java:500)
	at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:439)
	at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404)
	at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212)
	at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
	at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
	at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
	at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211)
	at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60)
	at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667)
	at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454)
	at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404)
	at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212)
	at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
	at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
	at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
	at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211)
	at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60)
	at graphql.execution.Execution.executeOperation(Execution.java:159)
	at graphql.execution.Execution.execute(Execution.java:105)
	at graphql.GraphQL.execute(GraphQL.java:613)
	at graphql.GraphQL.parseValidateAndExecute(GraphQL.java:538)
	at graphql.GraphQL.executeAsync(GraphQL.java:502)
	at graphql.kickstart.execution.GraphQLInvoker$$Lambda$728/1017792343.executeAsync(Unknown Source)
	at graphql.kickstart.execution.GraphQLInvoker.executeAsync(GraphQLInvoker.java:37)
	at graphql.kickstart.execution.GraphQLInvoker.execute(GraphQLInvoker.java:28)
	at graphql.kickstart.servlet.HttpRequestInvokerImpl.invoke(HttpRequestInvokerImpl.java:164)
	at graphql.kickstart.servlet.HttpRequestInvokerImpl.lambda$invokeAndHandleAsync$2(HttpRequestInvokerImpl.java:79)
	at graphql.kickstart.servlet.HttpRequestInvokerImpl$$Lambda$1001/566610721.run(Unknown Source)
	at com.abc.aggregator.server.graphql.context.MDCContextTaskDecorator.lambda$decorate$0(MDCContextTaskDecorator.java:20)
	at com.abc.aggregator.server.graphql.context.MDCContextTaskDecorator$$Lambda$1002/1079170835.run(Unknown Source)
	at org.springframework.security.concurrent.DelegatingSecurityContextRunnable.run(DelegatingSecurityContextRunnable.java:82)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)

DATALOADER THREAD

"dataloader-executor50" #129 prio=5 os_prio=0 tid=0x00007fbfc001a000 nid=0x6970 runnable [0x00007fbfbd9d6000] java.lang.Thread.State: RUNNABLE at java.util.HashMap.putVal(HashMap.java:658) at java.util.HashMap.put(HashMap.java:613) at graphql.execution.instrumentation.dataloader.FieldLevelTrackingApproach$CallStack.increaseExpectedFetchCount(FieldLevelTrackingApproach.java:50) at graphql.execution.instrumentation.dataloader.FieldLevelTrackingApproach.beginExecutionStrategy(FieldLevelTrackingApproach.java:134) - locked <0x00000006b3d78bd8> (a graphql.execution.instrumentation.dataloader.FieldLevelTrackingApproach$CallStack) at graphql.execution.instrumentation.dataloader.DataLoaderDispatcherInstrumentation.beginExecutionStrategy(DataLoaderDispatcherInstrumentation.java:140) at graphql.execution.instrumentation.ChainedInstrumentation.lambda$beginExecutionStrategy$4(ChainedInstrumentation.java:108) at graphql.execution.instrumentation.ChainedInstrumentation$$Lambda$1044/652196505.apply(Unknown Source) at graphql.collect.ImmutableKit.map(ImmutableKit.java:84) at graphql.execution.instrumentation.ChainedInstrumentation.beginExecutionStrategy(ChainedInstrumentation.java:106) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:46) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628) at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996) at graphql.execution.ExecutionStrategy.resolveFieldWithInfo(ExecutionStrategy.java:211) at graphql.execution.AsyncExecutionStrategy.execute(AsyncExecutionStrategy.java:60) at graphql.execution.ExecutionStrategy.completeValueForObject(ExecutionStrategy.java:667) at graphql.execution.ExecutionStrategy.completeValue(ExecutionStrategy.java:454) at graphql.execution.ExecutionStrategy.completeField(ExecutionStrategy.java:404) at graphql.execution.ExecutionStrategy.lambda$resolveFieldWithInfo$1(ExecutionStrategy.java:212) at graphql.execution.ExecutionStrategy$$Lambda$1103/513823736.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) at org.dataloader.DataLoaderHelper.lambda$dispatchQueueBatch$2(DataLoaderHelper.java:251) at org.dataloader.DataLoaderHelper$$Lambda$1161/186899273.apply(Unknown Source) at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1609) at com.abc.aggregator.server.graphql.context.MDCContextTaskDecorator.lambda$decorate$0(MDCContextTaskDecorator.java:20) at com.abc.aggregator.server.graphql.context.MDCContextTaskDecorator$$Lambda$1002/1079170835.run(Unknown Source) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:750)

Based on the above dumps, you may find an easy win is disabling instrumentation - graphql.GraphQL.Builder#doNotAddDefaultInstrumentations.

For Dataloader i have set it to NoopStatisticsCollecter. Is that what you mean ? Also i have a class which extends SimpleInstrumentation, where i have some custom logic basically to emit execution time latency metrics and some logging etc. I'm using Graphql kickstart lib. Haven't seen a way to override this property. Can you give some pointers on how i can override this with Graphql kickstart librarby?

@adrian-skybaker

@adrian-skybaker : I tried extending the DataLoaderDispatcherInstrumentation class and basically return a no op in it's execution . But data loaders are not working after this. Also i observed that , even if the field is not loaded by dataloader, it still goes through the DataLoaderDispatcherInstrumentation flows.

@adrian-skybaker

@adrian-skybaker : Will dataloaders work if we set this graphql.GraphQL.Builder#doNotAddDefaultInstrumentations?
@bbakerman

Will dataloaders work if we set this graphql.GraphQL.Builder#doNotAddDefaultInstrumentations?

No this will stop the DataLoaderDispatcherInstrumentation from loading and this is crucial to using DataLoaders in graphql-java, since it knows when to dispatch them on field completion

@padmapreethi-902117

@padmapreethi-902117 - It's great that you capture some thread stack traces but this is rarely enough to truly nail down where the CPU is being burnt. The stack trace above is what I would expect to see in any normal graphql-java based app. So no insights provided there.

You best bet is to use a tool like JProfiler to nail down in more specifics what time is being spent where.

@bbakerman

@bbakerman So my Graphql schema is bit heavy on list (overall response size is within 300-500KB(max) ). And i can see ExecutionStrategy#CompletValueForList is being triggered multiple times which itself is causing a overhead to the overall latency. Do you recommend some sort of ParallelExecutionStrategy specifically for lists?

@bbakerman

I'm trying something around, extending AsyncExecutionStrategy and override the completeValueForList method to execute the list items parallely. @bbakerman : Is this feasible to optimise?

@bbakerman

@bbakerman : Any thoughts on this ?

override the completeValueForList method to execute the list items parallely

This seems like an interesting approach - graphql-java itself would never do any threading (since threading is a concern of consumers not the base engine).

If it works out faster for you, then great. It would NOT burn less CPU - in fact it would burn more since there needs to be thread context switching and work coordination.

But depending on your data shapes it may leads to a faster response.

I would be interested in how this worked out for you

@bbakerman

Hi @bbakerman,

we have meanwhile (probably) encountered the same phenomenon in our project.

In our case

the GQL standard serialization is about 15 times slower than a manual JSON serialization
GQL serialization takes about 8 times as lang than (simply) fetching the data from RDMBS

I created a fork of the "spring-guides/gs-graphql-server" repository to compare GQL standard serialization with manual JSON serialization.(including a script for measurement):

https://github.com/itd-jt/gs-graphql-server-serialization-performance

The readme of the repository describes more details. (The effects respectively the relations are very similar with our production code.)

We would be particularly interested to know if this performance is to be expected or if there is anything that can be done (other than manual serialization) to speed up GQL serialization.

Thanks for the support and best regards
Jakob

We would be particularly interested to know if this performance is to be expected or if there is anything that can be done (other than manual serialization) to speed up GQL serialization.

The performance is to be expected. The current engine in graphql (both in graphql-java and the reference graphql-js) run data fetchers over every data attribute.

So if you have

type Query {
    books : [Book]
{

type Book {
    title : String!
    isbn : String
    publishDate : LocalDateTime
}


query q {
   books {
      author
      publishDate
   }
}

And you returned 1000 book entries in that list - the graphql engine will invoke the data fetcher books once (and get 1000 entries in memory) and then for every entry it will invoke the data fetchers for the fields asked for (author / publishDate) 1000 times.

Why does it do that? Because of type safety and field subselection.

The data fetcher that loaded the books could be reasons load up the whole book. Maybe it's calling some REST service and it always returns 3 book attributes and not the two asked for in the query.

The returned data might be { author : "JRR Tolkien", isbn : "74745627223", publishDate : "01/08/1967"} but the query only wanted 2 entries.

So the engine has to visit each object and subselect the attributes that are required via the query subselection. This means it has to visit each object in the list and create a "map" of the sub-selected data from the original source object.

Now it might be that you can load data that perfectly fits the subselection - but the engine does not know this and with complex types thi quickly becomes hard to do.

Finally there is type safety. In our example we had a publishDate : LocalDateTime - this custom scalar needs to "serialise" the in memory representation to the scalar representation - maybe the in memory book object has the publishDate in seconds since epoch and the custom scalar will tweak that into some ISO data format. It has to visit every object to do that.

A final example is non null checking. In our example we have title : String! - so code needs to check that the title attribute in each in memory book is present and do graphql error processing when its not.

All this subselection and type safety has a price. That price is that the engine must visit each node and run code. We have tried to make that code as fast as possible (PropertyDataFetcher is highly optimized and the scalars do very little work) but they do work nonetheless

Now lets contrast this to a REST request. First off there is typically (but not always) little concept of subselection.

GET /books

A common pattern is that all the book data comes back - over fetching - even if the client does not want it. graphql solves this but it has a higher price.

A typical REST implementation might be to just trust the data is in the right shape - so lets hope the publishDate is in the right format when lifted up. Now systems like Jackson allow a lot of this to be handled which is cool.

So on flat entities like "get books" - a RESTian system will always beat a graphql system in pure speed and if pure speed is your only consideration then you should not use graphql (see above in comments for more on that)

But if you want to build flexible data retrival mechanisms where entities are a graph of data and clients can compose together when they ask - then graphql is a proven winner

query madeUpMoreCompexBookExample {
   books {
       title
       publishDate 
       relatedBooks {
          title
          isbn
          byTheSameAuthor {
            title
          }
      }
}

expressing this made up example in a RESTian system is ... well good luck.

In your example you have two representations - a rich one that a client could navigate because it has a graphql schema available to it and the data is in that format

allBooks(nrOfBooks: Int!): [Book]

and you have a JSON in a String format that nominally a client cant know anything about. Its just a string. Now you might know its JSON in a string and you could choose to tightly couple your server and clients in this way. Another alternative is a JSON scalar : https://github.com/graphql-java/graphql-java-extended-scalars#object--json-scalars

allBooksAsJSON(nrOfBooks: Int!): String

This works with flat objects like "books" but it falls down if you build a more complex graph of objects.

GQL serialization takes about 8 times as lang than (simply) fetching the data from RDMBS

This is surprising and not my live experience but everyone has different situations.

There is one things you might be able to do to make graphql fetching faster - if you are not using DataLoaders you can turn off Instrumentation which adds overhead to the fetching process. graphql.GraphQL.Builder#doNotAddDefaultInstrumentation

On the other hand this behavior can become a critical issue for use cases like data export, reporting or data transfer where a large amount of data is fetched from a GQL backend and processed further.

You are spot on here - graphql is not well suited to large data intensive situations like export. This is not an area where it shines

Good luck

Hello, this issue has been inactive for 60 days, so we're marking it as stale. If you would like to continue this discussion, please comment within the next 30 days or we'll close the issue.

Hello, as this issue has been inactive for 90 days, we're closing the issue. If you would like to resume the discussion, please create a new issue.

Navigation Menu

Repository navigation

Performance of handling data fetcher response data #1485

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Performance of handling data fetcher response data #1485

Description

Activity

bbakerman commented on Apr 5, 2019

jvanbz commented on Apr 5, 2019

adrian-skybaker commented on Sep 4, 2022

bbakerman commented on Sep 4, 2022

adrian-skybaker commented on Sep 4, 2022

bbakerman commented on Sep 7, 2022

adrian-skybaker commented on Sep 7, 2022

bbakerman commented on Sep 7, 2022

adrian-skybaker commented on Sep 8, 2022

bbakerman commented on Sep 9, 2022

jord1e commented on Sep 16, 2022

padmapreethi-902117 commented on Sep 29, 2022

adrian-skybaker commented on Sep 29, 2022

padmapreethi-902117 commented on Sep 29, 2022

padmapreethi-902117 commented on Sep 29, 2022

padmapreethi-902117 commented on Sep 29, 2022

bbakerman commented on Sep 30, 2022

bbakerman commented on Sep 30, 2022

padmapreethi-902117 commented on Sep 30, 2022

padmapreethi-902117 commented on Sep 30, 2022

padmapreethi-902117 commented on Oct 3, 2022

bbakerman commented on Oct 9, 2022

itd-jt commented on Oct 13, 2023

bbakerman commented on Oct 13, 2023

github-actions commented on Feb 3, 2024

github-actions commented on Mar 4, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions