Spring Boot 3.1.6 health endpoint latency is very high when other query is running.

[patiramyadav]

Spring Boot 3.1.6 health endpoint latency is very high when other query is running.

[dariuszkuc]

Spring Boot Webflux defaults to reactor Netty threadpool which in turns defaults to max(cpu, 4). By default, we don't switch graphql-java execution to other threads (as it is expensive) and it should generally be up to the clients to configure long running queries to use different dispatchers... but maybe we should.

You have few options

• per Netty documentation you could try providing dedicated IO worker thread by specifying -Dreactor.netty.ioSelectCount=1 and also potentially increasing worker threads
  • haven't tried it but it does sound like it should alleviate your health endpoint issue
• run graphql-java requests in a different thread by wrapping it in a coroutine dispatcher*
  • extend default SpringGraphQLServer and just wrap its execution with default dispatcher

class MySpringGraphQLServer(
    requestParser: SpringGraphQLRequestParser,
    contextFactory: SpringGraphQLContextFactory,
    requestHandler: GraphQLRequestHandler
) : SpringGraphQLServer(requestParser, contextFactory, requestHandler) {
    override suspend fun execute(request: ServerRequest): GraphQLServerResponse? = withContext(Dispatchers.Default) {
        super.execute(request)
    }
}

*we may end up pushing this change to the repo as well

[patiramyadav]

please provide a repository link where issue can be reproduced

It is on private project, I will try to create public project and add there.

[samuelAndalon]

please provide a repository link where issue can be reproduced

[patiramyadav]

In heavy IO mode this happens, hard to upload whole project. I don't have 24hour live mock server. If you guys have mock server and open api spec, I will generate client, I need at least two mock servers(micro services).

This problem happens when all the reactive threads are busy and the time acts like blocking. My management port is different 9999, does it share same thread pool with port 8080?

Something like this should solve the problem:

@OptIn(ExperimentalCoroutinesApi::class)
val customDispatcher = Dispatchers.IO.limitedParallelism(300)
suspend fun <T> withIOContext(block: suspend () -> T) = withContext(customDispatcher) {
    block()
}

But I am not sure how to configure this globally singleton way.

I used k6 to generate the traffic:
query.ts

import { check, sleep } from 'k6';
import http from 'k6/http';

// Use istio url
const BASE_URL = 'http://localhost:8080/graphql'

// Add customerId and accountId so that each request will pick randomly from here.
const listOfAccountDetails = [
  { 'accountId': '1', 'customerId': '2' },
  { 'accountId': '3', 'customerId': '4' },
  { 'accountId': '5', 'customerId': '6' },
  { 'accountId': '7', 'customerId': '8' },
  { 'accountId': '9', 'customerId': '10' },
  { 'accountId': '11', 'customerId': '12' },
];

export const options = {
  duration: '10000d', // Run forever
  vus: 500,
  thresholds: {
    checks: ['rate>0.9'] // Ensures > 90% of function checks are successful
  }
};


function account_query2(accountId, customerId) {
  return `
      query fetchAccount1{
        account1(accountId: "${accountId}", customerId:"${customerId}"){
          activities(fromDate: "2010-01-01", toDate:"2023-12-02"){
            amount
          }
        }
      }`;
}

// Main function to execute the request
export default function () {
  const randomIndex = Math.floor(Math.random() * listOfAccountDetails.length);
  const accDetails = listOfAccountDetails[randomIndex];
  const request = account_query2(accDetails.accountId, accDetails.customerId)
  console.log(JSON.stringify(accDetails));
  const accountResponse = http.post(BASE_URL, JSON.stringify({ query: request }), {
    headers:
    {
      "Content-Type": "application/json",
      'requester-id': "12345666666",
      'role': 'agent',
      "x-b3-traceid": 'xxxxxxxx-xxxx-4xxx-yxxx-xxxxxxxxxxxx'.replace(/[xy]/g, function (c) {
        let r = Math.random() * 16 | 0, v = c == 'x' ? r : (r & 0x3 | 0x8);
        return Math.random() * 16 | 0, v = c == 'x' ? r : (r & 0x3 | 0x8).toString(16);
      }),
      "x-b3-spanid": "xxxxxxx",
      "x-b3-parentspanid": "1242314314",
      "x-b3-sampled": "1"
    }
  });
  console.log(accountResponse.body, accountResponse.status);
  console.log(JSON.parse(accountResponse.body));
  check(accountResponse, {
    'account query is 200': (r) => { return r.status === 200 && !("errors" in JSON.parse(r.body)) }
  });
}

health.ts

import { check, sleep } from 'k6';
import http from 'k6/http';

// Use istio url
const BASE_URL = 'http://localhost:9999/health'


export const options = {
  duration: '10000d', // Run forever
  vus: 1,
  thresholds: {
    checks: ['rate>0.9'] // Ensures > 90% of function checks are successful
  }
};

// Main function to execute the request
export default function () {
  const accountResponse = http.get(BASE_URL);
  console.log(accountResponse.body, accountResponse.status);
  console.log(JSON.parse(accountResponse.body));
  check(accountResponse, {
    'health query is 200': (r) => { return r.status === 200 && !("errors" in JSON.parse(r.body)) }
  });
  // sleep(3)
}

[patiramyadav]

Screen.Recording.2023-12-05.at.11.29.57.PM.mov

For security reason I can't show whole screen, Left side: calling /health endpoint single user(health in cloud usually have single call). Right side: actual query with 500 users.

query throughput:

 http_reqs......................: 4720   37.184813/s
     http_req_duration..............: avg=8.6s     min=0s       med=7.53s max=1m0s   p(90)=9.94s  p(95)=32.46s
       { expected_response:true }...: avg=8.09s    min=678.83ms med=7.86s max=59.76s p(90)=9.61s  p(95)=13.52s

health endpoint throughput:

     http_reqs......................: 7       0.062976/s
     http_req_duration..............: avg=15.4s    min=11.85s med=16.29s max=17.46s p(90)=17.07s  p(95)=17.26s  
       { expected_response:true }...: avg=15.4s    min=11.85s med=16.29s max=17.46s p(90)=17.07s  p(95)=17.26s  

health check timeout could be increased but not ideally more than 5 sec.
I am not expert on writing core framework but health check if enabled should have higher priority or configurable or dedicated thread in reactive framework.

[patiramyadav]

When I am wrapping like this problem solved, but I have lots of query. Service1 is actually service, hiding name.

[patiramyadav]

@dariuszkuc Something like this doesn't work.

java -Dreactor.netty.ioSelectCount=200 -jar application/build/libs/application-0.0.1-SNAPSHOT.jar com.company.orchestrator.MainKt

This worked for me, thanks lot.

class IOSpringGraphQLServer(
    requestParser: SpringGraphQLRequestParser,
    contextFactory: SpringGraphQLContextFactory,
    requestHandler: GraphQLRequestHandler
) : SpringGraphQLServer(requestParser, contextFactory, requestHandler) {
    @OptIn(ExperimentalCoroutinesApi::class)
    override suspend fun execute(request: ServerRequest): GraphQLServerResponse? {
        val withContext = withContext(Dispatchers.IO.limitedParallelism(300)) {
            super.execute(request)
        }
        return withContext
    }
}

And config:

@Configuration
class GraphQLConfig(
    private val requestParser: SpringGraphQLRequestParser,
    private val contextFactory: SpringGraphQLContextFactory,
    private val requestHandler: GraphQLRequestHandler
) {
    @Bean
    fun ioSpringGraphQLServer(): IOSpringGraphQLServer {
        return IOSpringGraphQLServer(requestParser, contextFactory, requestHandler)
    }
}

[dariuszkuc]

I'm guessing you should be increasing the workers instead of IO selector thread, per Netty docs it should be -Dreactor.netty.ioSelectCount=1 -Dreactor.netty.ioWorkerCount=200.

That being said.... since graphql-kotlin is based on the reactive paradigm, IMHO 200/300 threads is waaaaaay too many (this looks kind of like config you would use for blocking servlet Tomcat based configuration) as most of them will never be used. If you are non-blocking (i.e. using coroutines and switching work as necessary) then you generally only need couple compute threads -> Dispatchers.Default should be plenty. You would then switch to Dispatchers.IO for the IO calls or to some other thread for some heavy computation work.

Also note that the switch there in the GraphQLServer is only for the overall graphql-java engine orchestration, individual data fetchers will run in the default coroutine scope (assuming you are using coroutines) unless you provide custom context with a different dispatcher.

[patiramyadav]

Agreed: spring-cloud/spring-cloud-gateway#1844 I see here. It works with those.

[samuelAndalon]

Will create a PR to execute operations out of the reactor http epoll