[debug](rpc) debug rpc time consumption problem by jacktengg · Pull Request #39852 · apache/doris

jacktengg · 2024-08-23T09:02:33Z

Proposed changes

Issue Number: close #xxx

Add detail RPC time info for each channel, sorted by max rpc time of channels:

 DATA_STREAM_SINK_OPERATOR (id=1,dst_id=1):
- Partitioner: Crc32HashPartitioner(64)
- BlocksProduced: 74
- BrpcSendTime: 2.689us
- BrpcSendTime.Wait: 0ns
- BytesSent: 89.35 KB
- CloseTime: 680.152us
- CompressTime: 0ns
- ExecTime: 160.663ms
- InitTime: 263.608us
- InputRows: 32.512K (32512)
- LocalBytesSent: 0.00 - LocalSendTime: 0ns
- LocalSentRows: 0
- MemoryUsage: - PeakMemoryUsage: 80.00 KB
- MergeBlockTime: 0ns
- OpenTime: 4.113ms
- OverallThroughput: 0.0 /sec
- PendingFinishDependency: 41.179ms
- RowsProduced: 32.512K (32512)
- RpcAvgTime: 11.850ms
- RpcCount: 10
- RpcMaxTime: 86.891ms
- RpcMinTime: 15.200ms
- RpcSumTime: 118.503ms
- SerializeBatchTime: 13.517ms
- SplitBlockDistributeByChannelTime: 38.923ms
- SplitBlockHashComputeTime: 2.659ms
- UncompressedRowBatchSize: 135.19 KB
- WaitForDependencyTime: 0ns
- WaitForRpcBufferQueue: 0ns
RpcInstanceDetails:
- Instance 85d4f75b72a9ea61: Count: 4, MaxTime: 36.238ms, MinTime: 12.107ms, AvgTime: 21.722ms, SumTime: 86.891ms
- Instance 85d4f75b72a9ea91: Count: 3, MaxTime: 11.107ms, MinTime: 2.431ms, AvgTime: 5.470ms, SumTime: 16.412ms
- Instance 85d4f75b72a9eac1: Count: 3, MaxTime: 7.554ms, MinTime: 3.160ms, AvgTime: 5.066ms, SumTime: 15.200m

doris-robot · 2024-08-23T09:02:38Z

Thank you for your contribution to Apache Doris.
Don't know what should be done next? See How to process your PR

Since 2024-03-18, the Document has been moved to doris-website.
See Doris Document.

jacktengg · 2024-08-23T09:02:48Z

run buildall

github-actions

clang-tidy made some suggestions

…lacklist to skip some backend during query

github-actions

clang-tidy made some suggestions

jacktengg · 2024-08-23T10:05:48Z

run buildall

yiguolei · 2024-08-24T00:41:58Z

 template <typename Parent>
-void ExchangeSinkBuffer<Parent>::register_sink(TUniqueId fragment_instance_id) {
+void ExchangeSinkBuffer<Parent>::register_sink(TUniqueId fragment_instance_id,
+ vectorized::PipChannel<Parent>* channel) {


增加这个channel 变量的目的是？

yiguolei · 2024-08-24T00:46:03Z

 template <typename Parent>
 Status ExchangeSinkBuffer<Parent>::_send_rpc(InstanceLoId id) {
+ if (_parent) {
+ SCOPED_TIMER(_parent->brpc_send_timer());


这么写没意义， scoped 就是在这个 {} 有用

yiguolei · 2024-08-24T01:11:54Z

+ out << "Instance " << std::hex << stats->inst_lo_id;
+ auto stats_str = fmt::format(
+ "Count: {}, MaxTime: {}, MinTime: {}, AvgTime: {}, SumTime: {}",
+ stats->rpc_count, PrettyPrinter::print(stats->max_time, TUnit::TIME_NS),


CloseTime: avg 11.310us, max 11.310us, min 11.310us
- ExecTime: avg 150.158us, max 150.158us, min 150.158us
- InitTime: avg 72.193us, max 72.193us, min 72.193us

yiguolei · 2024-08-24T01:12:33Z

+ [](const auto& a, const auto& b) { return a->max_time > b->max_time; });
+ auto count = std::min((size_t)max_count, _instance_to_rpc_stats_vec.size());
+ int i = 0;
+ auto* detail_profile = profile->create_child("RpcInstanceDetails", true, true);


这个profile 对象得检查下是否为nullptr

github-actions · 2024-08-24T04:47:15Z

clang-tidy review says "All clean, LGTM! 👍"

jacktengg · 2024-08-24T06:45:17Z

run buildall

…le with branch-2.1 (#40384) Ref #39852

…n problem (#43284) Picked from the 2.1 branch, only the RPC profile-related code was selected. #39852 #40117 ``` DATA_STREAM_SINK_OPERATOR (id=2,dst_id=2): - RpcCount: sum 16, avg 4, max 4, min 4 - RpcMaxTime: avg 1.15ms, max 1.163ms, min 818.493us - RpcAvgTime: 11.850ms - RpcCount: 10 - RpcMaxTime: 86.891ms - RpcMinTime: 15.200ms - RpcSumTime: 118.503ms - SerializeBatchTime: 13.517ms - SplitBlockDistributeByChannelTime: 38.923ms - SplitBlockHashComputeTime: 2.659ms - UncompressedRowBatchSize: 135.19 KB - WaitForDependencyTime: 0ns - WaitForRpcBufferQueue: 0ns RpcInstanceDetails: - Instance 85d4f75b72a9ea61: Count: 4, MaxTime: 36.238ms, MinTime: 12.107ms, AvgTime: 21.722ms, SumTime: 86.891ms - Instance 85d4f75b72a9ea91: Count: 3, MaxTime: 11.107ms, MinTime: 2.431ms, AvgTime: 5.470ms, SumTime: 16.412ms - Instance 85d4f75b72a9eac1: Count: 3, MaxTime: 7.554ms, MinTime: 3.160ms, AvgTime: 5.066ms, SumTime: 15.200m ```

…n problem (apache#43284) Picked from the 2.1 branch, only the RPC profile-related code was selected. apache#39852 apache#40117 ``` DATA_STREAM_SINK_OPERATOR (id=2,dst_id=2): - RpcCount: sum 16, avg 4, max 4, min 4 - RpcMaxTime: avg 1.15ms, max 1.163ms, min 818.493us - RpcAvgTime: 11.850ms - RpcCount: 10 - RpcMaxTime: 86.891ms - RpcMinTime: 15.200ms - RpcSumTime: 118.503ms - SerializeBatchTime: 13.517ms - SplitBlockDistributeByChannelTime: 38.923ms - SplitBlockHashComputeTime: 2.659ms - UncompressedRowBatchSize: 135.19 KB - WaitForDependencyTime: 0ns - WaitForRpcBufferQueue: 0ns RpcInstanceDetails: - Instance 85d4f75b72a9ea61: Count: 4, MaxTime: 36.238ms, MinTime: 12.107ms, AvgTime: 21.722ms, SumTime: 86.891ms - Instance 85d4f75b72a9ea91: Count: 3, MaxTime: 11.107ms, MinTime: 2.431ms, AvgTime: 5.470ms, SumTime: 16.412ms - Instance 85d4f75b72a9eac1: Count: 3, MaxTime: 7.554ms, MinTime: 3.160ms, AvgTime: 5.066ms, SumTime: 15.200m ```

…le with branch-2.1 (apache#40384) Ref apache#39852

…n problem (apache#43284) Picked from the 2.1 branch, only the RPC profile-related code was selected. apache#39852 apache#40117 ``` DATA_STREAM_SINK_OPERATOR (id=2,dst_id=2): - RpcCount: sum 16, avg 4, max 4, min 4 - RpcMaxTime: avg 1.15ms, max 1.163ms, min 818.493us - RpcAvgTime: 11.850ms - RpcCount: 10 - RpcMaxTime: 86.891ms - RpcMinTime: 15.200ms - RpcSumTime: 118.503ms - SerializeBatchTime: 13.517ms - SplitBlockDistributeByChannelTime: 38.923ms - SplitBlockHashComputeTime: 2.659ms - UncompressedRowBatchSize: 135.19 KB - WaitForDependencyTime: 0ns - WaitForRpcBufferQueue: 0ns RpcInstanceDetails: - Instance 85d4f75b72a9ea61: Count: 4, MaxTime: 36.238ms, MinTime: 12.107ms, AvgTime: 21.722ms, SumTime: 86.891ms - Instance 85d4f75b72a9ea91: Count: 3, MaxTime: 11.107ms, MinTime: 2.431ms, AvgTime: 5.470ms, SumTime: 16.412ms - Instance 85d4f75b72a9eac1: Count: 3, MaxTime: 7.554ms, MinTime: 3.160ms, AvgTime: 5.066ms, SumTime: 15.200m ```

github-actionsBot added the meta-change label Aug 23, 2024

github-actionsBot reviewed Aug 23, 2024
View reviewed changes

Comment threadbe/src/pipeline/exec/exchange_sink_buffer.cpp

jacktengg force-pushed the 2.1-rpc-debug branch from a114052 to c1387a3Compare August 23, 2024 09:50

jacktengg added 2 commits August 23, 2024 17:50

[improvement](profile) add rpc detail counters
2f4aa41

[debugfeature](backendblacklist) add a new session variable backend b…
fc8bc74
…lacklist to skip some backend during query

jacktengg force-pushed the 2.1-rpc-debug branch from c1387a3 to fc8bc74Compare August 23, 2024 09:50

github-actionsBot reviewed Aug 23, 2024
View reviewed changes

Comment threadbe/src/pipeline/exec/exchange_sink_buffer.cpp

jacktengg force-pushed the 2.1-rpc-debug branch from ce2ce33 to b268b08Compare August 23, 2024 15:43

yiguolei reviewed Aug 24, 2024
View reviewed changes

fix and improve
51145fb

jacktengg force-pushed the 2.1-rpc-debug branch from b268b08 to 51145fbCompare August 24, 2024 04:40

yiguolei merged commit 2dea859 into apache:branch-2.1Aug 24, 2024

RoanHeNaN mentioned this pull request Sep 4, 2024
[chore](thrift compatibility) Fix thrift id on master is not compatible with branch-2.1 #40384
Merged

yiguolei pushed a commit that referenced this pull request Sep 5, 2024
[chore](thrift compatibility) Fix thrift id on master is not compatib…
68574b2
…le with branch-2.1 (#40384) Ref #39852

Mryange mentioned this pull request Nov 5, 2024
[profile](rpc) add RpcInstanceDetails profile to debug rpc consumption problem #43284
Merged
16 tasks

Mryange mentioned this pull request Dec 4, 2024
[profile](rpc) add RpcInstanceDetails profile to debug rpc consumption problem #43284 #44978
Closed
16 tasks

HappenLee pushed a commit to HappenLee/incubator-doris that referenced this pull request Apr 24, 2026
[chore](thrift compatibility) Fix thrift id on master is not compatib…
e254cb6
…le with branch-2.1 (apache#40384) Ref apache#39852

Navigation Menu

Uh oh!

[debug](rpc) debug rpc time consumption problem - #39852

[debug](rpc) debug rpc time consumption problem#39852
yiguolei merged 3 commits into
apache:branch-2.1from
jacktengg:2.1-rpc-debug

jacktengg commented Aug 23, 2024•
edited
Loading

Uh oh!

doris-robot commented Aug 23, 2024

Uh oh!

jacktengg commented Aug 23, 2024

Uh oh!

github-actionsBot left a comment

Uh oh!

Uh oh!

github-actionsBot left a comment

Uh oh!

Uh oh!

jacktengg commented Aug 23, 2024

Uh oh!

yiguoleiAug 24, 2024

Uh oh!

yiguoleiAug 24, 2024

Uh oh!

Uh oh!

yiguoleiAug 24, 2024

Uh oh!

yiguoleiAug 24, 2024

Uh oh!

github-actionsBot commented Aug 24, 2024

Uh oh!

jacktengg commented Aug 24, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

jacktengg commented Aug 23, 2024• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Proposed changes

Uh oh!

doris-robot commented Aug 23, 2024

Uh oh!

jacktengg commented Aug 23, 2024

Uh oh!

github-actionsBot left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

github-actionsBot left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

jacktengg commented Aug 23, 2024

Uh oh!

yiguoleiAug 24, 2024

Choose a reason for hiding this comment

Uh oh!

yiguoleiAug 24, 2024

Choose a reason for hiding this comment

Uh oh!

Uh oh!

yiguoleiAug 24, 2024

Choose a reason for hiding this comment

Uh oh!

yiguoleiAug 24, 2024

Choose a reason for hiding this comment

Uh oh!

github-actionsBot commented Aug 24, 2024

Uh oh!

jacktengg commented Aug 24, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

jacktengg commented Aug 23, 2024•
edited
Loading