Ceph » CephFS

From 5451587/remote/smithi110/log/ceph-client.1.30354.log.gz:

We can see that the client.4606 has received the revoke request and was trying to flush the dirty data to disks and the start time is "2020-09-20T16:26:35.056+0000":

2020-09-20T16:26:35.056+0000 7f55ceffd700  5 client.4606 handle_cap_grant on in 0x200000007d5 mds.0 seq 11 caps now pAsLsXsFscr was pAsLsXsFsxcrwb
2020-09-20T16:26:35.056+0000 7f55ceffd700 10 client.4606 update_inode_file_time 0x200000007d5.head(faked_ino=0 ref=5 ll_ref=3 cap_refs={4=0,1024=1,4096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=1 btime=0.000000 mtime=2020-09-20T16:18:26.669617+0000 ctime=2020-09-20T16:18:26.669617+0000 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[0x200000007d5 ts 0/0 objects 25 dirty_or_tx 196608] parents=0x10000000731.head["datafile116"] 0x7f55c4063540) pAsLsXsFsxcrwb ctime 2020-09-20T16:18:26.669617+0000 mtime 2020-09-20T16:18:26.669617+0000
2020-09-20T16:26:35.056+0000 7f55ceffd700 10 client.4606   revocation of Fxwb
2020-09-20T16:26:35.056+0000 7f55ceffd700 15 inode.get on 0x7f55c4063540 0x200000007d5.head now 6
2020-09-20T16:26:35.056+0000 7f55ceffd700 10 client.4606 _flush 0x200000007d5.head(faked_ino=0 ref=6 ll_ref=3 cap_refs={4=0,1024=1,4096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=1 btime=0.000000 mtime=2020-09-20T16:18:26.669617+0000 ctime=2020-09-20T16:18:26.669617+0000 caps=pAsLsXsFscr(0=pAsLsXsFscr) objectset[0x200000007d5 ts 0/0 objects 25 dirty_or_tx 196608] parents=0x10000000731.head["datafile116"] 0x7f55c4063540)
...

But the flush finished at "2020-09-20T16:29:20.386+0000":

...
2020-09-20T16:29:20.385+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 20171 ==== osd_op_reply(34991 200000007d5.00000005 [write 2269184~4096,write 2392064~4096] v26'11642 uv11642 ondisk = 0) v8 ==== 206+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:29:20.386+0000 7f55cffff700 10 client.4606 _flushed 0x200000007d5.head(faked_ino=0 ref=6 ll_ref=3 cap_refs={4=0,1024=1,4096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=1 btime=0.000000 mtime=2020-09-20T16:18:26.669617+0000 ctime=2020-09-20T16:18:26.669617+0000 caps=pAsLsXsFscr(0=pAsLsXsFscr) objectset[0x200000007d5 ts 0/0 objects 25 dirty_or_tx 0] parents=0x10000000731.head["datafile116"] 0x7f55c4063540)
2020-09-20T16:29:20.386+0000 7f55cffff700  5 client.4606 put_cap_ref dropped last FILE_BUFFER ref on 0x200000007d5.head(faked_ino=0 ref=6 ll_ref=3 cap_refs={4=0,1024=0,4096=0,8192=0} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=1 btime=0.000000 mtime=2020-09-20T16:18:26.669617+0000 ctime=2020-09-20T16:18:26.669617+0000 caps=pAsLsXsFscr(0=pAsLsXsFscr) objectset[0x200000007d5 ts 0/0 objects 25 dirty_or_tx 0] parents=0x10000000731.head["datafile116"] 0x7f55c4063540)
2020-09-20T16:29:20.386+0000 7f55cffff700  5 client.4606 put_cap_ref dropped last FILE_CACHE ref on 0x200000007d5.head(faked_ino=0 ref=6 ll_ref=3 cap_refs={4=0,1024=0,4096=0,8192=0} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=1 btime=0.000000 mtime=2020-09-20T16:18:26.669617+0000 ctime=2020-09-20T16:18:26.669617+0000 caps=pAsLsXsFscr(0=pAsLsXsFscr) objectset[0x200000007d5 ts 0/0 objects 25 dirty_or_tx 0] parents=0x10000000731.head["datafile116"] 0x7f55c4063540)
2020-09-20T16:29:20.386+0000 7f55cffff700 10 client.4606 check_caps on 0x200000007d5.head(faked_ino=0 ref=6 ll_ref=3 cap_refs={4=0,1024=0,4096=0,8192=0} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=1 btime=0.000000 mtime=2020-09-20T16:18:26.669617+0000 ctime=2020-09-20T16:18:26.669617+0000 caps=pAsLsXsFscr(0=pAsLsXsFscr) objectset[0x200000007d5 ts 0/0 objects 25 dirty_or_tx 0] parents=0x10000000731.head["datafile116"] 0x7f55c4063540) wanted - used Fc issued pAsLsXsFscr revoking Fxwb flags=0
2020-09-20T16:29:20.386+0000 7f55cffff700 10 client.4606  cap mds.0 issued pAsLsXsFscr implemented pAsLsXsFsxcrwb revoking Fxwb
2020-09-20T16:29:20.386+0000 7f55cffff700 10 client.4606 completed revocation of Fxwb

It took almost 165 seconds.

For this situation since the writing data to osd took too long, maybe the osds were overloaded.

During flush the 0x200000007d5 inode, there also have many other inodes doing the flush on the same osd.6 at the same time:

...
2020-09-20T16:27:45.084+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17565 ==== osd_op_reply(40514 3000000024f.00000003 [write 217088~4096] v26'10430 uv10430 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.099+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17566 ==== osd_op_reply(40516 3000000020c.00000003 [write 2367488~4096] v26'10432 uv10432 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.137+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17567 ==== osd_op_reply(30880 200000007d5.00000005 [write 2215936~4096] v26'10486 uv10486 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.153+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17568 ==== osd_op_reply(42340 30000000228.00000016 [write 995328~4096,write 4153344~4096] v26'11014 uv11014 ondisk = 0) v8 ==== 206+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.192+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17569 ==== osd_op_reply(42351 30000000203.00000006 [write 1839104~4096] v26'11016 uv11016 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.270+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17570 ==== osd_op_reply(36547 30000000208.0000000d [write 2760704~4096] v26'10391 uv10391 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.320+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17571 ==== osd_op_reply(40531 30000000200.00000004 [write 73728~4096] v26'10434 uv10434 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.356+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17572 ==== osd_op_reply(30881 30000000258.00000012 [write 2768896~4096] v26'10488 uv10488 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.356+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17573 ==== osd_op_reply(42360 30000000222.0000000c [write 1658880~4096] v26'11018 uv11018 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
2020-09-20T16:27:45.412+0000 7f55e1046700  1 -- 172.21.15.110:0/2458736152 <== osd.6 v2:172.21.15.120:6816/34366 17574 ==== osd_op_reply(36553 30000000208.00000016 [write 2854912~4096] v26'10393 uv10393 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f55d0025db0 con 0x7f55ac005420
@@@    
...                                                                              

Too many inodes to write to the same osd.6 at the same time could make the osd.6 to be overloaded.

@Patrick,

Maybe the MDS shouldn't report the WRN to monitor when revoking the "Fwbl" caps ? Since it may need to flush the dirty buffer to disk, which may take a longer time than 60 seonds.

Xiubo Li wrote:

@Patrick,

Maybe the MDS shouldn't report the WRN to monitor when revoking the "Fwbl" caps ? Since it may need to flush the dirty buffer to disk, which may take a longer time than 60 seonds.

Okay, so the issue is that one of the OSDs was slow. That's not unusual for these tests. Is there a timeout config we can bump to say 300 seconds so this warning goes away? I do not want to ignorelist the warning.

Patrick Donnelly wrote:

Xiubo Li wrote:

@Patrick,

Maybe the MDS shouldn't report the WRN to monitor when revoking the "Fwbl" caps ? Since it may need to flush the dirty buffer to disk, which may take a longer time than 60 seonds.

Okay, so the issue is that one of the OSDs was slow. That's not unusual for these tests. Is there a timeout config we can bump to say 300 seconds so this warning goes away? I do not want to ignorelist the warning.

This depends on the `session_timeout` value, which the default value is 60 seconds:

4145     // exponential backoff of warning intervals
4146     if (age > mds->mdsmap->get_session_timeout() * (1 << cap->get_num_revoke_warnings())) {
4147       cap->inc_num_revoke_warnings();     
4148       CachedStackStringStream css;
4149       *css << "client." << cap->get_client() << " isn't responding to mclientcaps(revoke), ino " 
4150            << cap->get_inode()->ino() << " pending " << ccap_string(cap->pending())
4151            << " issued " << ccap_string(cap->issued()) << ", sent " << age << " seconds ago"; 
4152       mds->clog->warn() << css->strv();   
4153       dout(20) << __func__ << " " << css->strv() << dendl;
4154     } else {
4155       dout(20) << __func__ << " silencing log message (backoff) for " << "client." << cap->get_client() << "." << cap->get_inode()->i     no() << dendl;
4156     }

# ./bin/ceph fs get a 
Filesystem 'a' (1)
fs_name a
epoch   125
flags   12
created 2020-09-28T17:02:27.386794+0800
modified        2020-09-30T09:17:14.772135+0800
tableserver     0
root    0
session_timeout 60
session_autoclose       300
max_file_size   1099511627776
required_client_features        {}
last_failure    0
last_failure_osd_epoch  0
compat  compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding,6=dirfrag is stored in omap,8=no anchor table,9=file layout v2,10=snaprealm v2}
max_mds 1
in      0
up      {0=4307}
failed
damaged
stopped
data_pools      [3]
metadata_pool   2
inline_data     disabled
balancer
standby_count_wanted    1
[mds.c{0:4307} state up:active seq 3190 addr [v2:10.72.37.222:6830/2699242870,v1:10.72.37.222:6831/2699242870]]

Currently AFAICK we can change this only by `fs set` command:

# ceph fs set a session_timeout 300

The 300 seconds should be fine, there also had some other similiar issues before which also could see the same logs and they all took less than 200s.

Sounds good. Please write up a PR for this Xiubo.

Patrick Donnelly wrote:

Sounds good. Please write up a PR for this Xiubo.

Sure, will do.

/ceph/teuthology-archive/yuriw-2020-10-07_19:13:19-multimds-wip-yuri5-testing-2020-10-07-1021-octopus-distro-basic-smithi/5504780/teuthology.log