100% cpu problem with retrying

[ArtDu]

User, [07.11.2022 18:37]
дали небольшую нагрузку на cartridge-driver 0.9.1 (это java), и получили 100% CPU
java-клиент создан с политикой повторов. но до повторов не доходит, но тот код, который выполняется библиотекой для обработки потенциальных повторов, заваливает 6-ядерный процессор.
нагрузка небольшая: 200 тыс операций отправляются на роутер. после каждой 1000 асинхронных операций ждем их завершения (всех их), и так 200 раз. то есть синхронно-асинхронный пример. Все это добро работает 25 секунд. 100% CPU

User, [07.11.2022 18:37]
если убрать возможность повторов, то проблемы нет

User, [07.11.2022 18:39]
вот так создаем клиента:

        TarantoolClient<TarantoolTuple, TarantoolResult<TarantoolTuple>> client = TarantoolClientFactory.createClient()
                .withAddresses(tntProperties.getNodes().stream()
                        .map(node -> new TarantoolServerAddress(node.getHost(), node.getPort()))
                        .collect(Collectors.toList()))
                .withCredentials(tntProperties.getUser(), tntProperties.getPassword())
                .withConnectTimeout(1000 * connectTimeoutSec)
                .withReadTimeout(1000 * readTimeoutSec)
                .withRequestTimeout(1000 * requestTimeoutSec)
                .withConnectionSelectionStrategy(TarantoolConnectionSelectionStrategyType.PARALLEL_ROUND_ROBIN)
/*  если это раскомментировать, то привет 100% CPU              .withRetryingIndefinitely(TarantoolRequestRetryPolicies.retryNetworkErrors(),
                        policy -> policy
                                .withDelay(delayBeforeRetryMs)
                                .withRequestTimeout(1000 * requestTimeoutSec)
                                .withOperationTimeout(1000 * operationTimeoutSec)  // Попытки закончатся, как истечет этот таймаут
                )*/
                .withProxyMethodMapping()
                .build();

User, [07.11.2022 18:44]
виновата, судя по всему, TarantoolRequestRetryPolicies.wrapOperation

Artyom Dubinin, [07.11.2022 23:51]
а запросы без ретраинга прилетают успешно отработанные?

User, [07.11.2022 23:52]
все без ошибок

Artyom Dubinin, [07.11.2022 23:57]
а с ретраингом какие ошибки?

User, [08.11.2022 00:02]
я где то писал про ошибки ? ошибок нет вообще. проблема в 100% CPU

Artyom Dubinin, [08.11.2022 00:04]
Т.е. во врапере не разу ретраи не происходит?

User, [08.11.2022 00:05]
нет. да и не может дойти, потому что выполняется до истчения таймаута

Artyom Dubinin, [08.11.2022 00:07]
при чем тут таймаут?

User, [08.11.2022 00:14]

return operation.get().get(getRequestTimeout(), TimeUnit.MILLISECONDS);

User, [08.11.2022 00:40]
мне кажется проблема в том, как реализована обработка таймаута. в ForkJoinPool создается более 500 заданий которые висят на i/o. пул разбухает. каждый get с таймаутом видимо не бесплатный. и/или не бесплатно обслуживание самого пула. Детально не разбирался. но все время уходит на этот wrapper, как показывает jvm.

если вставлять асинхронно больше 1000, то и пул больше, там уже тысячи воркеров

User, [08.11.2022 14:27]
дополнительно:
TarantoolConnectionImpl: вот в этот листенер вообще не попадаем (в отладчике, да и в логе нет ничего):

        CompletableFuture<T> requestFuture = requestManager.submitRequest(request, resultMapper);
        channel.writeAndFlush(request).addListener(f -> {
            if (!f.isSuccess()) {
                requestFuture.completeExceptionally(
                        new RuntimeException("Failed to send the request to Tarantool server", f.cause()));
            } else {
                logger.debug("Request {} sent, status Success", request.getHeader().getSync());
            }
        });

и вызывает сомнение двойная обработка requestTimeout:

• RequestFutureManager.submitRequest -> timeoutScheduler.schedule( () -> ...., requestTimeout, ...)
• TarantoolRequestRetryPolicies.wrapOperation -> operation.get().get(getRequestTimeout(), ... )

кто из них первый сработает, неизвестно. но по коду похоже что порядок важен. лучше бы это все в одном месте обрабатывалось.

но напрямую к "CPU 100%" это вроде бы не относится

Artyom Dubinin, [08.11.2022 14:35]
Там по идеи не должно быть никаких подводных камней с ретраингом, потому что ретраинг ничем не отличается от обычного вызова, кроме того, что он ловит эксепшены и заново запускает вызов. Поэтому пока гипотиза такая, что ретраинг постоянно вызывается и delay маленький между ретраями и поэтому cpu в 100. Я задачу добавил к нам, посмотрю

User, [08.11.2022 14:36]
не вызывается. в дебаге туда не попадаем

[ArtDu]

Artyom Dubinin, [29.11.2022 14:43]
Привет, а какое значение у delayBeforeRetryMs?

Artyom Dubinin, [29.11.2022 14:48]
и что за метод вызываете, если хранимка, то какая логика под ним лежит

User, [29.11.2022 15:01]
привет. 500 мс
вызываем хранимку на роутере, которая вычисляет шард и дергает хранимку на сторадже, которая выполняет логику типа upsert: get, затем либо insert, либо update
в одной операции участвует ровно 1 кортеж
сетевых ошибок в логах нет

[ArtDu]

We need to remove get with timeout because It's the reason why driver run tasks synchronyous per thread. Thread wait the result, instead of starting new tasks

cartridge-java/src/main/java/io/tarantool/driver/api/retry/TarantoolRequestRetryPolicies.java

Line 127 in 64b0803

return operation.get().get(getRequestTimeout(), TimeUnit.MILLISECONDS);

cartridge-java/src/main/java/io/tarantool/driver/api/retry/TarantoolRequestRetryPolicies.java

Lines 114 to 144 in 64b0803

	@Override
	public <R> CompletableFuture<R> wrapOperation(Supplier<CompletableFuture<R>> operation, Executor executor) {
	Assert.notNull(operation, "Operation must not be null");
	Assert.notNull(executor, "Executor must not be null");
	return CompletableFuture.supplyAsync(() -> {
	long timeElapsed = 0;
	long tStart;
	Throwable ex;
	do {
	tStart = System.nanoTime();
	try {
	return operation.get().get(getRequestTimeout(), TimeUnit.MILLISECONDS);
	} catch (TimeoutException | InterruptedException e) {
	ex = e;
	} catch (ExecutionException e) {
	ex = e.getCause();
	}
	timeElapsed = timeElapsed + (System.nanoTime() - tStart) / 1_000_000L;
	if (timeElapsed >= getOperationTimeout()) {
	ex = new TarantoolTimeoutException(
	timeElapsed,
	ex);
	break;
	}
	} while (this.canRetryRequest(ex));
	throw new CompletionException(ex);
	}, executor);
	}
	}

[ArtDu]

Just for history

reproducer:

@Test
    void testInfiniteRetryTimeoutReached_withTimeout_() throws Exception {
        TarantoolClient<TarantoolTuple, TarantoolResult<TarantoolTuple>> client = TarantoolClientFactory.createClient()
            .withCredentials(new SimpleTarantoolCredentials(USER_NAME, PASSWORD))
            .withAddress(container.getRouterHost(), container.getRouterPort())
            .withConnectTimeout(1000)
            .withReadTimeout(1000)
            .withRetryingIndefinitely(policy -> policy.withDelay(500)
                .withRequestTimeout(2000)
                .withOperationTimeout(2000))
            .build();


        client.call("reset_request_counters").join();

        ArrayList<CompletableFuture<List<?>>> list = new ArrayList<>(1000);
        int batchSize = 1000;

        for (int i = 0; i < 200; i++) {
            for(int j = 0; j < batchSize; j++) {
                CompletableFuture<List<?>> future = client
                    .call("long_running_function", Collections.singletonList(0.01));
                list.add(j, future);
            }
            for(int j = 0; j < batchSize; j++) {
                assertEquals(list.get(j).join().get(0), true);
            }
            list.clear();
        }
    }

function long_running_function(seconds_to_sleep)
    fiber.sleep(seconds_to_sleep)
    return true
end