|
Hi, I have recheck the pattern when slow request are detected. I have an example with following (primary: 411, secondary: 176, 594) On primary slow requests detected: waiting for subops (176, 594) during 16 minutes !!!! 2016-11-17 13:29:27.209754 7f001d414700 0 log_channel(cluster) log [WRN] : 7 slow requests, 7 included below; oldest blocked for > 480.477315 secs 2016-11-17 13:29:27.209777 7f001d414700 0 log_channel(cluster) log [WRN] : slow request 480.477315 seconds old, received at 2016-11-17 13:21:26.732303: osd_op(client.2407558.1:206455044
rbd_data.66ea12ae8944a.00000000001acbbc [set-alloc-hint object_size 4194304 write_size 4194304,write 1257472~368640] 0.61fe279f snapc 3fd=[3fd,3de] ondisk+write e210553) currently waiting for subops from 176,594 So the primary OSD is waiting for subops since 13:21 (13:29 - 480 seconds) 2016-11-17 13:36:33.039691 7efffd8ee700 0 -- 192.168.228.23:6800/694486 >> 192.168.228.7:6819/3611836 pipe(0x13ffd000 sd=33 :17791 s=2 pgs=131 cs=7 l=0 c=0x13251de0).fault,
initiating reconnect 2016-11-17 13:36:39.570692 7efff6784700 0 -- 192.168.228.23:6800/694486 >> 192.168.228.13:6858/2033854 pipe(0x17009000 sd=60 :52188 s=2 pgs=147 cs=7 l=0 c=0x141159c0).fault,
initiating reconnect After this log, it seems the ops are unblocked and I do not have any more the “currently waiting for subops from 176,594” So primary OSD was blocked during 15 minutes in total !!!! On the secondary OSD, I can see the following messages during the same period (but also after and before) secondary: 2016-11-17 13:34:58.125076 7fbcc7517700 0 -- 192.168.228.7:6819/3611836 >> 192.168.228.42:6832/2873873 pipe(0x12d2e000 sd=127 :6819 s=2 pgs=86 cs=5 l=0 c=0xef18c00).fault
with nothing to send, going to sandby In some other example and with some DEBUG messages activated I was also able to see the many of the following messages on secondary OSDs. 2016-11-15 03:53:04.298502 7ff9c434f700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7ff9bdb42700' had timed out after 15 Thomas From: Nick Fisk [mailto:nick@xxxxxxxxxx]
Hi, Yes, I can’t think of anything else at this stage. Could you maybe repost some dump historic op dumps now that you have turned off snapshots.
I wonder if they might reveal anything. From: ceph-users [mailto:ceph-users-bounces@xxxxxxxxxxxxxx]
On Behalf Of Thomas Danan Hi Nick, We have deleted all Snapshots and observed the system for several hours. From what I see this did not help to reduce the blocked ops and IO freeze on Client ceph side. We have also tried to increase a little bit the PGs (by 8 than 128) because this is something we should do and we wanted to see how the cluster was behaving. During recovery, the number of blocked ops and associated duration increased significantly. Also the number of impacted OSDs was much more important.
Don’t really know what to conclude from all of this … Again we have checked Disk / network / and everything seems fine … Thomas From: Nick Fisk [mailto:nick@xxxxxxxxxx]
The snapshot works by using Copy On Write. If you dirty even a 4kb section of a 4MB object in the primary RBD, that entire 4MB object then needs
to be read and then written into the snapshot RBD. From: Thomas Danan [mailto:Thomas.Danan@xxxxxxxxxxxxx]
Hi Nick, Actually I was wondering, is there any difference between Snapshot or simple RBD image ? With simple RBD image when doing a random IO, we are asking Ceph cluster to update one or several 4MB objects no ? So Snapshotting is multiplying the load by 2 but not more, Am I wrong ? Thomas From: ceph-users [mailto:ceph-users-bounces@xxxxxxxxxxxxxx]
On Behalf Of Thomas Danan Hi Nick, Yes our application is doing small Random IO and I did not realize that the snapshotting feature could so much degrade performances in that case. We have just deactivated it and deleted all snapshots. Will notify you if it drastically reduce the blocked ops and consequently the IO freeze on client side. Thanks Thomas From: Nick Fisk [mailto:nick@xxxxxxxxxx]
From: ceph-users [mailto:ceph-users-bounces@xxxxxxxxxxxxxx]
On Behalf Of Thomas Danan Very interesting ... Any idea why optimal tunable would help here ? on our cluster we have 500TB of data, I am a bit concerned about changing it without taking lot of precautions . ... I am curious to know how much time it takes you to change tunable, size of your cluster and observed impacts on client IO ... Yes We do have daily rbd snapshot from 16 different ceph RBD clients. Snapshoting the RBD image is quite immediate while we are seing the issue continuously during the day... Just to point out that when you take a snapshot any writes to the original RBD will mean that the full 4MB object is copied into the snapshot.
If you have a lot of small random IO going on the original RBD this can lead to massive write amplification across the cluster and may cause issues such as what you describe. Also be aware that deleting large snapshots also puts significant strain on the OSD’s as they try and delete hundreds of thousands of objects. Will check all of this tomorrow . .. Thanks again Thomas Sent from my Samsung device
On 11/15/16 14:05, Thomas Danan wrote:
This electronic message contains information from Mycom which may be privileged or confidential. The information is intended to be for the use of the individual(s) or entity named above. If you are not the intended recipient, be aware that any disclosure, copying, distribution or any other use of the contents of this information is prohibited. If you have received this electronic message in error, please notify us by post or telephone (to the numbers or correspondence address above) or by email (at the email address above) immediately. |
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
