breuner
High latency reported with S3 GET Objects with Ceph
Using version 3.0-35 of elbencho I am evaluating the performance of S3 RGW Object gateway with Ceph.
SIngle node Ceph system, 6 OSDs, 3 way replica. Nothing complicated.
I created a single bucket with:
elbencho --s3endpoints "http://ipaddr:8000" --s3key cbt --s3secret intel2012 -d mybucket
I create 8 4K objects in the bucket, serialised, 1 thread, iodepth 1.
elbencho --s3endpoints http://ipaddr:8000 --s3key cbt --s3secret intel2012 -w -t 1 -n 1 -N 8 -s 4K --lat --s3fastget --live1n --nolive --direct --timelimit 120 --iodepth 1 --jsonfile /tmp/elbencho.694265.json --s3nocompress --s3nompcheck mybucket
You'll notice that I'm setting --s3fastget so that there isn't a delay in writing the object into buffer memory.
Latency is reported to be 3-4ms:
OPERATION RESULT TYPE FIRST DONE LAST DONE =========== ================ ========== ========= WRITE Elapsed time : 32ms 32ms Objects/s : 249 249 Throughput MiB/s : 0 0 Total MiB : 0 0 Objects total : 8 8 Objects latency : [ min=2.98ms avg=4.00ms max=8.30ms ] IO latency : [ min=2.98ms avg=4.00ms max=8.28ms ]
In the ceph log:
2025-09-11T14:01:49.643+0000 7f627b9ae640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx00000bd1fa835de3d10ca-0068c2d64d-14331-default ===== 2025-09-11T14:01:49.649+0000 7f62849c0640 1 ====== req done req=0x7f619d7d0580 op=put_obj bucket=mybucket status=0 http_status=200 latency=0.005999886s request_id=tx00000bd1fa835de3d10ca-0068c2d64d-14331-default ====== 2025-09-11T14:01:49.649+0000 7f62849c0640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:01:49.643 +0000] "PUT /mybucket/r0/d0/r0-f0 HTTP/1.1" 200 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" - latency=0.005999886s
Completion time 6ms. Next request is submitted almost straight away.
2025-09-11T14:01:49.649+0000 7f627f1b5640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx00000762bd0ce14858700-0068c2d64d-14331-default ===== 2025-09-11T14:01:49.653+0000 7f628a1cb640 1 ====== req done req=0x7f619d7d0580 op=put_obj bucket=mybucket status=0 http_status=200 latency=0.003999924s request_id=tx00000762bd0ce14858700-0068c2d64d-14331-default ====== 2025-09-11T14:01:49.653+0000 7f628a1cb640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:01:49.649 +0000] "PUT /mybucket/r0/d0/r0-f1 HTTP/1.1" 200 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" - latency=0.003999924s
Completion time is 4ms. Next request submitted almost straight away.
2025-09-11T14:01:49.654+0000 7f628b9ce640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx00000c9db396007be154a-0068c2d64d-14331-default ===== 2025-09-11T14:01:49.658+0000 7f628f1d5640 1 ====== req done req=0x7f619d7d0580 op=put_obj bucket=mybucket status=0 http_status=200 latency=0.003999924s request_id=tx00000c9db396007be154a-0068c2d64d-14331-default ====== 2025-09-11T14:01:49.658+0000 7f628f1d5640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:01:49.654 +0000] "PUT /mybucket/r0/d0/r0-f2 HTTP/1.1" 200 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" - latency=0.003999924s
I then use elbencho to GET the 8 objects, serially,
elbencho --s3endpoints http://ipaddr:8000 --s3key cbt --s3secret intel2012 -r -t 1 -n 1 -N 8 -s 4K --lat --s3fastget --live1n --nolive --direct --timelimit 120 --iodepth 1 --jsonfile /tmp/elbencho.694265.json --s3nocompress --s3nompcheck mybucket
OPERATION RESULT TYPE FIRST DONE LAST DONE =========== ================ ========== ========= READ Elapsed time : 303ms 303ms Objects/s : 26 26 Throughput MiB/s : 0 0 Total MiB : 0 0 Objects total : 8 8 Objects latency : [ min=3.25ms avg=37.9ms max=43.0ms ] IO latency : [ min=3.23ms avg=37.9ms max=43.0ms ]
Latency is reported to be near 40ms.
The json output is also confirming the high latency is microseconds:
{"phase_type":"WRITE","phase_id":"d2cc07f0-8fff-457c-9031-d6f6c07c2da1","iso_start_date":"2025-09-11T15:01:49.644+0100","first_done":{"elapsed_time_ms":"36","entries/s":"217","iops":"217","bytes/s":"889154","entries":"8","bytes":"32768","cpu%":"4"},"last_done":{"elapsed_time_ms":"36","entries/s":"217","iops":"217","bytes/s":"889154","entries":"8","bytes":"32768","cpu%":"4","latency":{"entries":{"min_us":"3917","avg_us":"4598","max_us":"6527"},"IO":{"min_us":"3914","avg_us":"4592","max_us":"6505"}}},"version":"3.0-35","command":""elbencho" "--s3endpoints" "http://9.71.45.44:8000" "--s3key" "cbt" "-w" "-t" "1" "-n" "1" "-N" "8" "-s" "4K" "--lat" "--s3fastget" "--live1n" "--nolive" "--direct" "--timelimit" "120" "--iodepth" "1" "--jsonfile" "/tmp/elbencho.786502.json" "--s3nocompress" "--s3nompcheck" "mybucket" "}
{"phase_type":"READ","phase_id":"19bd0be1-3e41-4cd9-bb08-6e7f9ece8d6d","iso_start_date":"2025-09-11T15:03:08.163+0100","first_done":{"elapsed_time_ms":"303","entries/s":"26","iops":"26","bytes/s":"108035","entries":"8","bytes":"32768","cpu%":"0"},"last_done":{"elapsed_time_ms":"303","entries/s":"26","iops":"26","bytes/s":"108035","entries":"8","bytes":"32768","cpu%":"0","latency":{"entries":{"min_us":"3254","avg_us":"37904","max_us":"43021"},"IO":{"min_us":"3232","avg_us":"37892","max_us":"43009"}}},"version":"3.0-35","command":""elbencho" "--s3endpoints" "http://9.71.45.44:8000" "--s3key" "cbt" "-r" "-t" "1" "-n" "1" "-N" "8" "-s" "4K" "--lat" "--s3fastget" "--live1n" "--nolive" "--direct" "--timelimit" "120" "--iodepth" "1" "--jsonfile" "/tmp/elbencho.786502.json" "--s3nocompress" "--s3nompcheck" "mybucket" "}
Ceph logs confirming the GET command is completing from Ceph quickly:
2025-09-11T14:03:08.162+0000 7f62a6a04640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx00000eda6add07d23b5ac-0068c2d69c-14331-default ===== 2025-09-11T14:03:08.165+0000 7f62b6a24640 1 ====== req done req=0x7f619d7d0580 op=get_obj bucket=mybucket status=0 http_status=206 latency=0.002999942s request_id=tx00000eda6add07d23b5ac-0068c2d69c-14331-default ====== 2025-09-11T14:03:08.165+0000 7f62b6a24640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:03:08.162 +0000] "GET /mybucket/r0/d0/r0-f0 HTTP/1.1" 206 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" bytes=0-4095 latency=0.002999942s
This request took 3 milliseconds.
2025-09-11T14:03:08.165+0000 7f623a92c640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx000000bb76835bd57cda1-0068c2d69c-14331-default ===== 2025-09-11T14:03:08.167+0000 7f62bca30640 1 ====== req done req=0x7f619d7d0580 op=get_obj bucket=mybucket status=0 http_status=206 latency=0.001999963s request_id=tx000000bb76835bd57cda1-0068c2d69c-14331-default ====== 2025-09-11T14:03:08.167+0000 7f62bca30640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:03:08.165 +0000] "GET /mybucket/r0/d0/r0-f1 HTTP/1.1" 206 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" bytes=0-4095 latency=0.001999963s
This request took around 2ms. Then there is a 41ms delay before the next request is issue.
2025-09-11T14:03:08.208+0000 7f62ba22b640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx00000757525a0661fc29e-0068c2d69c-14331-default ===== 2025-09-11T14:03:08.210+0000 7f62c2a3c640 1 ====== req done req=0x7f619d7d0580 op=get_obj bucket=mybucket status=0 http_status=206 latency=0.001999963s request_id=tx00000757525a0661fc29e-0068c2d69c-14331-default ====== 2025-09-11T14:03:08.210+0000 7f62c2a3c640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:03:08.208 +0000] "GET /mybucket/r0/d0/r0-f2 HTTP/1.1" 206 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" bytes=0-4095 latency=0.001999963s
This request took 2 milliseconds. 41ms delay before next request.
2025-09-11T14:03:08.251+0000 7f62bfa36640 1 ====== starting new request req=0x7f619d7d0580 request_id=tx00000e9fe6af8544b95d6-0068c2d69c-14331-default ===== 2025-09-11T14:03:08.253+0000 7f62c9a4a640 1 ====== req done req=0x7f619d7d0580 op=get_obj bucket=mybucket status=0 http_status=206 latency=0.001999961s request_id=tx00000e9fe6af8544b95d6-0068c2d69c-14331-default ====== 2025-09-11T14:03:08.253+0000 7f62c9a4a640 1 beast: 0x7f619d7d0580: 9.71.45.44 - cbt [11/Sep/2025:14:03:08.251 +0000] "GET /mybucket/r0/d0/r0-f3 HTTP/1.1" 206 4096 - "aws-sdk-cpp/1.11.628 ua/2.1 api/S3 os/Linux#5.14.0-570.39.1.el9_6.x86_64 lang/c++#C++17 md/aws-crt#0.33.4 md/arch#x86_64 md/GCC#11.5.0 m/D,a,b,P" bytes=0-4095 latency=0.001999961s
Looking at the RGW ceph log, I can see the commands are getting request_done very quickly, and there is a 40ms delay before Ceph receives the next GET request.
This suggests to me that elbencho is including the delay before the next command is sent in within the high latency that is being reported.
I've been talking to @markhpc (Mark Nelson) at Clyso and he advised me to try an experiment with hsbench:
hsbench -a cbt -b 1 -d 120 -j results.json -n 8 -s intel2012 -t 1 -u http://9.71.45.44:8000 -z 4K -m ipg
This produced the results I expected.
[root@cephalasquad3 hsbench]# ./hsbench.script 2025/09/11 15:05:18 Hotsauce S3 Benchmark Version 0.1 2025/09/11 15:05:18 Parameters: 2025/09/11 15:05:18 url=http://9.71.45.44:8000 2025/09/11 15:05:18 object_prefix= 2025/09/11 15:05:18 bucket_prefix=hotsauce-bench 2025/09/11 15:05:18 region=us-east-1 2025/09/11 15:05:18 modes=ipg 2025/09/11 15:05:18 output= 2025/09/11 15:05:18 json_output=results.json 2025/09/11 15:05:18 max_keys=1000 2025/09/11 15:05:18 object_count=8 2025/09/11 15:05:18 bucket_count=1 2025/09/11 15:05:18 duration=120 2025/09/11 15:05:18 threads=1 2025/09/11 15:05:18 loops=1 2025/09/11 15:05:18 size=4K 2025/09/11 15:05:18 interval=1.000000 2025/09/11 15:05:18 Running Loop 0 BUCKET INIT TEST 2025/09/11 15:05:18 Loop: 0, Int: TOTAL, Dur(s): 0.0, Mode: BINIT, Ops: 1, MB/s: 0.00, IO/s: 94, Lat(ms): [ min: 10.5, avg: 10.5, 99%: 10.5, max: 10.5 ], Slowdowns: 0 2025/09/11 15:05:18 Running Loop 0 OBJECT PUT TEST 2025/09/11 15:05:18 Loop: 0, Int: TOTAL, Dur(s): 0.0, Mode: PUT, Ops: 8, MB/s: 1.06, IO/s: 271, Lat(ms): [ min: 3.0, avg: 3.7, 99%: 6.3, max: 6.3 ], Slowdowns: 0 2025/09/11 15:05:18 Running Loop 0 OBJECT GET TEST 2025/09/11 15:05:19 Loop: 0, Int: TOTAL, Dur(s): 0.3, Mode: GET, Ops: 8, MB/s: 0.09, IO/s: 24, Lat(ms): [ min: 1.4, avg: 1.8, 99%: 3.0, max: 3.0 ], Slowdowns: 0
I've also tried creating a curl script that issues the S3 Object GETs, and I can see the latencies I expect:
for i in 0 1 2 3 4 5 6 7 do
echo "Getting object f${i}"
file="r0/d0/r0-f${i}" bucket="mybucket"
key="cbt" secret="intel2012"
host="ipaddr:8000" resource="/${bucket}/${file}"
contentType="application/x-compressed-tar"
contentType="text/plain"
dateValue=date -R -u
method="GET"
stringToSign="${method}
${contentType} ${dateValue} ${resource}"
signature=echo -en "$stringToSign" | openssl sha1 -hmac ${secret} -binary | base64
time curl -X ${method} -H "Content-Type: ${contentType}" -H "Date: ${dateValue}" -H "Authorization: AWS ${key}:${signature}" -H "Host: ${host}" "http://${host}${resource}?format=json&stats=True" --insecure
done
Results:
Getting object f0 % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 4096 100 4096 0 0 2000k 0 --:--:-- --:--:-- --:--:-- 4000k
real 0m0.011s user 0m0.004s sys 0m0.006s Getting object f1 % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 4096 100 4096 0 0 4000k 0 --:--:-- --:--:-- --:--:-- 4000k
real 0m0.008s user 0m0.002s sys 0m0.004s Getting object f2 % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 4096 100 4096 0 0 4000k 0 --:--:-- --:--:-- --:--:-- 4000k
real 0m0.007s user 0m0.002s sys 0m0.004s Getting object f3
Thank you very much for your help/guidance. Mark Nelson said you were very helpful.
My role is that I'm working on Fast EC for Ceph and evaluating the performance for Small object for Ceph with Erasure Coded pools and we are looking to use Elbencho for our performance evaluation.
I am also looking at including Elbencho support within CBT (Ceph Benchmarking Tool)
http://github.com/ceph/cbt
Thanks!
