x-envoy-upstream-service-time is more large than expected respond time

Question

We are using seldon-core + ambassador 1.14.3 to build our services.

But recently we found that some respond time from ambassador is too long.

the upstream pod after ambassador just calc n + 1 and return result, and it cost less than 1ms.

As we had the ambassador debug logs below.

[2022-06-16 09:17:38.187][209][debug][http] [source/common/http/conn_manager_impl.cc:254] [C39] new stream
[2022-06-16 09:17:38.187][209][debug][http] [source/common/http/conn_manager_impl.cc:886] [C39][S17049628811525024967] request headers complete (end_stream=false):
':authority', '10.11.145.30:30080'
':path', '/seldon.protos.Model/Predict'
':method', 'POST'
':scheme', 'http'
'content-type', 'application/grpc'
'te', 'trailers'
'user-agent', 'grpc-java-netty/1.45.1'
'seldon', 'rmd0006'
'namespace', 'mlmodel'
'x-client-trace-id', 'b9e3dcef490f494b96ecbb20b1ff9417'
'grpc-accept-encoding', 'gzip'
'grpc-timeout', '2999982u'

[2022-06-16 09:17:38.187][209][debug][router] [source/common/router/router.cc:425] [C39][S17049628811525024967] cluster 'cluster_rmd0006_groovy_mlmodel_9501_mlmodel' match for URL '/seldon.protos.Model/Predict'
[2022-06-16 09:17:38.187][209][debug][router] [source/common/router/router.cc:582] [C39][S17049628811525024967] router decoding headers:
':authority', '10.11.145.30:30080'
':path', '/seldon.protos.Model/Predict'
':method', 'POST'
':scheme', 'http'
'content-type', 'application/grpc'
'te', 'trailers'
'user-agent', 'grpc-java-netty/1.45.1'
'seldon', 'rmd0006'
'namespace', 'mlmodel'
'x-client-trace-id', 'b9e3dcef490f494b96ecbb20b1ff9417'
'grpc-accept-encoding', 'gzip'
'grpc-timeout', '2999982u'
'x-forwarded-for', '10.254.9.0'
'x-forwarded-proto', 'http'
'x-envoy-internal', 'true'
'x-request-id', '330a778e-f9e9-4ace-a6d7-530efe466b97'
'x-envoy-expected-rq-timeout-ms', '3000'

[2022-06-16 09:17:38.187][209][debug][router] [source/common/router/upstream_request.cc:359] [C39][S17049628811525024967] pool ready
[2022-06-16 09:17:38.187][209][debug][http] [source/common/http/filter_manager.cc:778] [C39][S17049628811525024967] request end stream

here we use tcpdump & wireshark trace tcp with upstream pod, it just cost 1ms as expect.

tcpdump result

[2022-06-16 09:17:38.227][209][debug][router] [source/common/router/router.cc:1174] [C39][S17049628811525024967] upstream headers complete: end_stream=false
[2022-06-16 09:17:38.227][209][debug][http] [source/common/http/conn_manager_impl.cc:1501] [C39][S17049628811525024967] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'application/grpc'
'grpc-encoding', 'identity'
'grpc-accept-encoding', 'gzip'
'x-envoy-upstream-service-time', '39'
'date', 'Thu, 16 Jun 2022 09:17:37 GMT'
'server', 'envoy'


[2022-06-16 09:17:38.227][209][debug][http] [source/common/http/conn_manager_impl.cc:1517] [C39][S17049628811525024967] encoding trailers via codec:
'grpc-status', '0'

The ambassador respond time is more large than service pod respond time.

If you have encountered this problem, please help give me some ideas