After some parallel copy command via botto for many files everything,
going to slow down, and eventualy got timeout from nginx@radosgw.
# ceph -s
2012-02-28 12:16:57.818566 pg v20743: 8516 pgs: 8516 active+clean;
2154 MB data, 53807 MB used, 20240 GB / 21379 GB avail
2012-02-28 12:16:57.845274 mds e1: 0/0/1 up
2012-02-28 12:16:57.845307 osd e719: 78 osds: 78 up, 78 in
2012-02-28 12:16:57.845512 log 2012-02-28 12:14:41.578889 osd.24
10.177.64.4:6839/2063 20 : [WRN] old request
osd_op(client.62138.0:1162 3_.archive/1330427624.13/37828,serwisy.html
[delete,create 0~0,setxattr user.rgw.acl (62),setxattr
user.rgw.content_type (10),setxattr user.rgw.etag (33),setxattr
user.rgw.idtag,setxattr user.rgw.x-amz-copy-source (33),setxattr
user.rgw.x-amz-meta-checksum (33),setxattr
user.rgw.x-amz-metadata-directive (5),setxattr
user.rgw.x-amz-storage-class (9),setxattr user.rgw.idtag (32),setxattr
user.rgw.shadow_name (74),clonerange 0~17913 from
3_.archive/1330427624.13/37828,serwisy.html_g8DHGgLP7Dhi7YSAzYtu_FGT_96NsiF/head
offset 0] 7.645e07f5) v4 received at 2012-02-28 12:14:10.683511
currently waiting for sub ops
2012-02-28 12:16:57.845622 mon e3: 3 mons at
{0=10.177.64.4:6789/0,1=10.177.64.6:6789/0,2=10.177.64.8:6789/0}
and other one from ceph -s
2012-02-28 12:32:16.697642 pg v21010: 8516 pgs: 8516 active+clean;
2161 MB data, 53839 MB used, 20240 GB / 21379 GB avail
2012-02-28 12:32:16.722796 mds e1: 0/0/1 up
2012-02-28 12:32:16.722938 osd e719: 78 osds: 78 up, 78 in
2012-02-28 12:32:16.723204 log 2012-02-28 12:28:30.015814 osd.24
10.177.64.4:6839/2063 78 : [WRN] old request
osd_op(client.62020.0:3344 .dir.3 [call rgw.bucket_complete_op]
7.ccb26a35) v4 received at 2012-02-28 12:27:59.458121 currently
waiting for sub ops
2012-02-28 12:32:16.723327 mon e3: 3 mons at
{0=10.177.64.4:6789/0,1=10.177.64.6:6789/0,2=10.177.64.8:6789/0}
from nginx timeout after 33 seconds.
10.177.8.12 - - - [28/Feb/2012:12:14:19 +0100] "PUT
/www.onet.pl/.archive/1330427624.13/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
HTTP/1.1" rlength: 528 bsent: 0 rtime: 33.001 urtime: - status: 499
bbsent: 0 httpref: "-" useragent: "Boto/2.2.2 (linux2)"
Inside attachment logs from radosgw in debug mode.
In normal put, get, head etc, everything works OK. Only parallel copy
going to be mess i think :).
I see some in radosgw log:
2012-02-28 12:27:34.774107 7ff99bfef700 can't clone object
www.onet.pl:.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
to shadow object, tag/shadow_obj haven't been set
and
2012-02-28 12:27:52.798272 7ff99bfef700 prepare_atomic_for_write_impl:
state is not atomic. state=0x7ff93c02cd58
I use ceph 0.42 with ext4 as local filesystems, maybe xattr in ext4
make that problem ??.
--
-----
Pozdrawiam
Sławek Skowron
2012-02-28 12:27:34.767514 7ff99bfef700 dequeued request req=0x7ff93c08fb10
2012-02-28 12:27:34.767531 7ff99bfef700 RGWWQ: empty
2012-02-28 12:27:34.767544 7ff99bfef700 ====== starting new request req=0x7ff93c08fb10 =====
2012-02-28 12:27:34.767593 7ff99bfef700 req 650:0.000047::::initializing
2012-02-28 12:27:34.767601 7ff99bfef700 in url_decode with /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.767606 7ff99bfef700 src=/test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.767612 7ff99bfef700 dest=/test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
2012-02-28 12:27:34.767630 7ff99bfef700 in url_decode with
2012-02-28 12:27:34.767636 7ff99bfef700 src=
2012-02-28 12:27:34.767640 7ff99bfef700 dest=
2012-02-28 12:27:34.767646 7ff99bfef700 parsed: name= val=
2012-02-28 12:27:34.767662 7ff99bfef700 s->object=.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif s->bucket=test
2012-02-28 12:27:34.767675 7ff99bfef700 meta>> HTTP_X_AMZ_STORAGE_CLASS=STANDARD
2012-02-28 12:27:34.767690 7ff99bfef700 meta>> HTTP_X_AMZ_COPY_SOURCE=test/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.767704 7ff99bfef700 meta>> HTTP_X_AMZ_METADATA_DIRECTIVE=COPY
2012-02-28 12:27:34.767717 7ff99bfef700 x>> x-amz-copy-source:test/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.767723 7ff99bfef700 x>> x-amz-metadata-directive:COPY
2012-02-28 12:27:34.767727 7ff99bfef700 x>> x-amz-storage-class:STANDARD
2012-02-28 12:27:34.767736 7ff99bfef700 FCGI_ROLE=RESPONDER
2012-02-28 12:27:34.767741 7ff99bfef700 SCRIPT_FILENAME=/var/www/radosgw.fcgi
2012-02-28 12:27:34.767745 7ff99bfef700 QUERY_STRING=
2012-02-28 12:27:34.767750 7ff99bfef700 REQUEST_METHOD=PUT
2012-02-28 12:27:34.767755 7ff99bfef700 CONTENT_TYPE=
2012-02-28 12:27:34.767759 7ff99bfef700 CONTENT_LENGTH=0
2012-02-28 12:27:34.767764 7ff99bfef700 SCRIPT_NAME=/test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
2012-02-28 12:27:34.767777 7ff99bfef700 REQUEST_URI=/test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.767782 7ff99bfef700 DOCUMENT_URI=/test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
2012-02-28 12:27:34.767787 7ff99bfef700 DOCUMENT_ROOT=/var/www
2012-02-28 12:27:34.767791 7ff99bfef700 SERVER_PROTOCOL=HTTP/1.1
2012-02-28 12:27:34.767795 7ff99bfef700 GATEWAY_INTERFACE=CGI/1.1
2012-02-28 12:27:34.767800 7ff99bfef700 SERVER_SOFTWARE=nginx/1.0.5
2012-02-28 12:27:34.767804 7ff99bfef700 REMOTE_ADDR=10.177.8.11
2012-02-28 12:27:34.767808 7ff99bfef700 REMOTE_PORT=47279
2012-02-28 12:27:34.767813 7ff99bfef700 SERVER_ADDR=10.177.64.8
2012-02-28 12:27:34.767817 7ff99bfef700 SERVER_PORT=80
2012-02-28 12:27:34.767822 7ff99bfef700 SERVER_NAME=
2012-02-28 12:27:34.767826 7ff99bfef700 REDIRECT_STATUS=200
2012-02-28 12:27:34.767830 7ff99bfef700 HTTP_HOST=10.177.0.3
2012-02-28 12:27:34.767835 7ff99bfef700 HTTP_ACCEPT_ENCODING=identity
2012-02-28 12:27:34.767839 7ff99bfef700 HTTP_CONTENT_LENGTH=0
2012-02-28 12:27:34.767844 7ff99bfef700 HTTP_X_AMZ_STORAGE_CLASS=STANDARD
2012-02-28 12:27:34.767848 7ff99bfef700 HTTP_USER_AGENT=Boto/2.2.2 (linux2)
2012-02-28 12:27:34.767852 7ff99bfef700 HTTP_X_AMZ_COPY_SOURCE=test/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.767857 7ff99bfef700 HTTP_DATE=Tue, 28 Feb 2012 11:27:32 GMT
2012-02-28 12:27:34.767861 7ff99bfef700 HTTP_AUTHORIZATION=AWS 73VF66Q2JH5PT5K7QJ3A:Colo8TeOgpkMWG6g763152hie2A=
2012-02-28 12:27:34.767866 7ff99bfef700 HTTP_X_AMZ_METADATA_DIRECTIVE=COPY
2012-02-28 12:27:34.767870 7ff99bfef700 HTTP_X_FORWARDED_FOR=10.177.57.86
2012-02-28 12:27:34.767875 7ff99bfef700 HTTP_CONNECTION=close
2012-02-28 12:27:34.767883 7ff99bfef700 req 650:0.000339:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif::getting op
2012-02-28 12:27:34.767892 7ff99bfef700 req 650:0.000348:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif:copy_obj:authorizing
2012-02-28 12:27:34.767909 7ff99bfef700 get_obj_state: rctx=0x7ff93c0971e0 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7ff93c097298 s->prefetch_data=0
2012-02-28 12:27:34.767920 7ff99bfef700 moving .users+73VF66Q2JH5PT5K7QJ3A to cache LRU end
2012-02-28 12:27:34.767926 7ff99bfef700 cache get: name=.users+73VF66Q2JH5PT5K7QJ3A : hit
2012-02-28 12:27:34.767934 7ff99bfef700 get_obj_state: s->obj_tag was set empty
2012-02-28 12:27:34.767942 7ff99bfef700 moving .users+73VF66Q2JH5PT5K7QJ3A to cache LRU end
2012-02-28 12:27:34.767948 7ff99bfef700 cache get: name=.users+73VF66Q2JH5PT5K7QJ3A : hit
2012-02-28 12:27:34.767993 7ff99bfef700 get_canon_resource(): dest=/test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.768003 7ff99bfef700 auth_hdr:
2012-02-28 12:27:34.768024 7ff99bfef700 hmac=0a8968f1378e82990c586ea0efadf5e768627b60
2012-02-28 12:27:34.768041 7ff99bfef700 b64=Colo8TeOgpkMWG6g763152hie2A=
2012-02-28 12:27:34.768052 7ff99bfef700 auth_sign=Colo8TeOgpkMWG6g763152hie2A=
2012-02-28 12:27:34.768061 7ff99bfef700 compare=0
2012-02-28 12:27:34.768072 7ff99bfef700 req 650:0.000527:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif:copy_obj:reading permissions
2012-02-28 12:27:34.768088 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=.rgw:test state=0x7ff93c097628 s->prefetch_data=0
2012-02-28 12:27:34.768096 7ff99bfef700 moving .rgw+test to cache LRU end
2012-02-28 12:27:34.768102 7ff99bfef700 cache get: name=.rgw+test : hit
2012-02-28 12:27:34.768111 7ff99bfef700 get_obj_state: s->obj_tag was set empty
2012-02-28 12:27:34.768126 7ff99bfef700 moving .rgw+test to cache LRU end
2012-02-28 12:27:34.768132 7ff99bfef700 cache get: name=.rgw+test : hit
2012-02-28 12:27:34.768144 7ff99bfef700 rgw_get_bucket_info: bucket=test(@.rgw.buckets[3]) owner 0
2012-02-28 12:27:34.768158 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test: state=0x7ff93c097628 s->prefetch_data=0
2012-02-28 12:27:34.768174 7ff99bfef700 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>0</ID><DisplayName>ocdn</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>0</ID><DisplayName>ocdn</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2012-02-28 12:27:34.768183 7ff99bfef700 req 650:0.000639:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif:copy_obj:verifying op permissions
2012-02-28 12:27:34.768191 7ff99bfef700 in url_decode with test/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.768196 7ff99bfef700 src=test/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.768202 7ff99bfef700 dest=test/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
2012-02-28 12:27:34.768207 7ff99bfef700 decoded obj=test/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
2012-02-28 12:27:34.768218 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=.rgw:test state=0x7ff93c097628 s->prefetch_data=0
2012-02-28 12:27:34.768226 7ff99bfef700 moving .rgw+test to cache LRU end
2012-02-28 12:27:34.768231 7ff99bfef700 cache get: name=.rgw+test : hit
2012-02-28 12:27:34.768242 7ff99bfef700 rgw_get_bucket_info: bucket=test(@.rgw.buckets[3]) owner 0
2012-02-28 12:27:34.768256 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test:__d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif state=0x7ff93c097ce8 s->prefetch_data=0
2012-02-28 12:27:34.769338 7ff99bfef700 get_obj_state: s->obj_tag was set empty
2012-02-28 12:27:34.769449 7ff99bfef700 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>0</ID><DisplayName>ocdn</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>0</ID><DisplayName>ocdn</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="Group"><URI>http://acs.amazonaws.com/groups/global/AllUsers</URI></Grantee><Permission>READ</Permission></Grant></AccessControlList></AccessControlPolicy>
2012-02-28 12:27:34.769471 7ff99bfef700 Searching permissions for uid=0 mask=1
2012-02-28 12:27:34.769485 7ff99bfef700 Found permission: 15
2012-02-28 12:27:34.769496 7ff99bfef700 uid=0 requested perm (type)=1, policy perm=1, user_perm_mask=15, acl perm=1
2012-02-28 12:27:34.769511 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test: state=0x7ff93c097628 s->prefetch_data=0
2012-02-28 12:27:34.769528 7ff99bfef700 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>0</ID><DisplayName>ocdn</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>0</ID><DisplayName>ocdn</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2012-02-28 12:27:34.769536 7ff99bfef700 Searching permissions for uid=0 mask=2
2012-02-28 12:27:34.769542 7ff99bfef700 Found permission: 15
2012-02-28 12:27:34.769548 7ff99bfef700 uid=0 requested perm (type)=2, policy perm=2, user_perm_mask=15, acl perm=2
2012-02-28 12:27:34.769597 7ff99bfef700 req 650:0.002052:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif:copy_obj:verifying op params
2012-02-28 12:27:34.769610 7ff99bfef700 req 650:0.002065:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif:copy_obj:executing
2012-02-28 12:27:34.769668 7ff99bfef700 x>> x-amz-copy-source:test/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif
2012-02-28 12:27:34.769743 7ff99bfef700 x>> x-amz-metadata-directive:COPY
2012-02-28 12:27:34.769786 7ff99bfef700 x>> x-amz-storage-class:STANDARD
2012-02-28 12:27:34.769895 7ff99bfef700 Copy object test(@.rgw.buckets[3]):__d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif => test(@.rgw.buckets[3]):.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif
2012-02-28 12:27:34.769973 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test:__d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif state=0x7ff93c097ce8 s->prefetch_data=0
2012-02-28 12:27:34.769992 7ff99bfef700 Read xattr: user.rgw.acl
2012-02-28 12:27:34.770004 7ff99bfef700 Read xattr: user.rgw.content_type
2012-02-28 12:27:34.770015 7ff99bfef700 Read xattr: user.rgw.etag
2012-02-28 12:27:34.770027 7ff99bfef700 Read xattr: user.rgw.idtag
2012-02-28 12:27:34.770038 7ff99bfef700 Read xattr: user.rgw.x-amz-meta-checksum
2012-02-28 12:27:34.770054 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test:__d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif state=0x7ff93c097ce8 s->prefetch_data=0
2012-02-28 12:27:34.770061 7ff99bfef700 state->obj_tag is empty, not appending atomic test
2012-02-28 12:27:34.770067 7ff99bfef700 rados->read ofs=0 len=3346
2012-02-28 12:27:34.770856 7ff99bfef700 rados->read r=0 bl.length=3346
2012-02-28 12:27:34.773301 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test:.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif state=0x7ff93c099d58 s->prefetch_data=0
2012-02-28 12:27:34.774107 7ff99bfef700 can't clone object test:.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif to shadow object, tag/shadow_obj haven't been set
2012-02-28 12:27:34.774178 7ff99bfef700 calling op.clone_range(dst_ofs=0, src.object=.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif_U-nYhwkjVZT_hzxpSaZG1c9WjqeDFjI range.src_ofs=0 range.len=3346
2012-02-28 12:27:52.797247 7ff99bfef700 get_obj_state: rctx=0x7ff93c091850 obj=test:.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d,wyslij_belka.gif_U-nYhwkjVZT_hzxpSaZG1c9WjqeDFjI state=0x7ff93c02cd58 s->prefetch_data=0
2012-02-28 12:27:52.798252 7ff99bfef700 get_obj_state: s->obj_tag was set empty
2012-02-28 12:27:52.798272 7ff99bfef700 prepare_atomic_for_write_impl: state is not atomic. state=0x7ff93c02cd58
2012-02-28 12:27:52.798389 7ff99bfef700 --> Status: 200
2012-02-28 12:27:52.798426 7ff99bfef700 --> Content-type: binary/octet-stre
2012-02-28 12:27:52.798537 7ff99bfef700 req 650:18.030990:s3:PUT /test/.archive/1330428452.43/_d/dodatki/887184387c048cb30c88f22169f0f74d%2Cwyslij_belka.gif:copy_obj:http status=200
2012-02-28 12:27:52.798696 7ff99bfef700 ====== req done req=0x7ff93c08fb10 http_status=200 ======
