java-client icon indicating copy to clipboard operation
java-client copied to clipboard

Timeout Exception after 1 minute but set to 5 minutes

Open Thorben91 opened this issue 1 year ago • 4 comments

I have a Qdrant database with 65.909.239 points. When I do a large query with my Java application using searchBatchAsync() I get a timeout exception. I have set all timeouts to 5 minutes, but the exception always comes after 1 minute. Have I overlooked something or where do I have to set the timeout. I am using Qdrant 1.13.4 and io.qdrant.client:1.13.0.

Here is my code:

@Override
public QdrantClient getClient() {
	final var client = new QdrantClient(QdrantGrpcClient.newBuilder(ManagedChannelBuilder.forAddress("localhost", 6334)
			.usePlaintext()
			.maxInboundMessageSize(Integer.MAX_VALUE)
			.maxInboundMetadataSize(Integer.MAX_VALUE)
			.idleTimeout(Duration.ofMinutes(5L).toSeconds(), TimeUnit.SECONDS)
			.keepAliveTimeout(Duration.ofMinutes(5L).toSeconds(), TimeUnit.SECONDS)
			.build(), true, false).withApiKey(API_KEY).withTimeout(Duration.ofMinutes(5L)).build());
	return client;
}

@Override
public SearchPoints convertVectorToSearchPoints(final Float[] vector) {
	return convertVectorToSearchPoints(getCollectionName(), vector);
}

@Override
public SearchPoints convertVectorToSearchPoints(final String collectionName, final Float[] vector) {
	final var searchPoints = SearchPoints.newBuilder()
			.setCollectionName(collectionName)
			.addAllVector(List.of(vector))
			.setLimit(2L)
			.setTimeout(Duration.ofMinutes(5L).toSeconds())
			.setParams(SearchParams.newBuilder().setExact(false).build())
			.setWithPayload(WithPayloadSelector.newBuilder().setEnable(true).build())
			.setWithVectors(WithVectorsSelector.newBuilder().setEnable(true).build())
			.build();
	return searchPoints;
}

try (final var client = getClient()) {
	final var searchPointsList = queryVectors.stream().map(this::convertVectorToSearchPoints).toList();
	final var results = client.searchBatchAsync(collectionName, searchPointsList, ReadConsistency.newBuilder().setFactor(1L).setType(ReadConsistencyType.All).build(), Duration.ofMinutes(5L)).get();
}

Here is the exception:

2025-02-18 15:21:22,962 - ERROR [grpc-default-executor-3] io.qdrant.client.QdrantClient []: Search batch operation failed
io.grpc.StatusRuntimeException: INTERNAL: Service internal error: 1 of 1 read operations failed:
  Timeout error: Operation 'Search' timed out after 60 seconds
        at io.grpc.Status.asRuntimeException(Status.java:533) ~[grpc-api-1.65.1.jar:1.65.1]
        at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:538) ~[grpc-stub-1.65.1.jar:1.65.1]
        at io.grpc.internal.DelayedClientCall$DelayedListener$3.run(DelayedClientCall.java:489) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.DelayedClientCall$DelayedListener.delayOrExecute(DelayedClientCall.java:453) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.DelayedClientCall$DelayedListener.onClose(DelayedClientCall.java:486) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:564) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl.access$100(ClientCallImpl.java:72) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:729) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:710) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[grpc-core-1.65.1.jar:1.65.1]
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
        at java.base/java.lang.Thread.run(Thread.java:1583) [?:?]
2025-02-18 15:21:22,982 - ERROR [pool-25-thread-1] my.application.views.qdrant.SearchView []: Exception caught - java.util.concurrent.ExecutionException: io.grpc.StatusRuntimeException: INTERNAL: Service internal error: 1 of 1 read operations failed:
  Timeout error: Operation 'Search' timed out after 60 seconds
java.util.concurrent.ExecutionException: io.grpc.StatusRuntimeException: INTERNAL: Service internal error: 1 of 1 read operations failed:
  Timeout error: Operation 'Search' timed out after 60 seconds
        at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:604) ~[guava-33.4.0-jre.jar:?]
        at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:579) ~[guava-33.4.0-jre.jar:?]
        at com.google.common.util.concurrent.FluentFuture$TrustedFuture.get(FluentFuture.java:91) ~[guava-33.4.0-jre.jar:?]
        at my.application.api.qdrant.QdrantServiceImpl.searchBestMatches(QdrantServiceImpl.java:231) ~[classes/:?]
        at my.application.api.qdrant.QdrantServiceImpl.searchBestMatches(QdrantServiceImpl.java:216) ~[classes/:?]
        at my.application.api.qdrant.QdrantServiceImpl.searchBestMatches(QdrantServiceImpl.java:206) ~[classes/:?]
        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[?:?]
        at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[?:?]
        at org.apache.wicket.proxy.jdk.JdkProxyFactory$JdkHandler.invoke(JdkProxyFactory.java:172) ~[wicket-ioc-10.3.0.jar:10.3.0]
        at jdk.proxy3/jdk.proxy3.$Proxy393.searchBestMatches(Unknown Source) ~[?:?]
        at my.application.views.qdrant.SearchView.search(SearchView.java:42) ~[classes/:?]
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
        at java.base/java.lang.Thread.run(Thread.java:1583) [?:?]
Caused by: io.grpc.StatusRuntimeException: INTERNAL: Service internal error: 1 of 1 read operations failed:
  Timeout error: Operation 'Search' timed out after 60 seconds
        at io.grpc.Status.asRuntimeException(Status.java:533) ~[grpc-api-1.65.1.jar:1.65.1]
        at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:538) ~[grpc-stub-1.65.1.jar:1.65.1]
        at io.grpc.internal.DelayedClientCall$DelayedListener$3.run(DelayedClientCall.java:489) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.DelayedClientCall$DelayedListener.delayOrExecute(DelayedClientCall.java:453) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.DelayedClientCall$DelayedListener.onClose(DelayedClientCall.java:486) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:564) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl.access$100(ClientCallImpl.java:72) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:729) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:710) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.65.1.jar:1.65.1]
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[grpc-core-1.65.1.jar:1.65.1]
        ... 3 more

Here is the Qdrant logging:

2025-02-18T15:21:22.734159Z ERROR qdrant::tonic::logging: gRPC /qdrant.Points/SearchBatch unexpectedly failed with Internal error "Service internal error: 1 of 1 read operations failed:\n  Timeout error: Operation 'Search' timed out after 60 seconds" 60.130383

Why does my timeout of 5 minutes not work, does anyone have an idea or can help?

Best regards Thorben

Thorben91 avatar Feb 18 '25 16:02 Thorben91

@generall Why was the issue moved, it looks like a server problem. I have now added a current DEBUG logging from the client. It clearly shows that the client is sending the correct timeout (5 minutes in milliseconds): grpc-timeout: 299979m

2025-02-20 12:41:36,711 - DEBUG [grpc-nio-worker-ELG-1-8] io.grpc.netty.shaded.io.grpc.netty.NettyClientHandler []: [id: 0x4701046c, L:/127.0.0.1:57921 - R:localhost/127.0.0.1:6334] OUTBOUND HEADERS: streamId=3 headers=GrpcHttp2OutboundHeaders[:authority: localhost:6334, :path: /qdrant.Points/SearchBatch, :method: POST, :scheme: http, content-type: application/grpc, te: trailers, user-agent: grpc-java-netty/1.65.1, grpc-accept-encoding: gzip, api-key: REMOVED, grpc-timeout: 299979m] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false

The timeout error message also comes from the server. A timeout error message from the client looks different and would not appear in the logs from the Qdrant server.

Best regards Thorben

Thorben91 avatar Feb 20 '25 11:02 Thorben91

there are many different timeouts, conenction timeout, execution timeout e.t.c. They should be properly configured on client side

generall avatar Feb 20 '25 12:02 generall

As you can see from my code above, I have set each timeout to 5 minutes. More timeouts cannot be configured in the client. As can be seen from the DEBUG log output from the client, my timeout is correctly transmitted to the Qdrant server via gRPC, but the Qdrant server aborts after 60 seconds with a corresponding error message.

Thorben91 avatar Feb 20 '25 12:02 Thorben91

The problem still exists and everything still points to a problem on the server side! Can anyone please help?

Thorben91 avatar Mar 05 '25 08:03 Thorben91