Actions
Bug #64852
openMDS hangs on "joining batch getattr" when client does statx
% Done:
0%
Source:
Community (user)
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS, kceph
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Every couple days, our CephFS hangs on one specific directory:
# ls -1U /var/mycluster/files/logs/web-server mycluster-node-6 mycluster-node-5
In the above case, it hands listing the directory `mycluster-node-4`.
The directory in question contains 3 log files. To each one, a single process on the corresponding machine does append-only log writing.
A backup process on node-6 reads all of them from time to time, front to current-end.
This seems to cause some MDS hangs with ops "joining batch getattr", see further down.
This is very annoying, because it hangs the web-servers' operations, thus causing downtimes.
- Kernel mounts, Linux 6.1.51 x86_64
- roughly 3-machine setup (named "mycluster-node-4/5/6")
I suspect this started happening after theu pgrade from Ceph 16.2.7 to 18.2.1.
`ceph status`:
cluster:
id: d9000ec0-93c2-479f-bd5d-94ae9673e347
health: HEALTH_WARN
1 clients failing to respond to capability release
1 clients failing to advance oldest client/flush tid
1 MDSs report slow requests
`ceph health detail`:
HEALTH_WARN 1 clients failing to respond to capability release; 1 clients failing to advance oldest client/flush tid; 1 MDSs report slow requests
[WRN] MDS_CLIENT_LATE_RELEASE: 1 clients failing to respond to capability release
mds.mycluster-node-4(mds.0): Client mycluster-node-6 failing to respond to capability release client_id: 2834268
[WRN] MDS_CLIENT_OLDEST_TID: 1 clients failing to advance oldest client/flush tid
mds.mycluster-node-4(mds.0): Client mycluster-node-4 failing to advance its oldest client/flush tid. client_id: 2824133
[WRN] MDS_SLOW_REQUEST: 1 MDSs report slow requests
mds.mycluster-node-4(mds.0): 20 slow requests are blocked > 30 secs
`ceph daemon mds.mycluster-node-4 dump_ops_in_flight`:
{
"ops": [
{
"description": "client_request(client.2824133:9919861 getattr AsLsFs #0x100000005eb 2024-03-12T03:44:31.681505+0000 caller_uid=0, caller_gid=0{0,})",
"initiated_at": "2024-03-12T03:44:31.682342+0000",
"age": 771.75823718300001,
"duration": 771.75826522499995,
"type_data": {
"flag_point": "failed to rdlock, waiting",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9919861
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:44:31.682342+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:44:31.682342+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:44:31.682342+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:44:31.682346+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:44:31.682350+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:44:31.682364+0000",
"event": "failed to rdlock, waiting"
}
],
"locks": null
}
},
{
"description": "client_request(client.2834268:1816805 getattr AsLsFs #0x100000005eb 2024-03-12T03:44:46.716862+0000 caller_uid=0, caller_gid=0{0,})",
"initiated_at": "2024-03-12T03:44:46.718273+0000",
"age": 756.72230640800001,
"duration": 756.722368695,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2834268
},
"tid": 1816805
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:44:46.718273+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:44:46.718273+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:44:46.718273+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:44:46.718458+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:44:46.718469+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:44:46.718487+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920012 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:51:51.085328+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:51:51.086754+0000",
"age": 332.35382480800001,
"duration": 332.35391520799999,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920012
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:51:51.086754+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:51:51.086755+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:51:51.086754+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:51:51.086763+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:51:51.086855+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:51:51.086882+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920007 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:45:49.074642+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:45:49.075714+0000",
"age": 694.36486495400004,
"duration": 694.36498380700004,
"type_data": {
"flag_point": "failed to rdlock, waiting",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920007
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:45:49.075714+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:45:49.075714+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:45:49.075714+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:45:49.075720+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:45:49.075862+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:45:49.075900+0000",
"event": "failed to rdlock, waiting"
}
],
"locks": null
}
},
{
"description": "client_request(client.2834268:1816883 getattr AsLsFs #0x100000005eb 2024-03-12T03:52:40.459299+0000 caller_uid=0, caller_gid=0{0,})",
"initiated_at": "2024-03-12T03:52:40.459690+0000",
"age": 282.98088915099999,
"duration": 282.98103522500003,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2834268
},
"tid": 1816883
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:52:40.459690+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:52:40.459691+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:52:40.459690+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:52:40.459694+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:52:40.459704+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:52:40.459722+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2834268:1816884 getattr AsLsFs #0x100000005eb 2024-03-12T03:52:59.763439+0000 caller_uid=0, caller_gid=0{0,})",
"initiated_at": "2024-03-12T03:52:59.763937+0000",
"age": 263.67664239300001,
"duration": 263.67681670000002,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2834268
},
"tid": 1816884
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:52:59.763937+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:52:59.763937+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:52:59.763937+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:52:59.763945+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:52:59.763969+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:52:59.764013+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920008 getattr AsLsFs #0x100000005eb 2024-03-12T03:47:14.654799+0000 caller_uid=0, caller_gid=0{0,})",
"initiated_at": "2024-03-12T03:47:14.655225+0000",
"age": 608.78535396999996,
"duration": 608.785554757,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920008
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:47:14.655225+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:47:14.655226+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:47:14.655225+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:47:14.655235+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:47:14.655251+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:47:14.655295+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920009 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:47:19.602808+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:47:19.603301+0000",
"age": 603.83727808900005,
"duration": 603.83750533499995,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920009
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:47:19.603301+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:47:19.603301+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:47:19.603301+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:47:19.603305+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:47:19.603370+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:47:19.603390+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920013 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:53:21.592507+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:53:21.593509+0000",
"age": 241.84706984600001,
"duration": 241.84732366200001,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920013
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:53:21.593509+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:53:21.593510+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:53:21.593509+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:53:21.593516+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:53:21.593580+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:53:21.593612+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920014 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:54:52.078687+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:54:52.079429+0000",
"age": 151.36114999500001,
"duration": 151.36143049099999,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920014
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:54:52.079429+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:54:52.079429+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:54:52.079429+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:54:52.079435+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:54:52.079508+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:54:52.079537+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920015 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:56:22.600873+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:56:22.601181+0000",
"age": 60.839397910999999,
"duration": 60.839725416,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920015
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:56:22.601181+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:56:22.601181+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:56:22.601181+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:56:22.601189+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:56:22.601264+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:56:22.601294+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:8720628 getattr Fs #0x100000005eb 2024-03-12T02:47:12.232891+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T02:47:12.234710+0000",
"age": 4211.2058691359998,
"duration": 4211.2062251939997,
"type_data": {
"flag_point": "failed to rdlock, waiting",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 8720628
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T02:47:12.234710+0000",
"event": "initiated"
},
{
"time": "2024-03-12T02:47:12.234711+0000",
"event": "throttled"
},
{
"time": "2024-03-12T02:47:12.234710+0000",
"event": "header_read"
},
{
"time": "2024-03-12T02:47:12.234721+0000",
"event": "all_read"
},
{
"time": "2024-03-12T02:47:12.234744+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T02:47:12.234800+0000",
"event": "failed to rdlock, waiting"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920011 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:50:20.601151+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:50:20.602598+0000",
"age": 422.837981232,
"duration": 422.83836455099998,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920011
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:50:20.602598+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:50:20.602598+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:50:20.602598+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:50:20.602607+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:50:20.602684+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:50:20.602716+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
},
{
"description": "client_request(client.2784147:14245173 lookup #0x1000000027c/mycluster-node-4 2024-03-12T03:44:54.212496+0000 caller_uid=0, caller_gid=0{0,})",
"initiated_at": "2024-03-12T03:44:54.213086+0000",
"age": 749.22749317299997,
"duration": 749.22790294200001,
"type_data": {
"flag_point": "failed to rdlock, waiting",
"reqid": {
"entity": {
"type": "client",
"num": 2784147
},
"tid": 14245173
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:44:54.213086+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:44:54.213086+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:44:54.213086+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:44:54.213090+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:44:54.213100+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:44:54.213112+0000",
"event": "acquired locks"
},
{
"time": "2024-03-12T03:44:54.213113+0000",
"event": "acquired locks"
},
{
"time": "2024-03-12T03:44:54.213115+0000",
"event": "failed to rdlock, waiting"
}
],
"locks": null
}
},
{
"description": "client_request(client.2824133:9920010 getattr AsLsXsFs #0x100000005eb 2024-03-12T03:48:50.114980+0000 caller_uid=1000, caller_gid=65534{96,65534,})",
"initiated_at": "2024-03-12T03:48:50.116677+0000",
"age": 513.32390260299996,
"duration": 513.32434409200005,
"type_data": {
"flag_point": "joining batch getattr",
"reqid": {
"entity": {
"type": "client",
"num": 2824133
},
"tid": 9920010
},
"op_type": "client_request",
"events": [
{
"time": "2024-03-12T03:48:50.116677+0000",
"event": "initiated"
},
{
"time": "2024-03-12T03:48:50.116677+0000",
"event": "throttled"
},
{
"time": "2024-03-12T03:48:50.116677+0000",
"event": "header_read"
},
{
"time": "2024-03-12T03:48:50.116682+0000",
"event": "all_read"
},
{
"time": "2024-03-12T03:48:50.116748+0000",
"event": "dispatched"
},
{
"time": "2024-03-12T03:48:50.116772+0000",
"event": "joining batch getattr"
}
],
"locks": null
}
}
],
"num_ops": 15
}
The two classes of hanging ops here are:
- `failed to rdlock, waiting`
- `joining batch getattr` * at the time of writing, this returns 0 results in Google * only possibly related issue is: https://tracker.ceph.com/issues/62847 `"mds: blogbench requests stuck (5mds+scrub+snaps-flush)"`
Interestingly, on `node-4` (the node matching the directory which is hanging during listing), the following works:
root@mycluster-node-4 # ls -1U /var/mycluster/files/logs/web-server mycluster-node-6 mycluster-node-5 mycluster-node-4
But it's hanging on the other machines. It also hangs on `node-4` if I don't pass `-1U` to `ls`.
Equally hanging is `stat /var/mycluster/files/logs/web-server/mycluster-node-4`.
The syscall that's hanging in the `stat` is:
statx(AT_FDCWD</root>, "/var/mycluster/files/logs/web-server/mycluster-node-4", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW|AT_NO_AUTOMOUNT, STATX_ALL,
In such situations `systemctl stop mycluster-server` (e.g. on `node-4`) fails to work, the process is stuck in state `D` in `htop`.
If terminated, it can't come back up, supposedly also because it cannot start writing to the log file.
I observed
# ceph osd blacklist ls 10.0.0.6:6801/4168360951 2024-03-12T22:27:44.910773+0000 10.0.0.6:6800/4168360951 2024-03-12T22:27:44.910773+0000 listed 2 entries
but removing those blocks with `ceph osd blocklist rm` did not resolve the issue.
On node-6, after `systemctl stop mycluster-server.service nginx.service`, `umount /var/mycluster/files` hangs for ~1 minute. After that, it seems to succeed, and listing works again:
# ls -lh /var/mycluster/files/logs/web-server total 374G -rw-r--r-- 1 cam nogroup 137G Mar 12 04:17 mycluster-node-4 -rw-r--r-- 1 cam nogroup 118G Mar 12 04:16 mycluster-node-5 -rw-r--r-- 1 cam nogroup 119G Mar 12 04:14 mycluster-node-6
And `dump_ops_in_flight` is now empty.
Ideas:
- Maybe the backup process reading large log file on node-6 while the log-writing process is writing to it from node-4.
Workarounds:
- Generally rebooting the affected Ceph client machine listed in `ceph health detail` fixes the issue immediately.
- `systemctl stop mycluster-server.service nginx.service && umount /var/mycluster/files` and ~1 minute waiting on the problematic machine seems to fix the issue.
Actions