Установленный крайний срок gRPC и разница времени ожидания вызова ниже, чем крайний срок

Question

Я делаю вызовы gRPC из java-сервиса и использую withDeadlineAfter(1000, TimeUnit.MILLISECONDS).callApi()

В большинстве случаев этот вызов прерывается (DEADLINE_EXCEEDED). Когда я проверил логи, это выглядит следующим образом

2019-06-14 06:30:09.153 +0000 - [DEBUG] - from io.grpc.internal.ClientCallImpl - Call timeout set to '999861860' ns, due to context deadline. Explicit call timeout was not set.
2019-06-14 06:30:09.909 +0000 - [ERROR] - from application - [ epoch=1560493809909 req=1560493808679.df7ns.10.0.3.96 ] - EVENT_MIGRATION:Failed to create channel: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 999695013ns

Если я правильно понимаю, крайний срок был установлен во время 06: 30: 09.153 на 1 секунду после 09.153 , что фактически означает, что вызов с заглушкой должен прерваться после 10,153 . Исключение было брошено намного раньше зарегистрированного времени.

Может кто-нибудь объяснить, пожалуйста, поведение?

Answer 1

Я ожидаю, что проблема заключается в том, что время регистрации измерялось с точки, отличной от крайнего срока.А именно, "ns" были вычислены до того, как регистратор извлек текущее время.

Это было бы особенно заметно с новым процессом Java, поскольку загрузка классов и медленный интерпретатор Java означают, что вы можете видеть значительные промежутки времени между кодомВы ожидаете быть быстрым.Также было бы возможно, если бы система работала с перебоями из-за подкачки или высокой средней нагрузки.