Ceph » RADOS

The only OSDs involved are osd.6 and osd.0.

Slow heartbeat ping on front interface from osd.6 to osd.0 2237.999 msec

It was a spike during a 1 minute average which then got averaged into 5 minute and 15 minute results.

First noticed:
2019-09-09T22:25:11.341+0000 7ff29e65e700 20 mgr.server operator() health checks:

Last seen:
2019-09-09T22:26:13.363+0000 7ff29e65e700 20 mgr.server operator() health checks:

Strange short backup of pings that resolved at 2019-09-09T22:24:33 which could have created a 2 second average as follows:
Approx long pings 12, 9, 7, 7, 3 (total 38 seconds / 16 samples = 2.375)
2019-09-09T22:24:33.523+0000 11486700 25 osd.6 35 handle_osd_ping got all replies from osd.0 , erase pending ping(sent at 2019-09-09T22:24:21.846702+0000) and older pending ping(s)
2019-09-09T22:24:33.542+0000 11486700 25 osd.6 35 handle_osd_ping got all replies from osd.0 , erase pending ping(sent at 2019-09-09T22:24:24.862372+0000) and older pending ping(s)
2019-09-09T22:24:33.547+0000 11486700 25 osd.6 35 handle_osd_ping got all replies from osd.0 , erase pending ping(sent at 2019-09-09T22:24:26.163955+0000) and older pending ping(s)
2019-09-09T22:24:33.550+0000 11486700 25 osd.6 35 handle_osd_ping got all replies from osd.0 , erase pending ping(sent at 2019-09-09T22:24:26.789567+0000) and older pending ping(s)
2019-09-09T22:24:33.553+0000 11486700 25 osd.6 35 handle_osd_ping got all replies from osd.0 , erase pending ping(sent at 2019-09-09T22:24:30.929649+0000) and older pending ping(s)

This may show that a slow reconnect occurring after 2019-09-09T22:24:21 caused ping responses from osd.0 to be delayed to osd.6.
2019-09-09T22:24:21.637+0000 2e758700 10 osd.6 27 heartbeat_reset failed hb con 0x259c4670 for osd.0, reopening

Reproduced several times with debug_ms = 20

http://pulpito.ceph.com/dzafman-2019-09-11_15:28:37-rados-wip-zafman-testing3-distro-basic-smithi/

I have been looking at the single job here: http://pulpito.ceph.com/dzafman-2019-09-11_15:06:05-rados-wip-zafman-testing3-distro-basic-smithi/

I confused the front and back interface with a retransmit. The ports are the 2 interfaces.

At the ping receiving end osd.6 replied but had to retransmit

2019-09-11T22:37:02.301+0000 11485700 5 --2- v2:172.21.15.13:6815/12578 >> 172.21.15.118:0/13469 conn(0x23e34b10 0x146fb970 crc :-1 s=READY pgs=2 cs=0 l=1 rx=0 tx=0).write_message sending message m=0x1c9d1e90 seq=20 osd_ping(ping_reply e26 up_from 15 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 79.789461809s delta_ub -1.094885368s) v5

6 seconds later from new port 6814/12578 instead of 6815/12578

2019-09-11T22:37:08.960+0000 12487700 5 --2- v2:172.21.15.13:6814/12578 >> 172.21.15.118:0/13469 conn(0x146fe210 0x23e377c0 crc :-1 s=READY pgs=2 cs=0 l=1 rx=0 tx=0).write_message sending message m=0xed23000 seq=20 osd_ping(ping_reply e31 up_from 15 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 85.752623239s delta_ub 4.868276062s) v5

This shows the front and back interface. I don't know which is which, but it already sent the second interface maybe 1/2 second after the first. Then didn't get a reply for 6 seconds.

front/back interface 1

2019-09-11T22:37:02.135+0000 12487700  5 --2- 172.21.15.118:0/13469 >> v2:172.21.15.13:6815/12578 conn(0x27cdd130 0x27cdf820 crc :-1 s=READY pgs=6 cs=0 l=1 rx=0 tx=0).write_message sending message m=0x208d4d20 seq=20 osd_ping(ping e26 up_from 14 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 80.884347177s delta_ub 1.278888951s) v5

2019-09-11T22:37:02.503+0000 12487700  5 --2- 172.21.15.118:0/13469 >> v2:172.21.15.13:6815/12578 conn(0x27cdd130 0x27cdf820 crc :-1 s=READ_MESSAGE_COMPLETE pgs=6 cs=0 l=1 rx=0 tx=0).handle_message received message m=0x20a48f20 seq=20 from=osd.6 type=70 osd_ping(ping_reply e26 up_from 15 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 79.789461809s delta_ub -1.094885368s) v5
2019-09-11T22:37:02.504+0000 12487700  1 -- 172.21.15.118:0/13469 <== osd.6 v2:172.21.15.13:6815/12578 20 ==== osd_ping(ping_reply e26 up_from 15 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 79.789461809s delta_ub -1.094885368s) v5 ==== 2033+0+0 (crc 0 0 0) 0x20a48f20 con 0x27cdd130

front/back interface 2

2019-09-11T22:37:03.145+0000 11485700  5 --2- 172.21.15.118:0/13469 >> v2:172.21.15.13:6814/12578 conn(0x27ce2ee0 0x27ce55d0 crc :-1 s=READY pgs=6 cs=0 l=1 rx=0 tx=0).write_message sending message m=0x20432e00 seq=20 osd_ping(ping e26 up_from 14 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 80.884347177s delta_ub 1.278888951s) v5

2019-09-11T22:37:09.988+0000 11485700  5 --2- 172.21.15.118:0/13469 >> v2:172.21.15.13:6814/12578 conn(0x27ce2ee0 0x27ce55d0 crc :-1 s=READ_MESSAGE_COMPLETE pgs=6 cs=0 l=1 rx=0 tx=0).handle_message received message m=0x209fa080 seq=20 from=osd.6 type=70 osd_ping(ping_reply e31 up_from 15 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 85.752623239s delta_ub 4.868276062s) v5
2019-09-11T22:37:09.988+0000 11485700  1 -- 172.21.15.118:0/13469 <== osd.6 v2:172.21.15.13:6814/12578 20 ==== osd_ping(ping_reply e31 up_from 15 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 85.752623239s delta_ub 4.868276062s) v5 ==== 2033+0+0 (crc 0 0 0) 0x209fa080 con 0x27ce2ee0

This shows the send on osd.0 and receive at osd.6.

osd.0: 2019-09-11T22:37:02.135+0000 12487700  5 --2- 172.21.15.118:0/13469 >> v2:172.21.15.13:6815/12578 conn(0x27cdd130 0x27cdf820 crc :-1 s=READY pgs=6 cs=0 l=1 rx=0 tx=0).write_message sending message m=0x208d4d20 seq=20 osd_ping(ping e26 up_from 14 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 80.884347177s delta_ub 1.278888951s) v5
osd.6: 2019-09-11T22:37:02.235+0000 11485700  5 --2- v2:172.21.15.13:6815/12578 >> 172.21.15.118:0/13469 conn(0x23e34b10 0x146fb970 crc :-1 s=READ_MESSAGE_COMPLETE pgs=2 cs=0 l=1 rx=0 tx=0).handle_message received message m=0x1c9dc920 seq=20 from=osd.0 type=70 osd_ping(ping e26 up_from 14 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 80.884347177s delta_ub 1.278888951s) v5

osd.0: 2019-09-11T22:37:03.145+0000 11485700  5 --2- 172.21.15.118:0/13469 >> v2:172.21.15.13:6814/12578 conn(0x27ce2ee0 0x27ce55d0 crc :-1 s=READY pgs=6 cs=0 l=1 rx=0 tx=0).write_message sending message m=0x20432e00 seq=20 osd_ping(ping e26 up_from 14 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 80.884347177s delta_ub 1.278888951s) v5
osd.6: 2019-09-11T22:37:08.198+0000 12487700  5 --2- v2:172.21.15.13:6814/12578 >> 172.21.15.118:0/13469 conn(0x146fe210 0x23e377c0 crc :-1 s=READ_MESSAGE_COMPLETE pgs=2 cs=0 l=1 rx=0 tx=0).handle_message received message m=0x23b6ffe0 seq=20 from=osd.0 type=70 osd_ping(ping e26 up_from 14 ping_stamp 2019-09-11T22:37:02.086496+0000/80.884347177s send_stamp 80.884347177s delta_ub 1.278888951s) v5

David Zafman wrote:

This is already included in back porting of https://tracker.ceph.com/issues/40640

Thanks, David.