Project

General

Profile

Actions
Copy link

Bug #43894

open

validating permissions for get requests takes much longer than list request

Added by Or Friedmann about 4 years ago. Updated about 4 years ago.

Status:
Triaged
Priority:
Normal
Assignee:
Or Friedmann
Target version:
Ceph - v15.0.0
% Done:

0%

Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
Ceph - v15.0.0
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket recalculating target
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket reading permissions
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket init op
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket verifying op mask
2020-01-30T11:09:18.501+0200 7fd259fc3700 20 req 3 0.003000083s s3:list_bucket required_mask= 1 user.op_mask=7
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket verifying op permissions
2020-01-30T11:09:18.501+0200 7fd259fc3700 20 req 3 0.003000083s s3:list_bucket -- Getting permissions begin with perm_mask=49
2020-01-30T11:09:18.501+0200 7fd259fc3700 5 req 3 0.003000083s s3:list_bucket Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) mask=49
2020-01-30T11:09:18.501+0200 7fd259fc3700 5 Searching permissions for uid=testid
2020-01-30T11:09:18.501+0200 7fd259fc3700 5 Found permission: 15
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Searching permissions for group=1 mask=49
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Permissions for group not found
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Searching permissions for group=2 mask=49
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Permissions for group not found
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 req 3 0.004000110s s3:list_bucket - Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0), owner=testid, perm=1
2020-01-30T11:09:18.502+0200 7fd259fc3700 10 req 3 0.004000110s s3:list_bucket identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) requested perm (type)=1, policy perm=1, user_perm_mask=1, acl perm=1
2020-01-30T11:09:18.502+0200 7fd259fc3700 2 req 3 0.004000110s s3:list_bucket verifying op params

list ~ 4ms

2020-01-30T11:13:27.276+0200 7fd1e77ae700 15 req 6 0.003000082s s3:get_obj server signature=39d10b469fade649f43fc7c80720820fe8b3947ca8a720fca6eb9d09a9f071f4
2020-01-30T11:13:27.276+0200 7fd1e77ae700 15 req 6 0.003000082s s3:get_obj client signature=39d10b469fade649f43fc7c80720820fe8b3947ca8a720fca6eb9d09a9f071f4
2020-01-30T11:13:27.276+0200 7fd1e77ae700 15 req 6 0.003000082s s3:get_obj compare=0
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 req 6 0.003000082s s3:get_obj rgw::auth::s3::LocalEngine granted access
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 req 6 0.003000082s s3:get_obj rgw::auth::s3::AWSAuthStrategy granted access
2020-01-30T11:13:27.276+0200 7fd1e77ae700 2 req 6 0.003000082s s3:get_obj normalizing buckets and tenants
2020-01-30T11:13:27.276+0200 7fd1e77ae700 10 s->object=xxx s->bucket=hello
2020-01-30T11:13:27.276+0200 7fd1e77ae700 2 req 6 0.003000082s s3:get_obj init permissions
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 get_system_obj_state: rctx=0x7fd4c03eefb8 obj=default.rgw.meta:root:hello state=0x7fd320018c70 s->prefetch_data=0
2020-01-30T11:13:27.276+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+root+hello : hit (requested=0x16, cached=0x17)
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 get_system_obj_state: s->obj_tag was set empty
2020-01-30T11:13:27.276+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+root+hello : hit (requested=0x11, cached=0x17)
2020-01-30T11:13:27.277+0200 7fd1e77ae700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/&quot;&gt;&lt;Owner&gt;&lt;ID&gt;testid&lt;/ID&gt;&lt;DisplayName&gt;M. Tester</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance&quot; xsi:type="CanonicalUser"><ID>testid</ID><DisplayName>M. Tester</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2020-01-30T11:13:27.277+0200 7fd1e77ae700 20 get_system_obj_state: rctx=0x7fd4c03ef478 obj=default.rgw.meta:users.uid:testid state=0x7fd320018c70 s->prefetch_data=0
2020-01-30T11:13:27.277+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+users.uid+testid : hit (requested=0x6, cached=0x17)
2020-01-30T11:13:27.277+0200 7fd1e77ae700 20 get_system_obj_state: s->obj_tag was set empty
2020-01-30T11:13:27.277+0200 7fd1e77ae700 20 Read xattr: user.rgw.idtag
2020-01-30T11:13:27.277+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+users.uid+testid : hit (requested=0x3, cached=0x17)
2020-01-30T11:13:27.277+0200 7fd1e77ae700 2 req 6 0.004000110s s3:get_obj recalculating target
2020-01-30T11:13:27.277+0200 7fd1e77ae700 2 req 6 0.004000110s s3:get_obj reading permissions
2020-01-30T11:13:27.278+0200 7fd1e77ae700 20 get_obj_state: rctx=0x7fd4c03f29e8 obj=hello:xxx state=0x7fd32001a018 s->prefetch_data=0
2020-01-30T11:13:27.278+0200 7fd1e77ae700 20 WARNING: blocking librados call
2020-01-30T11:13:27.283+0200 7fd1e77ae700 10 manifest: total_size = 571648542
2020-01-30T11:13:27.283+0200 7fd1e77ae700 20 get_obj_state: setting s->obj_tag to c3389a18-0740-434f-9232-c770e512d902.4155.5
2020-01-30T11:13:27.283+0200 7fd1e77ae700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/&quot;&gt;&lt;Owner&gt;&lt;ID&gt;testid&lt;/ID&gt;&lt;DisplayName&gt;M. Tester</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance&quot; xsi:type="CanonicalUser"><ID>testid</ID><DisplayName>M. Tester</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2020-01-30T11:13:27.283+0200 7fd1e77ae700 2 req 6 0.010000275s s3:get_obj init op
2020-01-30T11:13:27.283+0200 7fd1e77ae700 2 req 6 0.010000275s s3:get_obj verifying op mask
2020-01-30T11:13:27.283+0200 7fd1e77ae700 20 req 6 0.010000275s s3:get_obj required_mask= 1 user.op_mask=7
2020-01-30T11:13:27.283+0200 7fd1e77ae700 2 req 6 0.010000275s s3:get_obj verifying op permissions
2020-01-30T11:13:27.284+0200 7fd1e77ae700 20 req 6 0.011000302s s3:get_obj -- Getting permissions begin with perm_mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 req 6 0.011000302s s3:get_obj Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Searching permissions for uid=testid
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Found permission: 15
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Searching permissions for group=1 mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Permissions for group not found
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Searching permissions for group=2 mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Permissions for group not found
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 req 6 0.011000302s s3:get_obj - Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0), owner=testid, perm=1
2020-01-30T11:13:27.284+0200 7fd1e77ae700 10 req 6 0.011000302s s3:get_obj identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) requested perm (type)=1, policy perm=1, user_perm_mask=15, acl perm=1
2020-01-30T11:13:27.284+0200 7fd1e77ae700 2 req 6 0.011000302s s3:get_obj verifying op params

Get ~ 11ms

Actions
Copy link
 #1

Updated by Casey Bodley about 4 years ago

  • Status changed from New to Triaged
  • Assignee set to Or Friedmann
Actions
Copy link
 #2

Updated by Casey Bodley about 4 years ago

Try adding --debug-ms=1 to include osd requests/replies in the log out. You could use that to compare the osds ops from the two different requests, and calculate the latency of the osd ops themselves.

Actions
Copy link

Also available in: Atom PDF