Hi! I have re-run our test as follows:
* 4 Rados Gateways, on 4 baremetal machines which have a total of 48 spinning rust OSDs. * Benchmark run on a virtual machine talking to HAProxy which balances the requests across the 4 Rados GWs. * Three instances of the benchmark run in parallel. Each instance creates 1000 containers, puts 11 objects into each container. Once they have all been created, each instances deletes its own containers again. I configured one of the radosgws with the debug levels you requested. The tests produced quite an amount of data (approx. 1GB of text), so I took the liberty to pre-process that a bit. In this run we landed at around 1.2s per container created (including the objects in them) on average. This was slightly better than the 1.6s we witnessed before, but that test ran for much longer, so there might have been some queue-up effect. Interestingly enough the average is actually somewhat misleading. The logs below show the creation of one object in a container each, one being the fastest of this benchmark (at least on the debug-enabled radosgw), one being the slowest. The fastest one was completed in 0.013s, the longest one took 4.93s(!). The attached logs are cleaned up so that they each show just a single request and replaced longish, but constant information with placeholders. Our container names are of the form “stresstest-xxxxxxxxxxx” which I shortened to “<CNT-UUID>” for brevity. Also, I removed the redundant prefix (date, hour, minute of day). The column before the log level looked like a thread-id. As I focused on a single request, I removed all the lines that did not match the same id, replacing the actual value with “<ID>”. That makes the logs much easier to read and understand. Just in case I might have removed too much information for the logs to be useful, the complete log is available in BZIP2 compressed form for download. Just let me know if you need it, then I will provide a link via direct email. To me it seems like there might indeed be a contention issue. It would be interesting to know, if this is correct and if there are any settings that we could adjust to alleviate the issue. Daniel ============================== ➜ ~ cat rados_shortest.txt 21.431185 <ID> 20 QUERY_STRING=page=swift¶ms=/v1/<CNT-UUID>/version 21.431187 <ID> 20 REMOTE_ADDR=10.102.8.140 21.431188 <ID> 20 REMOTE_PORT=44007 21.431189 <ID> 20 REQUEST_METHOD=PUT 21.431190 <ID> 20 REQUEST_SCHEME=https 21.431191 <ID> 20 REQUEST_URI=/swift/v1/<CNT-UUID>/version 21.431192 <ID> 20 SCRIPT_FILENAME=/var/www/s3gw.fcgi 21.431193 <ID> 20 SCRIPT_NAME=/swift/v1/<CNT-UUID>/version 21.431194 <ID> 20 SCRIPT_URI=https://localhost:8405/swift/v1/<CNT-UUID>/version 21.431195 <ID> 20 SCRIPT_URL=/swift/v1/<CNT-UUID>/version 21.431196 <ID> 20 SERVER_ADDR=10.102.9.11 21.431197 <ID> 20 SERVER_ADMIN=[no address given] 21.431198 <ID> 20 SERVER_NAME=localhost 21.431199 <ID> 20 SERVER_PORT=8405 21.431200 <ID> 20 SERVER_PORT_SECURE=443 21.431201 <ID> 20 SERVER_PROTOCOL=HTTP/1.1 21.431202 <ID> 20 SERVER_SIGNATURE= 21.431203 <ID> 20 SERVER_SOFTWARE=Apache/2.4.7 (Ubuntu) 21.431205 <ID> 1 ====== starting new request req=0x7f038c019e90 ===== 21.431219 <ID> 2 req 980641:0.000015::PUT /swift/v1/<CNT-UUID>/version::initializing 21.431259 <ID> 10 ver=v1 first=<CNT-UUID> req=version 21.431265 <ID> 10 s->object=version s->bucket=<CNT-UUID> 21.431269 <ID> 2 req 980641:0.000065:swift:PUT /swift/v1/<CNT-UUID>/version::getting op 21.431274 <ID> 2 req 980641:0.000070:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:authorizing 21.431321 <ID> 20 get_obj_state: rctx=0x7f030800b720 obj=.users.swift:documentstore:swift state=0x7f03080f31e8 s->prefetch_data=0 21.431332 <ID> 10 cache get: name=.users.swift+documentstore:swift : hit 21.431338 <ID> 20 get_obj_state: s->obj_tag was set empty 21.431344 <ID> 10 cache get: name=.users.swift+documentstore:swift : hit 21.431369 <ID> 20 get_obj_state: rctx=0x7f030800b720 obj=.users.uid:documentstore state=0x7f03080f31e8 s->prefetch_data=0 21.431374 <ID> 10 cache get: name=.users.uid+documentstore : hit 21.431378 <ID> 20 get_obj_state: s->obj_tag was set empty 21.431382 <ID> 10 cache get: name=.users.uid+documentstore : hit 21.431401 <ID> 10 swift_user=documentstore:swift 21.431416 <ID> 20 build_token token=13000000646f63756d656e7473746f72653a737769667406a4b2ba3999f8a84f45355438d8ff17 21.431467 <ID> 2 req 980641:0.000262:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:reading permissions 21.431493 <ID> 20 get_obj_state: rctx=0x7f03837ed250 obj=.rgw:<CNT-UUID> state=0x7f03080f31e8 s->prefetch_data=0 21.431508 <ID> 10 cache get: name=.rgw+<CNT-UUID> : type miss (requested=22, cached=19) 21.433081 <ID> 10 cache put: name=.rgw+<CNT-UUID> 21.433106 <ID> 10 removing entry: name=.rgw+stresstest-ab9ee3e2-dcf5-4a5b-ab40-931d94c7784038242 from cache LRU 21.433114 <ID> 10 moving .rgw+<CNT-UUID> to cache LRU end 21.433120 <ID> 20 get_obj_state: s->obj_tag was set empty 21.433122 <ID> 20 Read xattr: user.rgw.idtag 21.433124 <ID> 20 Read xattr: user.rgw.manifest 21.433129 <ID> 10 cache get: name=.rgw+<CNT-UUID> : hit 21.433141 <ID> 20 rgw_get_bucket_info: bucket instance: <CNT-UUID>(@{i=.rgw.buckets.index}.rgw.buckets[default.78418684.118911]) 21.433148 <ID> 20 reading from .rgw:.bucket.meta.<CNT-UUID>:default.78418684.118911 21.433169 <ID> 20 get_obj_state: rctx=0x7f03837ed250 obj=.rgw:.bucket.meta.<CNT-UUID>:default.78418684.118911 state=0x7f0308005778 s->prefetch_data=0 21.433185 <ID> 10 cache get: name=.rgw+.bucket.meta.<CNT-UUID>:default.78418684.118911 : type miss (requested=22, cached=19) 21.434632 <ID> 10 cache put: name=.rgw+.bucket.meta.<CNT-UUID>:default.78418684.118911 21.434650 <ID> 10 moving .rgw+.bucket.meta.<CNT-UUID>:default.78418684.118911 to cache LRU end 21.434657 <ID> 10 updating xattr: name=user.rgw.acl bl.length()=177 21.434664 <ID> 20 get_obj_state: s->obj_tag was set empty 21.434667 <ID> 20 Read xattr: user.rgw.acl 21.434668 <ID> 20 Read xattr: user.rgw.idtag 21.434669 <ID> 20 Read xattr: user.rgw.manifest 21.434675 <ID> 10 cache get: name=.rgw+.bucket.meta.<CNT-UUID>:default.78418684.118911 : hit 21.434701 <ID> 15 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>documentstore</ID><DisplayName>Document Store</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>documentstore</ID><DisplayName>Document Store</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy> 21.434710 <ID> 2 req 980641:0.003506:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:init op 21.434716 <ID> 2 req 980641:0.003512:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:verifying op mask 21.434719 <ID> 20 required_mask= 2 user.op_mask=7 21.434720 <ID> 2 req 980641:0.003516:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:verifying op permissions 21.434723 <ID> 5 Searching permissions for uid=documentstore mask=50 21.434725 <ID> 5 Found permission: 15 21.434726 <ID> 5 Searching permissions for group=1 mask=50 21.434727 <ID> 5 Permissions for group not found 21.434729 <ID> 5 Searching permissions for group=2 mask=50 21.434730 <ID> 5 Permissions for group not found 21.434731 <ID> 5 Getting permissions id=documentstore owner=documentstore perm=2 21.434732 <ID> 10 uid=documentstore requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2 21.434734 <ID> 2 req 980641:0.003530:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:verifying op params 21.434737 <ID> 2 req 980641:0.003533:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:executing 21.434850 <ID> 20 get_obj_state: rctx=0x7f03837ed250 obj=<CNT-UUID>:version state=0x7f03080c5378 s->prefetch_data=0 21.436144 <ID> 10 setting object write_tag=default.78418684.980641 21.444613 <ID> 2 req 980641:0.013408:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:http status=201 ============================== ➜ ~ cat rados_longest.txt 31.886128 <ID> 20 QUERY_STRING=page=swift¶ms=/v1/<CNT-UUID>/version 31.886129 <ID> 20 REMOTE_ADDR=10.102.8.140 31.886130 <ID> 20 REMOTE_PORT=46714 31.886131 <ID> 20 REQUEST_METHOD=PUT 31.886132 <ID> 20 REQUEST_SCHEME=https 31.886134 <ID> 20 REQUEST_URI=/swift/v1/<CNT-UUID>/version 31.886135 <ID> 20 SCRIPT_FILENAME=/var/www/s3gw.fcgi 31.886136 <ID> 20 SCRIPT_NAME=/swift/v1/<CNT-UUID>/version 31.886137 <ID> 20 SCRIPT_URI=https://localhost:8405/swift/v1/<CNT-UUID>/version 31.886138 <ID> 20 SCRIPT_URL=/swift/v1/<CNT-UUID>/version 31.886139 <ID> 20 SERVER_ADDR=10.102.9.11 31.886140 <ID> 20 SERVER_ADMIN=[no address given] 31.886141 <ID> 20 SERVER_NAME=localhost 31.886143 <ID> 20 SERVER_PORT=8405 31.886144 <ID> 20 SERVER_PORT_SECURE=443 31.886145 <ID> 20 SERVER_PROTOCOL=HTTP/1.1 31.886146 <ID> 20 SERVER_SIGNATURE= 31.886147 <ID> 20 SERVER_SOFTWARE=Apache/2.4.7 (Ubuntu) 31.886148 <ID> 1 ====== starting new request req=0x7f038c024c50 ===== 31.886162 <ID> 2 req 983095:0.000013::PUT /swift/v1/<CNT-UUID>/version::initializing 31.886195 <ID> 10 ver=v1 first=<CNT-UUID> req=version 31.886200 <ID> 10 s->object=version s->bucket=<CNT-UUID> 31.886203 <ID> 2 req 983095:0.000055:swift:PUT /swift/v1/<CNT-UUID>/version::getting op 31.886208 <ID> 2 req 983095:0.000060:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:authorizing 31.886242 <ID> 20 get_obj_state: rctx=0x7f02b0062770 obj=.users.swift:documentstore:swift state=0x7f02b007ac18 s->prefetch_data=0 31.886250 <ID> 10 cache get: name=.users.swift+documentstore:swift : hit 31.886255 <ID> 20 get_obj_state: s->obj_tag was set empty 31.886260 <ID> 10 cache get: name=.users.swift+documentstore:swift : hit 31.886297 <ID> 20 get_obj_state: rctx=0x7f02b0062770 obj=.users.uid:documentstore state=0x7f02b007ac18 s->prefetch_data=0 31.886303 <ID> 10 cache get: name=.users.uid+documentstore : hit 31.886308 <ID> 20 get_obj_state: s->obj_tag was set empty 31.886312 <ID> 10 cache get: name=.users.uid+documentstore : hit 31.886329 <ID> 10 swift_user=documentstore:swift 31.886343 <ID> 20 build_token token=13000000646f63756d656e7473746f72653a737769667410f2006ed65dbbaa4f453554207a0f1f 31.886393 <ID> 2 req 983095:0.000245:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:reading permissions 31.886419 <ID> 20 get_obj_state: rctx=0x7f0378fd8250 obj=.rgw:<CNT-UUID> state=0x7f02b007ac18 s->prefetch_data=0 31.886430 <ID> 10 cache get: name=.rgw+<CNT-UUID> : type miss (requested=22, cached=19) 36.746327 <ID> 10 cache put: name=.rgw+<CNT-UUID> 36.746404 <ID> 10 moving .rgw+<CNT-UUID> to cache LRU end 36.746426 <ID> 20 get_obj_state: s->obj_tag was set empty 36.746431 <ID> 20 Read xattr: user.rgw.idtag 36.746433 <ID> 20 Read xattr: user.rgw.manifest 36.746452 <ID> 10 cache get: name=.rgw+<CNT-UUID> : hit 36.746481 <ID> 20 rgw_get_bucket_info: bucket instance: <CNT-UUID>(@{i=.rgw.buckets.index}.rgw.buckets[default.78418684.119116]) 36.746491 <ID> 20 reading from .rgw:.bucket.meta.<CNT-UUID>:default.78418684.119116 36.746549 <ID> 20 get_obj_state: rctx=0x7f0378fd8250 obj=.rgw:.bucket.meta.<CNT-UUID>:default.78418684.119116 state=0x7f02b00ce638 s->prefetch_data=0 36.746585 <ID> 10 cache get: name=.rgw+.bucket.meta.<CNT-UUID>:default.78418684.119116 : type miss (requested=22, cached=19) 36.747938 <ID> 10 cache put: name=.rgw+.bucket.meta.<CNT-UUID>:default.78418684.119116 36.747955 <ID> 10 moving .rgw+.bucket.meta.<CNT-UUID>:default.78418684.119116 to cache LRU end 36.747963 <ID> 10 updating xattr: name=user.rgw.acl bl.length()=177 36.747972 <ID> 20 get_obj_state: s->obj_tag was set empty 36.747975 <ID> 20 Read xattr: user.rgw.acl 36.747977 <ID> 20 Read xattr: user.rgw.idtag 36.747978 <ID> 20 Read xattr: user.rgw.manifest 36.747985 <ID> 10 cache get: name=.rgw+.bucket.meta.<CNT-UUID>:default.78418684.119116 : hit 36.748025 <ID> 15 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>documentstore</ID><DisplayName>Document Store</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>documentstore</ID><DisplayName>Document Store</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy> 36.748037 <ID> 2 req 983095:4.861888:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:init op 36.748043 <ID> 2 req 983095:4.861895:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:verifying op mask 36.748046 <ID> 20 required_mask= 2 user.op_mask=7 36.748050 <ID> 2 req 983095:4.861902:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:verifying op permissions 36.748054 <ID> 5 Searching permissions for uid=documentstore mask=50 36.748056 <ID> 5 Found permission: 15 36.748058 <ID> 5 Searching permissions for group=1 mask=50 36.748060 <ID> 5 Permissions for group not found 36.748061 <ID> 5 Searching permissions for group=2 mask=50 36.748063 <ID> 5 Permissions for group not found 36.748064 <ID> 5 Getting permissions id=documentstore owner=documentstore perm=2 36.748066 <ID> 10 uid=documentstore requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2 36.748069 <ID> 2 req 983095:4.861921:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:verifying op params 36.748072 <ID> 2 req 983095:4.861924:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:executing 36.748200 <ID> 20 get_obj_state: rctx=0x7f0378fd8250 obj=<CNT-UUID>:version state=0x7f02b0042618 s->prefetch_data=0 36.802077 <ID> 10 setting object write_tag=default.78418684.983095 36.818727 <ID> 2 req 983095:4.932579:swift:PUT /swift/v1/<CNT-UUID>/version:put_obj:http status=201 ============================== -- Daniel Schneller Mobile Development Lead CenterDevice GmbH | Merscheider Straße 1 | 42699 Solingen tel: +49 1754155711 | Deutschland [email protected] | www.centerdevice.com > On 06 Oct 2014, at 19:26, Yehuda Sadeh <[email protected]> wrote: > > It'd be interesting to see which rados operation is slowing down the > requests. Can you provide a log dump of a request (with 'debug rgw = > 20', and 'debug ms = 1'). This might give us a better idea as to > what's going on. > > Thanks, > Yehuda > > On Mon, Oct 6, 2014 at 10:05 AM, Daniel Schneller > <[email protected]> wrote: >> Hi again! >> >> We have done some tests regarding the limits of storing lots and >> lots of buckets through Rados Gateway into Ceph. >> >> Our test used a single user for which we removed the default max >> buckets limit. It then continuously created containers - both empty >> and such with 10 objects of around 100k random data in them. >> >> With 3 parallel processes we saw relatively consistent time of >> about 500-700ms per such container. >> >> This kept steady until we reached approx. 3 million containers >> after which the time per insert sharply went up to currently >> around 1600ms and rising. Due to some hiccups with network >> equipment the tests were aborted a few times, but then resumed without >> deleting any of the previous runs created containers, so the actual >> number might be 2.8 or 3.2 million, but still in that ballpark. >> We aborted the test here. >> >> Judging by the advice given earlier (see quoted mail below) that >> we might hit a limit on some per-user data structures, we created >> another user account, removed its max-bucket limit as well and >> restarted the benchmark with that one, _expecting_ the times to be >> down to the original range of 500-700ms. >> >> However, what we are seeing is that the times stay at the 1600ms >> and higher levels even for that fresh account. >> >> Here is the output of `rados df`, reformatted to fit the email. >> clones, degraded and unfound were 0 in all cases and have been >> left out for clarity: >> >> .rgw >> ========================= >> KB: 1,966,932 >> objects: 9,094,552 >> rd: 195,747,645 >> rd KB: 153,585,472 >> wr: 30,191,844 >> wr KB: 10,751,065 >> >> .rgw.buckets >> ========================= >> KB: 2,038,313,855 >> objects: 22,088,103 >> rd: 5,455,123 >> rd KB: 408,416,317 >> wr: 149,377,728 >> wr KB: 1,882,517,472 >> >> .rgw.buckets.index >> ========================= >> KB: 0 >> objects: 5,374,376 >> rd: 267,996,778 >> rd KB: 262,626,106 >> wr: 107,142,891 >> wr KB: 0 >> >> .rgw.control >> ========================= >> KB: 0 >> objects: 8 >> rd: 0 >> rd KB: 0 >> wr: 0 >> wr KB: 0 >> >> .rgw.gc >> ========================= >> KB: 0 >> objects: 32 >> rd: 5,554,407 >> rd KB: 5,713,942 >> wr: 8,355,934 >> wr KB: 0 >> >> .rgw.root >> ========================= >> KB: 1 >> objects: 3 >> rd: 524 >> rd KB: 346 >> wr: 3 >> wr KB: 3 >> >> >> We would very much like to understand what is going on here >> in order to decide if Rados Gateway is a viable option to base >> our production system on (where we expect similar counts >> as in the benchmark), or if we need to investigate using librados >> directly which we would like to avoid if possible. >> >> Any advice on what configuration parameters to check or >> which additional information to provide to analyze this would be >> very much welcome. >> >> Cheers, >> Daniel >> >> >> -- >> Daniel Schneller >> Mobile Development Lead >> >> CenterDevice GmbH | Merscheider Straße 1 >> | 42699 Solingen >> tel: +49 1754155711 | Deutschland >> [email protected] | www.centerdevice.com >> >> >> >> >> On 10 Sep 2014, at 19:42, Gregory Farnum <[email protected]> wrote: >> >> On Wednesday, September 10, 2014, Daniel Schneller >> <[email protected]> wrote: >>> >>> On 09 Sep 2014, at 21:43, Gregory Farnum <[email protected]> wrote: >>> >>> >>> Yehuda can talk about this with more expertise than I can, but I think >>> it should be basically fine. By creating so many buckets you're >>> decreasing the effectiveness of RGW's metadata caching, which means >>> >>> the initial lookup in a particular bucket might take longer. >>> >>> >>> Thanks for your thoughts. With “initial lookup in a particular bucket” >>> do you mean accessing any of the objects in a bucket? If we directly >>> access the object (not enumerating the buckets content), would that >>> still be an issue? >>> Just trying to understand the inner workings a bit better to make >>> more educated guesses :) >> >> >> When doing an object lookup, the gateway combines the "bucket ID" with a >> mangled version of the object name to try and do a read out of RADOS. It >> first needs to get that bucket ID though -- it will cache an the bucket >> name->ID mapping, but if you have a ton of buckets there could be enough >> entries to degrade the cache's effectiveness. (So, you're more likely to pay >> that extra disk access lookup.) >> >>> >>> >>> >>> The big concern is that we do maintain a per-user list of all their >>> buckets — which is stored in a single RADOS object — so if you have an >>> extreme number of buckets that RADOS object could get pretty big and >>> become a bottleneck when creating/removing/listing the buckets. You >>> >>> >>> Alright. Listing buckets is no problem, that we don’t do. Can you >>> say what “pretty big” would be in terms of MB? How much space does a >>> bucket record consume in there? Based on that I could run a few numbers. >> >> >> Uh, a kilobyte per bucket? You could look it up in the source (I'm on my >> phone) but I *believe* the bucket name is allowed to be larger than the rest >> combined... >> More particularly, though, if you've got a single user uploading documents, >> each creating a new bucket, then those bucket creates are going to serialize >> on this one object. >> -Greg >> >>> >>> >>> >>> should run your own experiments to figure out what the limits are >>> there; perhaps you have an easy way of sharding up documents into >>> different users. >>> >>> >>> Good advice. We can do that per distributor (an org unit in our >>> software) to at least compartmentalize any potential locking issues >>> in this area to that single entity. Still, there would be quite >>> a lot of buckets/objects per distributor, so some more detail on >>> the above items would be great. >>> >>> Thanks a lot! >>> >>> >>> Daniel >> >> >> >> -- >> Software Engineer #42 @ http://inktank.com | http://ceph.com >> >> >> >> _______________________________________________ >> ceph-users mailing list >> [email protected] >> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com >>
_______________________________________________ ceph-users mailing list [email protected] http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
