perf: thrift filter decoding introduces high latency #13082
Description
Title: thrift filter introduces high latency
Description:
I observed high latency(thrift decoding cost 10ms+) when using thrift filter. qps under 1000, request/response message size < 1MB, connections < 100 , cpu usage < 0.01 core
envoy version: 1.12 ( cherry-picked the lastest thrift filter commits)
thrift protocol: framed + binary
Analysis shows most time is spent on thrift decoding. After dig into the code, I found thrift filter decode the whole struct of message to memory and encode it. I use thrift filter for loadbalancing, only metadata is useful. In this case, thrift filter waste a lot time decoding the struct part.
I wonder if we can add support to thrift filter to send the struct part as a passthrough.
Logs:
By replaying traffic from production, I observed 14ms latency for decoding a 930648 bytes message.
Following is debug log for a single request. For more detail, see trace log https://drive.google.com/file/d/1jkSPDFQmWBpa4BXbFJcdeNLzV9uiASbH/view?usp=sharing
[2020-09-14 21:00:54.437][17119][debug][conn_handler] [external/envoy/source/server/connection_handler_impl.cc:335] [C0] new connection
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:376] thrift: 65482 bytes available
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:397] thrift: framed(auto) transport started
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:431] thrift: protocol auto, state MessageBegin, 65478 bytes available
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/router/router_impl.cc:227] [C0][S5593458996354885164] cluster 'thrift_service' match for method 'PredictionService:Predict'
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/router/router_impl.cc:260] [C0][S5593458996354885164] router decoding request
[2020-09-14 21:00:54.437][17119][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:82] creating a new connection
[2020-09-14 21:00:54.437][17119][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:362] [C1] connecting
[2020-09-14 21:00:54.437][17119][debug][connection] [external/envoy/source/common/network/connection_impl.cc:706] [C1] connecting to 127.0.0.1:9090
[2020-09-14 21:00:54.437][17119][debug][connection] [external/envoy/source/common/network/connection_impl.cc:715] [C1] connection in progress
[2020-09-14 21:00:54.437][17119][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:108] queueing request due to no available connections
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:439] thrift: wait for continuation
[2020-09-14 21:00:54.437][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/conn_manager.cc:54] [C0] thrift filter stopped
[2020-09-14 21:00:54.437][17119][debug][connection] [external/envoy/source/common/network/connection_impl.cc:554] [C1] connected
[2020-09-14 21:00:54.438][17119][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:283] [C1] assigning connection
[2020-09-14 21:00:54.438][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/conn_manager.cc:127] [C0] thrift filter continued
[2020-09-14 21:00:54.438][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:376] thrift: 930611 bytes available
[2020-09-14 21:00:54.438][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:431] thrift: protocol binary(auto), state StructBegin, 930611 bytes available
[2020-09-14 21:00:54.452][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:455] thrift: framed(auto) transport ended
[2020-09-14 21:00:54.453][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:376] thrift: 12153 bytes available
[2020-09-14 21:00:54.453][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:397] thrift: framed transport started
[2020-09-14 21:00:54.453][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:431] thrift: protocol binary, state MessageBegin, 12149 bytes available
[2020-09-14 21:00:54.453][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:455] thrift: framed transport ended
[2020-09-14 21:00:54.453][17119][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/router/router_impl.cc:310] [C0][S5593458996354885164] response complete
Flamegraph
https://drive.google.com/file/d/1QNHe3I_fbXJtRAPY0alCNUiNO80Zfgf3/view?usp=sharing
Configuration
- filters:
- name: envoy.filters.network.thrift_proxy
config:
#typed_config:
# "@type": type.googleapis.com/envoy.config.filter.network.http_connection_manager.v2.HttpConnectionManager
stat_prefix: thrift_proxy
transport: AUTO_TRANSPORT
protocol: AUTO_PROTOCOL
route_config:
name: local_route
routes:
- match:
method_name: ""
route:
cluster: thrift_service
thrift_filters:
- name: envoy.filters.thrift.router