You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@servicecomb.apache.org by GitBox <gi...@apache.org> on 2020/02/25 02:22:59 UTC
[GitHub] [servicecomb-java-chassis] jiangqiushi opened a new issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
jiangqiushi opened a new issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593
ServiceComb版本：1.2.0.B006
服务端停机升级后，重新上线，客户端偶现490服务超时，但是从客户端的SlowInvocationLogger看不出问题出在哪个阶段。
通过客户端超时服务traceId追踪，服务端access log中没有该请求。
####客户端日志：
```xml
2020-02-25 00:02:08.159 | ERROR | [vert.x-eventloop-thread-8] | [] | [LoadbalanceHandler] | service CONSUMER rest tts_service_jtest.ttsservice.processTTS, call error, msg is cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:,message:The timeout period of 5000ms has been exceeded while executing POST /v1/tts/text2audio?null for host 10.31.57.5, server is rest://10.31.57.5:28087?sslEnabled=false&protocol=http2
2020-02-25 00:02:08.159 | ERROR | [vert.x-eventloop-thread-8] | [] | [LoadbalanceHandler] | Invoke server failed. Operation CONSUMER rest tts_service_jtest.ttsservice.processTTS; server rest://10.31.57.5:28087?sslEnabled=false&protocol=http2; 0-0 msg cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:,message:The timeout period of 5000ms has been exceeded while executing POST /v1/tts/text2audio?null for host 10.31.57.5
2020-02-25 00:02:08.160 | ERROR | [vert.x-eventloop-thread-8] | [] | [LoadbalanceHandler] | Invoke all server failed. Operation CONSUMER rest tts_service_jtest.ttsservice.processTTS, e=cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:,message:The timeout period of 5000ms has been exceeded while executing POST /v1/tts/text2audio?null for host 10.31.57.5
2020-02-25 00:02:08.160 | WARN | [gw_worker_20] | [] | [BizkeeperCommand] | bizkeeper command CONSUMER rest tts_service_jtest.ttsservice.processTTS failed due to InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request]
2020-02-25 00:02:08.160 | WARN | [gw_worker_20] | [] | [BizkeeperHandler] | bizkeeper execution error, info=cause:InvocationException,message:InvocationException: code=490;msg=CommonExceptionData [message=Cse Internal Bad Request];cause:,message:The timeout period of 5000ms has been exceeded while executing POST /v1/tts/text2audio?null for host 10.31.57.5
2020-02-25 00:02:08.160 | WARN | [gw_worker_20] | [] | [BizkeeperHandler] | catch error in bizkeeper:Consumer.tts_service_jtest.ttsservice.processTTS failed and fallback disabled.
2020-02-25 00:02:08.160 | WARN | [gw_worker_20] | [5e53f37b7b8724b8-2503128] | [SlowInvocationLogger] | slow(5000 ms) invocation, CONSUMER rest tts_service_jtest.ttsservice.processTTS:
http method: POST
url : /v1/tts/text2audio/
server : rest://10.31.57.5:28087?sslEnabled=false&protocol=http2
status code: 490
total : 5001.842 ms
prepare : 0.3 ms
handlers request : 0.147 ms
client filters request : 0.30 ms
send request : 0.0 ms
get connection : 0.0 ms
write to buf : 0.0 ms
wait response : 0.0 ms
wake consumer : 0.1 ms
client filters response: 0.0 ms
handlers response : 1.17 ms
2020-02-25 00:02:13.574 | INFO | [spectator-poller-0] | [] | [DefaultLogPublisher] |
os:
cpu:
all usage: 0.77% all idle: 99.23% process: 0.77%
net:
send(Bps) recv(Bps) send(pps) recv(pps) interface
33.197K 14.631K 21 27 eth0
vertx:
instances:
name eventLoopContext-created
registry 0
transport 0
monitor-center 0
transport:
client.endpoints:
remote connectCount disconnectCount queue connections send(Bps) receive(Bps)
10.31.57.5:28087 2 3 165 2 9 5.223K
10.31.35.137:28087 3 3 0 3 14 6.993K
(summary) 5 6 165 5 23 12.217K
threadPool:
coreSize maxThreads poolSize currentBusy rejected queueSize taskCount taskFinished name
25 100 0 0 NaN 0 0.0 0.0 cse.executor.groupThreadPool-group1
25 100 0 0 NaN 0 0.0 0.0 cse.executor.groupThreadPool-group0
consumer:
simple:
status tps latency operation
rest.200 0.0 0.000/0.000 asr_service.asrservice.asyncGetAsrResult
0.0 0.000/0.000 dlg_center_service_prod.SmurfsDialogApplication.answerV2
0.1 4.738/5.435 tts_service_jtest.ttsservice.processTTS
0.0 0.000/0.000 gop_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 asr_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 gop_service.asrservice.asyncGetAsrResult
0.1 4.738/5.435 (summary)
rest.490 0.0 0.000/0.000 asr_service.asrservice.asyncGetAsrResult
0.0 5001.842/5001.842 tts_service_jtest.ttsservice.processTTS
0.0 0.000/0.000 asr_service.asrservice.asyncUploadAsrData
0.0 5001.842/5001.842 (summary)
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [servicecomb-java-chassis] liubao68 commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
Posted by GitBox <gi...@apache.org>.
liubao68 commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593#issuecomment-590679686
增加连接数和vertical-count能够在一定程度上提供性能。如果你不期望增加， 那么就得降低单个请求的处理时间。 平均时延在4.738秒，所有少量请求超时是很大概率发生的事件。需要系统的测试下在不同的并发压力下，系统的吞吐量和时延分布，然后结合一些调优措施提升性能。 问题里面提到在服务重启的过程中偶然发现，有可能是重启的时候，需要重建连接，如果这个时候并发大，就可能导致请求排队，排队就会导致超时，超时会导致连接再次被重建，会出现短暂的恶性循环。 可以看看稳定状况下的平均响应时间是否有改善，确定是否上述问题，也可以看看服务端的性能统计数据，对比分析下。
```
rest.200 0.0 0.000/0.000 asr_service.asrservice.asyncGetAsrResult
0.0 0.000/0.000 dlg_center_service_prod.SmurfsDialogApplication.answerV2
0.1 4.738/5.435 tts_service_jtest.ttsservice.processTTS
0.0 0.000/0.000 gop_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 asr_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 gop_service.asrservice.asyncGetAsrResult
0.1 4.738/5.435 (summary)
```
小的超时时间设置可能导致上述短暂的恶性状态，可以设置较小的排队队列，及时丢弃已经超时的请求，客户端做好重试。这个是设置小的超时时间比较重要的可靠性保护措施。
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [servicecomb-java-chassis] liubao68 edited a comment on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
Posted by GitBox <gi...@apache.org>.
liubao68 edited a comment on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593#issuecomment-590679686
增加连接数和vertical-count能够在一定程度上提高性能。如果你不期望增加， 那么就得降低单个请求的处理时间。 平均时延在4.738秒，所有少量请求超时是很大概率发生的事件。需要系统的测试下在不同的并发压力下，系统的吞吐量和时延分布，然后结合一些调优措施提升性能。 问题里面提到在服务重启的过程中偶然发现，有可能是重启的时候，需要重建连接，如果这个时候并发大，就可能导致请求排队，排队就会导致超时，超时会导致连接再次被重建，会出现短暂的恶性循环。 可以看看稳定状况下的平均响应时间是否有改善，确定是否上述问题，也可以看看服务端的性能统计数据，对比分析下。
```
rest.200 0.0 0.000/0.000 asr_service.asrservice.asyncGetAsrResult
0.0 0.000/0.000 dlg_center_service_prod.SmurfsDialogApplication.answerV2
0.1 4.738/5.435 tts_service_jtest.ttsservice.processTTS
0.0 0.000/0.000 gop_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 asr_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 gop_service.asrservice.asyncGetAsrResult
0.1 4.738/5.435 (summary)
```
小的超时时间设置可能导致上述短暂的恶性状态，可以设置较小的排队队列，及时丢弃已经超时的请求，客户端做好重试。这个是设置小的超时时间比较重要的可靠性保护措施。
BWT : 看了下代码
```xml
rest:
client:
thread-count: 32
connection:
maxPoolSize: 10
idleTimeoutInSeconds: 10
keepAlive: true
http2:
maxPoolSize: 1
idleTimeoutInSeconds: 0
```
http2的配置项idleTimeoutInSeconds好像代码里面没使用，而是使用的rest client的配置，这个可能是代码有bug， 需要提一个issue修改一下。 参考源码 `RestTransportClient`
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [servicecomb-java-chassis] liubao68 commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
Posted by GitBox <gi...@apache.org>.
liubao68 commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593#issuecomment-590658026
从日志看，可能是客户端参数设置不合理，导致并发度过低，大量请求排队超时的缘故。 这些信息反映了这个情况：
1. 总时间超过5s，但是每个阶段时间都很少。 但是后面部分的时间为0， 所以其实是没有计算到后面的时间就超时了。在send request之前，就只有排队了。 这个和现象服务端没收到请求是一致的。
```
total : 5001.842 ms
prepare : 0.3 ms
handlers request : 0.147 ms
client filters request : 0.30 ms
send request : 0.0 ms
get connection : 0.0 ms
write to buf : 0.0 ms
wait response : 0.0 ms
wake consumer : 0.1 ms
client filters response: 0.0 ms
handlers response : 1.17 ms
```
2. 从下面日志看出大量请求排队, 从连接数为2可以看出，部分参数设置是不合理的，连接数过少，并发度上不去。
```
client.endpoints:
remote connectCount disconnectCount queue connections send(Bps) receive(Bps)
10.31.57.5:28087 2 3 165 2 9 5.223K
10.31.35.137:28087 3 3 0
```
导致这个原因可能是 vertical 数量设置过小的缘故， [参考](https://docs.servicecomb.io/java-chassis/zh_CN/transports/verticle-count/)
1.2.0.Bxxx版本实际上是 1.2.0的 pre release版本，所以估计是老版本问题，建议升级下新版本再试试。 或者加上下面的配置项试试:
估计是老版本：
```
servicecomb.rest.server.thread-count=10
```
或者新版本:
```
servicecomb.rest.server.verticle-count=10
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [servicecomb-java-chassis] liubao68 edited a comment on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
Posted by GitBox <gi...@apache.org>.
liubao68 edited a comment on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593#issuecomment-590679686
增加连接数和vertical-count能够在一定程度上提高性能。如果你不期望增加， 那么就得降低单个请求的处理时间。 平均时延在4.738秒，所有少量请求超时是很大概率发生的事件。需要系统的测试下在不同的并发压力下，系统的吞吐量和时延分布，然后结合一些调优措施提升性能。 问题里面提到在服务重启的过程中偶然发现，有可能是重启的时候，需要重建连接，如果这个时候并发大，就可能导致请求排队，排队就会导致超时，超时会导致连接再次被重建，会出现短暂的恶性循环。 可以看看稳定状况下的平均响应时间是否有改善，确定是否上述问题，也可以看看服务端的性能统计数据，对比分析下。
```
rest.200 0.0 0.000/0.000 asr_service.asrservice.asyncGetAsrResult
0.0 0.000/0.000 dlg_center_service_prod.SmurfsDialogApplication.answerV2
0.1 4.738/5.435 tts_service_jtest.ttsservice.processTTS
0.0 0.000/0.000 gop_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 asr_service.asrservice.asyncUploadAsrData
0.0 0.000/0.000 gop_service.asrservice.asyncGetAsrResult
0.1 4.738/5.435 (summary)
```
小的超时时间设置可能导致上述短暂的恶性状态，可以设置较小的排队队列，及时丢弃已经超时的请求，客户端做好重试。这个是设置小的超时时间比较重要的可靠性保护措施。
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [servicecomb-java-chassis] jiangqiushi commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
Posted by GitBox <gi...@apache.org>.
jiangqiushi commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593#issuecomment-590663607
> 从日志看，可能是客户端参数设置不合理，导致并发度过低，大量请求排队超时的缘故。 这些信息反映了这个情况：
>
> 1. 总时间超过5s，但是每个阶段时间都很少。 但是后面部分的时间为0， 所以其实是没有计算到后面的时间就超时了。在send request之前，就只有排队了。 这个和现象服务端没收到请求是一致的。
>
> ```
> total : 5001.842 ms
> prepare : 0.3 ms
> handlers request : 0.147 ms
> client filters request : 0.30 ms
> send request : 0.0 ms
> get connection : 0.0 ms
> write to buf : 0.0 ms
> wait response : 0.0 ms
> wake consumer : 0.1 ms
> client filters response: 0.0 ms
> handlers response : 1.17 ms
> ```
>
> 1. 从下面日志看出大量请求排队, 从连接数为2可以看出，部分参数设置是不合理的，连接数过少，并发度上不去。
>
> ```
> client.endpoints:
> remote connectCount disconnectCount queue connections send(Bps) receive(Bps)
> 10.31.57.5:28087 2 3 165 2 9 5.223K
> 10.31.35.137:28087 3 3 0
> ```
>
> 导致这个原因可能是 vertical 数量设置过小的缘故， [参考](https://docs.servicecomb.io/java-chassis/zh_CN/transports/verticle-count/)
>
> 1.2.0.Bxxx版本实际上是 1.2.0的 pre release版本，所以估计是老版本问题，建议升级下新版本再试试。 或者加上下面的配置项试试:
>
> 估计是老版本：
>
> ```
> servicecomb.rest.server.thread-count=10
> ```
>
> 或者新版本:
>
> ```
> servicecomb.rest.server.verticle-count=10
> ```
实际上我们期望走http2调用，服务端启用了http2，ServiceComb用户手册中关于[HTTP2](https://docs.servicecomb.io/java-chassis/1.x/zh_CN/transports/http2.html)的介绍，
连接数应该是足够的。
服务端配置：
```xml
rest:
address: 10.31.57.5:28087?sslEnabled=false&protocol=http2
server:
thread-count: 32
connection:
idleTimeoutInSeconds: 60
executor:
default:
group: 2
thread-per-group: 32
```
客户端的配置：
```xml
rest:
client:
thread-count: 32
connection:
maxPoolSize: 10
idleTimeoutInSeconds: 10
keepAlive: true
http2:
maxPoolSize: 1
idleTimeoutInSeconds: 0
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [servicecomb-java-chassis] jiangqiushi commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
Posted by GitBox <gi...@apache.org>.
jiangqiushi commented on issue #1593: 客户端偶现超时，SlowInvocationLogger无法提供有用信息
URL: https://github.com/apache/servicecomb-java-chassis/issues/1593#issuecomment-590701707
是的，我看了源码创建http2连接的时候没有使用自己idleTimeoutInSeconds配置项，这是个bug。
但是理论上，客户端最大连接数应该是这么算的吧？
```xml
thread-count（32） * maxPoolSize（1） * 服务实例数（2） = 64
```
最大连接数远远大于我们现在的性能要求，但是可能因为HTTP2错误使用了idleTimeoutInSeconds，导致连接不停的重建，我觉得这可能是问题。
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services