[ceph-users] Random slow requests without any load
Hello, I do have a very strange situation: in a almost-new ceph cluster, I do have random requests blocked, leading to timeouts. Example error from logs: > [WRN] Health check failed: 8 slow requests are blocked > 32 sec. Implicated osds 12 (REQUEST_SLOW) >7fd8bb0bd700 0 log_channel(cluster) log [WRN] : slow request 30.796124 seconds old, received at 2019-07-04 16:18:54.53038 8: osd_op(client.2829606.0:103 3.135 3:ac9abb76:::rbd_data.2b00ee6b8b4567.:head [set-alloc-hint object_size 4194304 write_size 419430 4,write 0~4096] snapc 0=[] ondisk+write+known_if_redirected e294) currently op_applied This happens totally randomly. I'm not able to reproduce it: I never had the issue with benchmarks, I do have it occasionally when I start or stop of VM (it's a proxmox deployment and ceph / rdb is used as storage for VMs) or when I use the VM. This is a example request stuck (with dump_ops_in_flight): > { "description": "osd_op(client.2829606.0:103 3.135 3:ac9abb76:::rbd_data.2b00ee6b8b4567.:head [set-alloc-hint object_size 4194304 write_size 4194304,write 0~4096] snapc 0=[] ondisk+write+known_if_redirected e294)", "initiated_at": "2019-07-04 16:18:54.530388", "age": 196.315782, "duration": 196.315797, "type_data": { "flag_point": "waiting for sub ops", "client_info": { "client": "client.2829606", "client_addr": "10.3.5.40:0/444048627", "tid": 103 }, "events": [ { "time": "2019-07-04 16:18:54.530388", "event": "initiated" }, { "time": "2019-07-04 16:18:54.530429", "event": "queued_for_pg" }, { "time": "2019-07-04 16:18:54.530437", "event": "reached_pg" }, { "time": "2019-07-04 16:18:54.530455", "event": "started" }, { "time": "2019-07-04 16:18:54.530507", "event": "waiting for subops from 8" }, { "time": "2019-07-04 16:18:54.531020", "event": "op_commit" }, { "time": "2019-07-04 16:18:54.531024", "event": "op_applied" } ] } } Since he seems to be waiting on osd 8, I tried to dump_ops_in_flight and to dump_historic_ops but there was nothing (witch is quite strange no ?). The cluster has no load in general: There is no i/o errors, no requests on disks (iostat is at 99.+% idle), no cpu usage, no ethernet usage. The OSD or the OSD waited on in subops are random. If I restart the target osd, the request is unstuck. There is nothing else in logs / dmesg except this: > 7fd8bf8f1700 0 -- 10.3.5.41:6809/16241 >> 10.3.5.42:6813/1015314 conn(0x555ddb9db800 :6809 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_msg accept connect_seq 39 vs existing csq=39 existing_state=STATE_CONNECTING But not around errors, I'm not sure it's just debuging output. On the network side, I had jumbo frames but disabling them changed nothing. Just in case, I do have a LACP bond to two switches (mlag/vtl), but I don't see any network issues (heavy pings are totally fine, even for a long time). I kind of suspect the tcp connection of the OSD who is stuck / in a bad state for some reason, but I'm not sure what and how I can debug this. My ceph version is: 12.2.12 (39cfebf25a7011204a9876d2950e4b28aba66d11) luminous (stable) Do you have any idea/pointer/help on what is the issue / what can I try to debug / check ? Thanks a lot and have a nice day! -- Maximilien Cuony ___ ceph-users mailing list ceph-users@lists.ceph.com http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
Re: [ceph-users] Random slow requests without any load
Hello, Just a quick update about this if somebody else get the same issue: The problem was with the firewall. Port range and established connection are allowed, but for some reasons it seems the tracking of connections are lost, leading to a strange state where one machine refuse data (RST are replied) and the sender never get the RST packed (even with 'related' packets allowed). There was a similar post on this list in February ("Ceph and TCP States") where lossing of connections in conntrack created issues, but the fix, net.netfilter.nf_conntrack_tcp_be_liberal=1 did not improve that particular case. As a workaround, we installed lighter rules for the firewall (allowing all packets from machines inside the cluster by default) and that "fixed" the issue :) Have a nice day, Le 7/4/19 à 6:14 PM, Maximilien Cuony a écrit : Hello, I do have a very strange situation: in a almost-new ceph cluster, I do have random requests blocked, leading to timeouts. Example error from logs: > [WRN] Health check failed: 8 slow requests are blocked > 32 sec. Implicated osds 12 (REQUEST_SLOW) >7fd8bb0bd700 0 log_channel(cluster) log [WRN] : slow request 30.796124 seconds old, received at 2019-07-04 16:18:54.53038 8: osd_op(client.2829606.0:103 3.135 3:ac9abb76:::rbd_data.2b00ee6b8b4567.:head [set-alloc-hint object_size 4194304 write_size 419430 4,write 0~4096] snapc 0=[] ondisk+write+known_if_redirected e294) currently op_applied This happens totally randomly. I'm not able to reproduce it: I never had the issue with benchmarks, I do have it occasionally when I start or stop of VM (it's a proxmox deployment and ceph / rdb is used as storage for VMs) or when I use the VM. This is a example request stuck (with dump_ops_in_flight): > { "description": "osd_op(client.2829606.0:103 3.135 3:ac9abb76:::rbd_data.2b00ee6b8b4567.:head [set-alloc-hint object_size 4194304 write_size 4194304,write 0~4096] snapc 0=[] ondisk+write+known_if_redirected e294)", "initiated_at": "2019-07-04 16:18:54.530388", "age": 196.315782, "duration": 196.315797, "type_data": { "flag_point": "waiting for sub ops", "client_info": { "client": "client.2829606", "client_addr": "10.3.5.40:0/444048627", "tid": 103 }, "events": [ { "time": "2019-07-04 16:18:54.530388", "event": "initiated" }, { "time": "2019-07-04 16:18:54.530429", "event": "queued_for_pg" }, { "time": "2019-07-04 16:18:54.530437", "event": "reached_pg" }, { "time": "2019-07-04 16:18:54.530455", "event": "started" }, { "time": "2019-07-04 16:18:54.530507", "event": "waiting for subops from 8" }, { "time": "2019-07-04 16:18:54.531020", "event": "op_commit" }, { "time": "2019-07-04 16:18:54.531024", "event": "op_applied" } ] } } Since he seems to be waiting on osd 8, I tried to dump_ops_in_flight and to dump_historic_ops but there was nothing (witch is quite strange no ?). The cluster has no load in general: There is no i/o errors, no requests on disks (iostat is at 99.+% idle), no cpu usage, no ethernet usage. The OSD or the OSD waited on in subops are random. If I restart the target osd, the request is unstuck. There is nothing else in logs / dmesg except this: > 7fd8bf8f1700 0 -- 10.3.5.41:6809/16241 >> 10.3.5.42:6813/1015314 conn(0x555ddb9db800 :6809 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_msg accept connect_seq 39 vs existing csq=39 existing_state=STATE_CONNECTING But not around errors, I'm not sure it's just debuging output. On the network side, I had jumbo frames but disabling them changed nothing. Just in case, I do have a LACP bond to two switches (mlag/vtl), but I don't see any network issues (heavy pings are totally fine, even for a long time). I kind of suspect the tcp connection of the OSD who is stuck / in a bad state for some reason, but I'm not sure what and how I can debug this. My ceph version is: 12.2.12 (39cfebf25a7011204a9876d2950e4b28aba66d11) luminous (stable) Do you have any idea/pointer/help on what is the issue / what can I try to debug / check ? Thanks a lot and have a nice day! ___ ceph-users mailing list ceph-users@lists.ceph.com http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
Re: [ceph-users] how to debug slow requests
Hello, Your issue look like mine - I had op stuck with the same status: check "Random slow requests without any load" on this month list archive. Bests, Le 7/20/19 à 6:06 PM, Wei Zhao a écrit : Hi ceph users: I was doing write benchmark, and found some io will be blocked for a very long time. The following log is one op , it seems to wait for replica to finish. My ceph version is 12.2.4, and the pool is 3+2 EC . Does anyone give me some adives about how I sould debug next ? { "ops": [ { "description": "osd_op(client.17985.0:670679 39.18 39:1a63fc5c:::benchmark_data_SH-IDC1-10-5-37-174_2917453_object670678:head [set-alloc-hint object_size 1048576 write_size 1048576,write 0~1048576] snapc 0=[] ondisk+write+known_if_redirected e1135)", "initiated_at": "2019-07-20 23:13:18.725466", "age": 329.248875, "duration": 329.248901, "type_data": { "flag_point": "waiting for sub ops", "client_info": { "client": "client.17985", "client_addr": "10.5.137.174:0/1544466091", "tid": 670679 }, "events": [ { "time": "2019-07-20 23:13:18.725466", "event": "initiated" }, { "time": "2019-07-20 23:13:18.726585", "event": "queued_for_pg" }, { "time": "2019-07-20 23:13:18.726606", "event": "reached_pg" }, { "time": "2019-07-20 23:13:18.726752", "event": "started" }, { "time": "2019-07-20 23:13:18.726842", "event": "waiting for subops from 4" }, { "time": "2019-07-20 23:13:18.743134", "event": "op_commit" }, { "time": "2019-07-20 23:13:18.743137", "event": "op_applied" } ] } }, ___ ceph-users mailing list ceph-users@lists.ceph.com http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com -- Maximilien Cuony ___ ceph-users mailing list ceph-users@lists.ceph.com http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com