brpc icon indicating copy to clipboard operation
brpc copied to clipboard

bthread_creation_max_latency延迟过大

Open vinllen opened this issue 2 years ago • 3 comments

Describe the bug (描述bug) 非BUG,问题定位。 开启了FLAGS_show_bthread_creation_in_vars,目前显示bthread创建时间(max延迟)过大,max达到100-150ms,P9999看起来最大在10ms,正常不到1ms,但是本身bthread usage使用率不到一半,CPU/内存负载并不高,请问有什么情况下会导致这个bthread创建时间过大?

worker usage:

bthread_timer_usage : 0.00517015
bthread_worker_count : 45
bthread_worker_usage : 15.9525
bthread_worker_usage_51840 : 0.380111
bthread_worker_usage_51841 : 0.254136
bthread_worker_usage_51842 : 0.371774
bthread_worker_usage_51843 : 0.251471
bthread_worker_usage_51844 : 0.24348
bthread_worker_usage_51845 : 0.301761
bthread_worker_usage_51846 : 0.254467
bthread_worker_usage_51847 : 0.256903
bthread_worker_usage_51848 : 0.2545
bthread_worker_usage_51849 : 0.324174
bthread_worker_usage_51850 : 0.382035
bthread_worker_usage_51851 : 0.254862
bthread_worker_usage_51852 : 0.25711
bthread_worker_usage_51853 : 0.250151
bthread_worker_usage_51854 : 0.249609
bthread_worker_usage_51855 : 0.372599
bthread_worker_usage_51856 : 0.375154
bthread_worker_usage_51857 : 0.254612
bthread_worker_usage_51858 : 0.25015
bthread_worker_usage_51859 : 0.377874
bthread_worker_usage_51860 : 0.250818
bthread_worker_usage_51861 : 0.375357
bthread_worker_usage_51862 : 0.253064
bthread_worker_usage_51863 : 0.302341
bthread_worker_usage_51864 : 0.297399
bthread_worker_usage_51865 : 0.372837
bthread_worker_usage_51866 : 0.241416
bthread_worker_usage_51867 : 0.367837
bthread_worker_usage_51868 : 0.378367
bthread_worker_usage_51869 : 0.378046
bthread_worker_usage_51870 : 0.378745
bthread_worker_usage_51871 : 0.305297
bthread_worker_usage_51872 : 0.379981
bthread_worker_usage_51873 : 0.325682
bthread_worker_usage_51874 : 0.304342
bthread_worker_usage_51875 : 0.372135
bthread_worker_usage_51876 : 0.390805
bthread_worker_usage_51877 : 0.379916
bthread_worker_usage_51878 : 0.252689
bthread_worker_usage_51879 : 0.406393
bthread_worker_usage_51880 : 0.295973
bthread_worker_usage_51881 : 0.306851
bthread_worker_usage_51882 : 0.234954
bthread_worker_usage_51883 : 0.302123
bthread_worker_usage_51884 : 0.248518

To Reproduce (复现方法)

Expected behavior (期望行为)

Versions (各种版本) OS: Compiler: brpc: protobuf:

Additional context/screenshots (更多上下文/截图)

vinllen avatar Aug 02 '23 11:08 vinllen

本身bthread usage使用率不到一半,CPU/内存负载并不高

这个显示的是一段时间的平均值。有可能瞬时worker usage较高,bthread得不到及时调度,所以出现了一些长尾

wwbmmm avatar Aug 16 '23 12:08 wwbmmm

本身bthread usage使用率不到一半,CPU/内存负载并不高

这个显示的是一段时间的平均值。有可能瞬时worker usage较高,bthread得不到及时调度,所以出现了一些长尾

我们这边生产集群也有这个现象。 针对大佬说的瞬时并发,我试了一下用rpc_replay设置相同qps减少瞬时值影响,确实可以降低长尾,瞬时并发较高应该是bthread调度长尾的一个原因。但是长尾依旧比较长(bthread_creation_latency平均200us,三九线4500us),大佬还有啥别的想法吗? 例如client的bthread调度要比server的bthread调度差之类的(因为我们这边没有下游的服务,在bthread_creation_qps相同的情况下,bthread_creation_latency一般都会明显比有下游的服务要好得多,平均几us)。

FancyJan avatar Sep 26 '23 09:09 FancyJan

我们这边生产集群也有这个现象。 针对大佬说的瞬时并发,我试了一下用rpc_replay设置相同qps减少瞬时值影响,确实可以降低长尾,瞬时并发较高应该是bthread调度长尾的一个原因。但是长尾依旧比较长(bthread_creation_latency平均200us,三九线4500us),大佬还有啥别的想法吗? 例如client的bthread调度要比server的bthread调度差之类的(因为我们这边没有下游的服务,在bthread_creation_qps相同的情况下,bthread_creation_latency一般都会明显比有下游的服务要好得多,平均几us)。

client的bthread调度和server的bthread调度是一样的。我自己起了个client访问server,client的bthread_creation_latency也是很低的。你这个可能和client端的其它业务逻辑有关

wwbmmm avatar Oct 13 '23 12:10 wwbmmm