Re: REQUEST_SLOW across many OSDs at the same time

[Massimo Sgaravatto <massimo.sgaravatto@xxxxxxxxx>]

On Mon, Feb 25, 2019 at 9:26 PM mart.v <mart.v@xxxxxxxxx> wrote:

- As far as I understand the reported 'implicated osds' are only the primary ones. In the log of the osds you should find also the relevant pg number, and with this information you can get all the involved OSDs. This might be useful e.g. to see if a specific OSD node is always involved. This was my case (a the problem was with the patch cable connecting the node)

I can see right from the REQUEST_SLOW error log lines implicated OSDs and therefore I can tell which nodes are involved. It is indeed on all nodes in a cluster, no exception. So it cannot be linked to one specific node.

I am afraid I was not clear enough. Suppose that ceph health detail reports a slow request involving osd.14

In osd.14 log I see this line:

2019-02-24 16:58:39.475740 7fe25a84d700  0 log_channel(cluster) log [WRN] : slow request 30.328572 seconds old, received at 2019-02-24 16:58:09.147037: osd_op(client.148580771.0:476351313 8.1d6 8:6ba6a916:::rbd_data.ba32e7238e1f29.00000000000004b3:head [set-alloc-hint object_size 4194304 write_size 4194304,write 3776512~4096] snapc 0=[] ondisk+write+known_if_redirected e1242718) currently op_applied

Here the pg_num is 8.1d6

# ceph pg map 8.1d6

osdmap e1247126 pg 8.1d6 (8.1d6) -> up [14,38,24] acting [14,38,24]

[root@ceph-osd-02 ceph]# ceph pg map 8.1d6

So the problem is not necessarily is osd.14. It could also in osd.38 or osd.24, or in the relevant hosts

 

- You can use the "ceph daemon osd.x dump_historic_ops" command to debug some of these slow requests (to see which events take much time)

2019-02-25 17:40:49.550303 > initiated

2019-02-25 17:40:49.550338 > queued_for_pg

2019-02-25 17:40:49.550924 > reached_pg

2019-02-25 17:40:49.550950 > started

2019-02-25 17:40:49.550989 > waiting for subops from 21,35

2019-02-25 17:40:49.552316 > op_commit

2019-02-25 17:40:49.552320 > op_applied

2019-02-25 17:40:49.553216 > sub_op_commit_rec from 21

2019-02-25 17:41:18.416662 > sub_op_commit_rec from 35

2019-02-25 17:41:18.416708 > commit_sent

2019-02-25 17:41:18.416726 > done 

I'm not sure how to read this output  - the time is start or finish? Does it mean that it is waiting for OSD 21 or 35? I tried to examine few different OSDs for dump_historic_ops, they all seems to wait on other OSDs. But there is no similarity (OSD numbers are different).

As far as I understand In this case most of the time was waiting for an answer from osd.35 

PS: You might also want to have a look at the thread "Debugging 'slow requests'" in this mailing list where Brad Hubbard (thanks again !) helped me debugging a 'slow request' problem 

Cheers, Massimo

Best,

Martin

_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com