Ceph » CephFS

Maybe related on testing branch: /ceph/teuthology-archive/pdonnell-2022-01-28_01:59:55-fs:workload-wip-pdonnell-testing-20220127.171526-distro-default-smithi/6645065/remote/smithi019/syslog/kern.log.gz

2022-01-28T03:22:27.902598+00:00 smithi019 kernel: libceph: mon0 (2)172.21.15.19:3300 session established
2022-01-28T03:22:27.910606+00:00 smithi019 kernel: libceph: client15204 fsid fbf413ce-7fe7-11ec-8c35-001a4aab830c
2022-01-28T03:41:39.136284+00:00 smithi019 kernel: ceph: dump_cap_flushes: still waiting for cap flushes through 79658:
2022-01-28T03:41:39.136444+00:00 smithi019 kernel: ceph: 5000000121f:fffffffffffffffe Fw 77655 0 1
2022-01-28T03:42:40.575953+00:00 smithi019 kernel: ceph: dump_cap_flushes: still waiting for cap flushes through 79658:
2022-01-28T03:42:40.576109+00:00 smithi019 kernel: ceph: 5000000121f:fffffffffffffffe Fw 77655 0 1
2022-01-28T03:43:42.015942+00:00 smithi019 kernel: ceph: dump_cap_flushes: still waiting for cap flushes through 79658:
2022-01-28T03:43:42.016095+00:00 smithi019 kernel: ceph: 5000000121f:fffffffffffffffe Fw 77655 0 1
2022-01-28T03:44:43.455977+00:00 smithi019 kernel: ceph: dump_cap_flushes: still waiting for cap flushes through 79658:
2022-01-28T03:44:43.456138+00:00 smithi019 kernel: ceph: 5000000121f:fffffffffffffffe Fw 77655 0 1
2022-01-28T03:45:36.299594+00:00 smithi019 kernel: libceph: mds0 (2)172.21.15.139:6838 socket closed (con state OPEN)
2022-01-28T03:45:36.320594+00:00 smithi019 kernel: libceph: mds2 (2)172.21.15.139:6834 socket closed (con state OPEN)
2022-01-28T03:45:36.331594+00:00 smithi019 kernel: libceph: mds1 (2)172.21.15.139:6836 socket closed (con state OPEN)
2022-01-28T03:45:36.372590+00:00 smithi019 kernel: libceph: mds3 (2)172.21.15.139:6832 socket closed (con state OPEN)
2022-01-28T03:45:36.372778+00:00 smithi019 kernel: libceph: mds4 (2)172.21.15.19:6840 socket closed (con state OPEN)
2022-01-28T06:58:34.552206+00:00 smithi019 kernel: perf: interrupt took too long (2525 > 2500), lowering kernel.perf_event_max_sample_rate to 79000

It really looks like we just never got a FLUSH_ACK for this cap:

2022-01-28T03:41:39.136284+00:00 smithi019 kernel: ceph: dump_cap_flushes: still waiting for cap flushes through 79658:
2022-01-28T03:41:39.136444+00:00 smithi019 kernel: ceph: 5000000121f:fffffffffffffffe Fw 77655 0 1

It really looks a lot like we just never received a FLUSH_ACK for this inode. The 4th field (the 0) is ci->i_last_cap_flush_ack, and that is set to 0, which means we've never seen a FLUSH_ACK for this inode.

What happens if the MDS gets a cap flush for an inode that doesn't exist yet? I don't think we can end up sending a cap flush before the create call, but it seems plausible that they could be processed in reverse order in the MDS.

Do we need to make the client wait until it gets the create response before we send a cap flush for it?

Venky, Patrick : any thoughts on the above? Either way, it might be nice to revise the dout() messages in Locker::handle_client_caps with lower numerical values, so that we get log messages if it just drops a cap flush on the floor.

I'll see if I can come up with an RFC patch for the MDS.

Jeff Layton wrote:

It really looks like we just never got a FLUSH_ACK for this cap:

[...]

It really looks a lot like we just never received a FLUSH_ACK for this inode. The 4th field (the 0) is ci->i_last_cap_flush_ack, and that is set to 0, which means we've never seen a FLUSH_ACK for this inode.

What happens if the MDS gets a cap flush for an inode that doesn't exist yet? I don't think we can end up sending a cap flush before the create call, but it seems plausible that they could be processed in reverse order in the MDS.

I think if the create gets put on a wait list then maybe (?) a cap flush could be sent and ignored by the MDS.

Do we need to make the client wait until it gets the create response before we send a cap flush for it?

That seems reasonable to me. I wonder what other places in the kclient wait for an unsafe create reply before e.g. releasing caps.