brpc RDMA failure

Describe the bug (描述bug)

W0528 17:36:56.793694   510 external/brpc/src/brpc/input_messenger.cpp:240] Close Socket{id=1248 fd=1395 addr=10.156.8.12:24452:24141} (0x55c9fa744b40) due to unknown message: \F87\88>[\BE\C0<\00\00\00\80\CA|\E1=\F87\88>[\BE\C0<\CA\E0U\BE\CA|\E1=\F87\88>[\BE\C0<\00\00\00\80\CA|\E1=\F87\88>[\BE\C0<S}:=O\E9\82\BD...<skipping 16256 bytes>
W0528 17:36:56.794202   510 external/brpc/src/brpc/policy/baidu_rpc_protocol.cpp:265] Fail to write into Socket{id=1248 fd=1395 addr=10.156.8.12:24452:24141} (0x55c9fa744b40): Invalid argument

To Reproduce (复现方法) master分支，RDMA打开的情况，数小时之内必现

Expected behavior (期望行为)

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

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

May 28 '23 10:05 372046933

用的是什么样的业务？是example么？怎样的测试？

May 29 '23 01:05 Tuvie

不是example，场景是一个分布式训练任务，打开RDMA开关后会出现。有没有啥辅助日志可以帮助排查的，类似TF VLOG那种？

May 29 '23 06:05 372046933

这类错误可能是多个线程同时访问一个IOBuf导致的。先禁掉zero copy看看是否还必现？rdma_recv_zerocopy=false（禁用接收端zerocopy），rdma_zerocopy_min_size=[比较大的值]（禁用发送端zerocopy）。先确认下是rpc内部竞争了，还是rpc和上面的应用之间竞争了。

May 29 '23 10:05 Tuvie

设置了rdma_recv_zerocopy=false, rdma_zerocopy_min_size=1073741824. 还是会出现异常服务端：

W0530 12:26:38.156749   812 external/brpc/src/brpc/input_messenger.cpp:240] Close Socket{id=678 fd=1331 addr=10.156.8.33:51496:19269} (0x562e43640000) due to unknown message: 7\D80\B5\B6\B6\E0\B8\B5k\8A\AE7H\CF\B27\F1\7F\947\92\E8\0F\B6\D1\A1\816\85j%\B7V\D6\BF7\C6\C0T\B7\9EP\80\B7`h\033\A5\BF68lG\F76\9E^\877\F5\B2w...<skipping 7205 bytes>

客户端：

[E1014]Got EOF of Socket{id=12 fd=1354 addr=10.156.8.33:12455:33556}

May 30 '23 05:05 372046933

是每次报错都来自server端吗？能否提供更多的复现方法或者问题触发时的特征？

May 30 '23 09:05 Tuvie

每次都是Server端先报错：Close socket...，客户端此时会出现成片的RPC 失败。我在客户端增加了重试逻辑，RPC是可以成功的，但是重试前发生了啥？有没有副作用？我还在确认中。

在使用TCP时，没有出现过类似报错

May 30 '23 10:05 372046933

客户端此时会出现成片的RPC 失败

是一个客户端的多个RPC失败，还是多个客户端的RPC失败？

May 30 '23 11:05 Tuvie

前者，一个客户端的多个RPC失败

May 30 '23 11:05 372046933

rdma_recv_zerocopy=false（禁用接收端zerocopy），rdma_zerocopy_min_size=[比较大的值]（禁用发送端zerocopy）

抱歉，我刚查了一下代码，上面这个说法有问题。rdma_zerocopy_min_size=[比较大的值]禁用的仍然是接收端zerocopy。发送端zerocopy暂时没法通过Flag禁用。我去做个版本，支持下关闭发送端zerocopy你再试试

May 30 '23 11:05 Tuvie

https://github.com/apache/brpc/pull/2267 可以试下这个PR。

这种IOBuf数据问题debug确实有些困难。如果打log数据量太大了

May 30 '23 14:05 Tuvie

#2267 有个typo需要fix一下，pipeline没有define BRPC_WITH_RDMA=true，检查不出来

Jun 01 '23 03:06 372046933

禁用send_zerocopy之后，

W0601 12:06:39.288266 18290 external/brpc/src/brpc/rdma/rdma_endpoint.cpp:1412] Fail to handle RDMA completion, error status(4): Socket{id=8589934594 fd=1337 addr=127.0.0.1:1234:24360} (0x0x5640308974c0): Resource temporarily unavailable
2023-06-01 12:06:39.288390: W ./tensorswitch/client/handle_base.h:119] Method:[Ping] Fail to get response from shard#0 [E3001]RDMA completion error(4) from Socket{id=8589934594 fd=1337 addr=127.0.0.1:1234:24360} (0x0x5640308974c0): RDMA verbs error, retry#9 request:

Jun 01 '23 04:06 372046933

你使用的rdma相关的flag都有哪些？能否贴一下看看

Jun 01 '23 05:06 Tuvie

rdma_recv_zerocopy=true
rdma_zerocopy_min_size=512
rdma_send_zerocopy=false

Jun 01 '23 05:06 372046933

其他的flag有设置吧？block size什么的

Jun 01 '23 06:06 Tuvie

没有，~发现同时禁用send/recv zerocopy可以跑了，不能单独禁用send_zerocopy~

Jun 01 '23 06:06 372046933

多节点运行还是不行

 Fail to handle RDMA completion, error status(4): Socket{id=32 fd=1334 addr=10.156.1.16:24615:18398} (0x0x5637deabe800): Resource temporarily unavailable

Jun 01 '23 06:06 372046933

程序里面是否有调用RegisterMemoryForRdma专门注册其他内存？

Jun 01 '23 13:06 Tuvie

有的，关闭zerocopy之后，不能再调用RegisterMemoryForRdma？

Jun 01 '23 13:06 372046933

那就是程序内有使用append_user_data直接使用了外部的内存，并且做了单独的注册对吧？不过你这个错误我目前还没在本地复现出来。还有别的线索吗

Jun 01 '23 14:06 Tuvie

那就是程序内有使用append_user_data直接使用了外部的内存，并且做了单独的注册对吧？不过你这个错误我目前还没在本地复现出来。还有别的线索吗

是的，区别只是rdma_send/recv_zerocopy传false，传true能跑，传false不能

Jun 01 '23 14:06 372046933

我目前仍然无法本地复现这样的问题。你们的程序里是否主动调用了ibverbs的发送？这个错误显示的是发送的数据没有在被注册的Memory Region内。

Jun 02 '23 05:06 Tuvie

我目前仍然无法本地复现这样的问题。你们的程序里是否主动调用了ibverbs的发送？这个错误显示的是发送的数据没有在被注册的Memory Region内。

有获取brpc::rdma::GetRdmaPd, 接着调用ibv_reg_mr，没有主动调用ibv send/recv相关 API

Jun 02 '23 05:06 372046933

如果是裸调ibv_reg_mr的，注册下来的mkey是通过append_user_data_with_meta传进去的是吧？

Jun 02 '23 05:06 Tuvie

是的，不然禁用zerocopy之前，也跑不起来

Jun 02 '23 05:06 372046933

应该是没commit全。再试试呢

Jun 02 '23 07:06 Tuvie

这一段修改，是之前的BUG吗？

https://github.com/apache/brpc/compare/726ee5435c24051ccc222e79b8b666e94e8d3c1f..9f7bce0ac70d4b0a6ec59da86718f25f376fe240#diff-8c54e550b0ba300eb91080953476b316b014020ac1916d26ecdd5e6fb3d4aee6L645-L652

Jun 02 '23 08:06 372046933

和之前的问题没有关系。是禁用zero_copy的时候复用了这个函数。

Jun 02 '23 08:06 Tuvie

和之前的问题没有关系。是禁用zero_copy的时候复用了这个函数。

上面那个不改，master分支有问题吗？

Jun 02 '23 09:06 372046933

不开send zero copy就没啥问题。如果出问题会出Fail to handle RDMA completion, error status(4)这类错误。

Jun 02 '23 09:06 Tuvie