deepseek-ai / deepseek-ai/3FS

RPC timeout during a stressful write test

Open
#140 9 comments 0 reactions 0 assignees View on GitHub
Dominant language
C++
Stars
10.2k
Forks
1.1k
PR merge metrics
No merged PRs in 30d

Description

Hi, we deploy 3FS on Alibaba Cloud ECS 8th generation instance with its Elastic RDMA Interface, following [this document](https://mp.weixin.qq.com/s/Ri9-sjsaoQ3LUE2-dTAN_g).
The configuration of our cluster is as following:

- Meta Node: 1x [ecs.g8i.48xlarge](https://help.aliyun.com/document_detail/25378.html#g8i)
- FUSE Client: 4x [ecs.ebmg8i.48xlarge](https://help.aliyun.com/document_detail/25378.html#ebmg8i)
- Storage Node: 5x [ecs.i4.4xlarge](https://help.aliyun.com/document_detail/25378.html#i4)

Additionally, the meta node also serves as a FUSE client.

We start 128 fio write jobs on each FUSE client, which write to 3FS simultaneously.
```
test_dir="/3fs/stage/`hostname`-fio"
mkdir "/3fs/stage/`hostname`-fio"

fio -numjobs=128 -fallocate=none -iodepth=2 -ioengine=libaio -direct=1 -rw=write -bs=4M --group_reporting -size=100M -time_based -runtime=300 -name=2depth_128file_4M_direct_write_bw -directory=${test_dir}
```

The fio process reports the following error:
```
fio: io_u error on file /3fs/stage/3fs-fuse-fio/2depth_128file_4M_direct_write_bw.50.0: Input/output error: write offset=8388608, buflen=4194304
fio: pid=35612, err=5/file:io_u.c:1845, func=io_u error, error=Input/output error
```

We found the following errors in `/var/log/3fs/hf3fs_fuse_main-err.log`:
```
[2025-03-10T17:35:35.101867099+08:00 hf3fs_fuse_main:36660 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x7f583452e6d0, timeout: 10s, peer address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101869946+08:00 hf3fs_fuse_main:36847 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x7f56ec109ac0, timeout: 10s, peer address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101884872+08:00 hf3fs_fuse_main:36798 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x7f5758720bc0, timeout: 10s, peer address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101893372+08:00 hf3fs_fuse_main:36806 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x7f572c7205d0, timeout: 10s, peer address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101898173+08:00 hf3fs_fuse_main:36827 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x7f572871f370, timeout: 10s, peer address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101886611+08:00 hf3fs_fuse_main:36794 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x7f576474da60, timeout: 10s, peer address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101914629+08:00 hf3fs_fuse_main:36660 StorageClientImpl.cc:876 ERROR] Call messenger error: RPC::Timeout(2005), batchWrite request: 0x7f583452e6d0, usercall: #238477, timeout: 10s, latency: 10000ms, host: 3fs-storage002, address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.102039496+08:00 hf3fs_fuse_main:36794 StorageClientImpl.cc:876 ERROR] Call messenger error: RPC::Timeout(2005), batchWrite request: 0x7f576474da60, usercall: #264383, timeout: 10s, latency: 3ms, host: 3fs-storage002, address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.101979856+08:00 hf3fs_fuse_main:36798 StorageClientImpl.cc:876 ERROR] Call messenger error: RPC::Timeout(2005), batchWrite request: 0x7f5758720bc0, usercall: #264391, timeout: 10s, latency: 0ms, host: 3fs-storage002, address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.102064488+08:00 hf3fs_fuse_main:36794 StorageClientImpl.cc:1917 ERROR] Cannot communicate with node NodeId(10002), error: RPC::Timeout(2005), usercall: #264383, write key: {"vChainId":{"chainId":900200019,"chainVer":1},"chunkId":"00000000-00000000-18400000-00000034"}
[2025-03-10T17:35:35.101993967+08:00 hf3fs_fuse_main:36806 StorageClientImpl.cc:876 ERROR] Call messenger error: RPC::Timeout(2005), batchWrite request: 0x7f572c7205d0, usercall: #252659, timeout: 10s, latency: 4414ms, host: 3fs-storage002, address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.102006687+08:00 hf3fs_fuse_main:36827 StorageClientImpl.cc:876 ERROR] Call messenger error: RPC::Timeout(2005), batchWrite request: 0x7f572871f370, usercall: #264378, timeout: 10s, latency: 5ms, host: 3fs-storage002, address: RDMA://10.99.0.3:8000
[2025-03-10T17:35:35.102070023+08:00 hf3fs_fuse_main:36660 StorageClientImpl.cc:1917 ERROR] Cannot communicate with node NodeId(10002), error: RPC::Timeout(2005), usercall: #238477, write key: {"vChainId":{"chainId":900600018,"chainVer":1},"chunkId":"00000000-00000000-19DF0000-00000043"}
[2025-03-10T17:35:35.102086198+08:00 hf3fs_fuse_main:36806 StorageClientImpl.cc:1917 ERROR] Cannot communicate with node NodeId(10002), error: RPC::Timeout(2005), usercall: #252659, write key: {"vChainId":{"chainId":900600018,"chainVer":1},"chunkId":"00000000-00000000-19DF0000-00000043"}
[2025-03-10T17:35:35.102082654+08:00 hf3fs_fuse_main:36798 StorageClientImpl.cc:1917 ERROR] Cannot communicate with node NodeId(10002), error: RPC::Timeout(2005), usercall: #264391, write key: {"vChainId":{"chainId":900300018,"chainVer":1},"chunkId":"00000000-00000000-18E10000-0000003F"}
```

The storage node also reports errors in `/var/log/3fs/storage_main-err.log`.
```
[2025-03-10T17:34:25.198116083+08:00 UpdatePool1:34409 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x565280c29188, timeout: 100ms, peer address: RDMA://10.99.0.5:8000
[2025-03-10T17:34:25.198116209+08:00 UpdatePool0:34408 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x56527d7cd588, timeout: 100ms, peer address: RDMA://10.99.0.5:8000
[2025-03-10T17:34:25.198121261+08:00 UpdatePool7:34415 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x56527b27b588, timeout: 100ms, peer address: RDMA://10.99.0.5:8000
[2025-03-10T17:34:25.198116423+08:00 UpdatePool5:34413 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x565279628788, timeout: 100ms, peer address: RDMA://10.99.0.5:8000
[2025-03-10T17:34:25.198118587+08:00 UpdatePool3:34411 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x56527d7cf888, timeout: 100ms, peer address: RDMA://10.99.0.4:8000
[2025-03-10T17:34:25.198183483+08:00 UpdatePool1:34409 ReliableForwarding.cc:234 ERROR] forward timeout, req {"payload":{"offset":0,"length":1048576,"chunkSize":1048576,"key":{"vChainId":{"chainId":900600002,"chainVer":1},"chunkId":"00000000-00000000-18B20000-0000002D"},"rdmabuf":{"addr":94903668514816,"size":1048576,"rkeys":[{"rkey":2972672,"devId":0}]},"updateVer":7,"updateType":"WRITE","checksum":{"type":"CRC32C","value":2107099607},"inlinebuf":"std::vector(0)"},"options":{"isSyncing":false,"fromClient":false,"commitChainVer":0},"tag":{"clientId":{"uuid":"7684d6be-96f3-4fa5-bad8-31d0aa3cf139","hostname":"3fs-meta"},"requestId":82377,"channel":{"id":3,"seqnum":82385}},"retryCount":0,"userInfo":"(uid 0, gid 0, groups ())","featureFlags":0,"debugFlags":{"injectRandomServerError":false,"injectRandomClientError":false,"numOfInjectPtsBeforeFail":0}}, result RPC::Timeout(2005)
[2025-03-10T17:34:25.198115877+08:00 UpdatePool6:34414 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x565280a60388, timeout: 100ms, peer address: RDMA://10.99.0.5:8000
[2025-03-10T17:34:25.198116402+08:00 UpdatePool2:34410 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x56527c010088, timeout: 100ms, peer address: RDMA://10.99.0.4:8000
[2025-03-10T17:34:25.198131506+08:00 UpdatePool4:34412 StorageMessenger.cc:31 ERROR] RPC communication error: RPC::Timeout(2005), request: 0x56527c116788, timeout: 100ms, peer address: RDMA://10.99.0.5:8000
[2025-03-10T17:34:25.198186195+08:00 UpdatePool0:34408 ReliableForwarding.cc:234 ERROR] forward timeout, req {"payload":{"offset":0,"length":1048576,"chunkSize":1048576,"key":{"vChainId":{"chainId":900100002,"chainVer":1},"chunkId":"00000000-00000000-183E0000-00000023"},"rdmabuf":{"addr":94903660126208,"size":1048576,"rkeys":[{"rkey":2972416,"devId":0}]},"updateVer":7,"updateType":"WRITE","checksum":{"type":"CRC32C","value":4168365105},"inlinebuf":"std::vector(0)"},"options":{"isSyncing":false,"fromClient":false,"commitChainVer":0},"tag":{"clientId":{"uuid":"5b48d7e5-368f-483e-9ab0-20ebaddf93ea","hostname":"shenkai-3fs-client-bm003"},"requestId":81717,"channel":{"id":9,"seqnum":81725}},"retryCount":0,"userInfo":"(uid 0, gid 0, groups ())","featureFlags":0,"debugFlags":{"injectRandomServerError":false,"injectRandomClientError":false,"numOfInjectPtsBeforeFail":0}}, result RPC::Timeout(2005)
```

We believe that this error is related to the reliable forwarding timeout and have adjusted different timeout parameters in the storage_main.toml. Finally, we resolved this error by increasing the `retry_first_timeout` to 500ms (default is 100ms). So, what does the `retry_first_timeout` parameter indicate for 3FS?
`sed -i "s/retry_first_wait = '100ms'/retry_first_wait = '500ms'/g" /opt/3fs/etc/storage_main.toml`

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.