Hi guys,
I was wondering if anyone noticed that the deep scrubbing process causes some osd to go down?
I have been keeping an eye on a few remaining stability issues in my test cluster. One of the unsolved issues is the occasional reporting of osd(s) going down and coming back up after about 20-30 seconds. This happens to various osds throughout the cluster. I have a small cluster of just 2 osd servers with 9 osds each.
The common trend that i see week after week is that whenever there is a long deep scrubbing activity on the cluster it triggers one or more osds to go down for a short period of time. After the osd is marked down, it goes back up after about 20 seconds. Obviously there is a repair process that kicks in which causes more load on the cluster. While looking at the logs, i've not seen the osds being marked down when the cluster is not deep scrubbing. It _always_ happens when there is a deep scrub activity. I am seeing the reports of osds going down about 3-4 times a week.
The latest happened just recently with the following log entries:
2015-04-10 19:32:48.330430 mon.0 192.168.168.13:6789/0 3441533 : cluster [INF] pgmap v50849466: 8508 pgs: 8506 active+clean, 2 active+clean+scrubbing+deep; 13213 GB data, 26896 GB used, 23310 GB / 50206 GB avail; 1005 B/s rd, 1005
B/s wr, 0 op/s
2015-04-10 19:32:52.950633 mon.0 192.168.168.13:6789/0 3441542 : cluster [INF] osd.6 192.168.168.200:6816/3738 failed (5 reports from 5 peers after 60.747890 >= grace 46.701350)
2015-04-10 19:32:53.121904 mon.0 192.168.168.13:6789/0 3441544 : cluster [INF] osdmap e74309: 18 osds: 17 up, 18 in
2015-04-10 19:32:53.231730 mon.0 192.168.168.13:6789/0 3441545 : cluster [INF] pgmap v50849467: 8508 pgs: 599 stale+active+clean, 7907 active+clean, 1 stale+active+clean+scrubbing+deep, 1 active+clean+scrubbing+deep; 13213 GB data, 26896 GB used, 23310 GB / 50206 GB avail; 375 B/s rd, 0 op/s
osd.6 logs around the same time are:
2015-04-10 19:16:29.110617 7fad6d5ec700 0 log_channel(default) log [INF] : 5.3d7 deep-scrub ok
2015-04-10 19:27:47.561389 7fad6bde9700 0 log_channel(default) log [INF] : 5.276 deep-scrub ok
2015-04-10 19:31:11.611321 7fad6d5ec700 0 log_channel(default) log [INF] : 5.287 deep-scrub ok
2015-04-10 19:31:53.339881 7fad7ce0b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad735f8700' had timed out after 15
2015-04-10 19:31:53.339887 7fad7ce0b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad745fa700' had timed out after 15
2015-04-10 19:31:53.339890 7fad7ce0b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad705f2700' had timed out after 15
2015-04-10 19:31:53.340050 7fad7e60e700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad735f8700' had timed out after 15
2015-04-10 19:31:53.340053 7fad7e60e700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad745fa700' had timed out after 15
[.....]
2015-04-10 19:32:53.010609 7fad7e60e700 1 heartbeat_map is_healthy 'FileStore::op_tp thread 0x7fad86132700' had timed out after 60
2015-04-10 19:32:53.010611 7fad7e60e700 1 heartbeat_map is_healthy 'FileStore::op_tp thread 0x7fad88937700' had timed out after 60
2015-04-10 19:32:53.111470 7fad66ed2700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6837/4409 pipe(0x2b793b80 sd=179 :6817 s=2 pgs=5 cs=1 l=0 c=0x21e8b420).fault with nothing to send, going to standby
2015-04-10 19:32:53.111496 7fad6329d700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6827/4208 pipe(0x2b793600 sd=172 :6817 s=2 pgs=7 cs=1 l=0 c=0x1791ab00).fault with nothing to send, going to standby
2015-04-10 19:32:53.111463 7fad55bd0700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6822/3910 pipe(0x2cb55dc0 sd=262 :6817 s=2 pgs=8 cs=1 l=0 c=0xe7802c0).fault with nothing to send, going to standby
2015-04-10 19:32:53.121815 7fad6218c700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6807/3575 pipe(0x2cf8e080 sd=294 :6817 s=2 pgs=4 cs=1 l=0 c=0x138669a0).fault with nothing to send, going to standby
2015-04-10 19:32:53.121856 7fad67bdf700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=190 :6817 s=2 pgs=9 cs=1 l=0 c=0x138922c0).fault with nothing to send, going to standby
2015-04-10 19:32:53.123545 7fad651bc700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6801/3053 pipe(0x15e538c0 sd=260 :6817 s=2 pgs=1 cs=1 l=0 c=0x16bf09a0).fault with nothing to send, going to standby
2015-04-10 19:32:53.128729 7fad53eb3700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6832/4257 pipe(0x37dcb80 sd=311 :6817 s=2 pgs=3 cs=1 l=0 c=0x1131f420).fault with nothing to send, going to standby
2015-04-10 19:32:53.132691 7fad53fb4700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6812/3674 pipe(0x37dbdc0 sd=417 :6817 s=2 pgs=3 cs=1 l=0 c=0x1c0badc0).fault with nothing to send, going to standby
2015-04-10 19:32:53.139856 7fad65cc7700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=365 :6817 s=2 pgs=5 cs=1 l=0 c=0xbd1f2c0).fault with nothing to send, going to standby
[ followed by about 500 or so lines which look similar to:]
2015-04-10 19:33:09.021252 7fad65cc7700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=24 :45523 s=2 pgs=1721 cs=3371 l=0 c=0x138922c0).fault, initiating reconnect
2015-04-10 19:33:09.021280 7fad53eb3700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6807/3575 pipe(0x2cf8e080 sd=37 :51859 s=2 pgs=1755 cs=3449 l=0 c=0x138669a0).fault, initiating reconnect
2015-04-10 19:33:09.021443 7fad66ed2700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6812/3674 pipe(0x37dbdc0 sd=18 :46453 s=2 pgs=1782 cs=3489 l=0 c=0x1c0badc0).fault, initiating reconnect
2015-04-10 19:33:09.021702 7fad6218c700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6837/4409 pipe(0x2b793b80 sd=38 :53724 s=2 pgs=1757 cs=3449 l=0 c=0x21e8b420).fault, initiating reconnect
[followed by:]
2015-04-10 19:33:09.021830 7fad8e142700 0 log_channel(default) log [WRN] : 6 slow requests, 6 included below; oldest blocked for > 94.284115 secs
2015-04-10 19:33:09.021834 7fad67bdf700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=29 :50115 s=2 pgs=1717 cs=3395 l=0 c=0xbd1f2c0).fault, initiating reconnect
2015-04-10 19:33:09.021840 7fad8e142700 0 log_channel(default) log [WRN] : slow request 62.902554 seconds old, received at 2015-04-10 19:32:06.119164: osd_op(client.64965167.0:1562644 rbd_data.1f264b2ae8944a.0000000000000400 [set-alloc-hint object_size 4194304 write_size 4194304,write 1155072~4096] 5.f4cd34bb ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 13
2015-04-10 19:33:09.021846 7fad8e142700 0 log_channel(default) log [WRN] : slow request 63.004012 seconds old, received at 2015-04-10 19:32:06.017706: osd_op(client.69637439.0:278581863 rbd_data.265f967a5f7514.0000000000064e2e [set-alloc-hint object_size 4194304 write_size 4194304,write 1040384~4096] 5.bf3d2652 snapc ac=[ac] ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 11
2015-04-10 19:33:09.021851 7fad8e142700 0 log_channel(default) log [WRN] : slow request 94.284115 seconds old, received at 2015-04-10 19:31:34.737603: osd_sub_op(unknown.0.0:0 5.299 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[]) currently started
2015-04-10 19:33:09.021856 7fad8e142700 0 log_channel(default) log [WRN] : slow request 92.669022 seconds old, received at 2015-04-10 19:31:36.352696: osd_op(client.69645050.0:2750479 rbd_data.1b704a8f51a837.000000000000023d [stat,set-alloc-hint object_size 4194304 write_size 4194304,write 1449984~4096] 5.44a257d7 snapc 9cc=[9cc,9c1,9b5,9a9,99d,991,984,972,953,2f8] ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 17
2015-04-10 19:33:09.021861 7fad8e142700 0 log_channel(default) log [WRN] : slow request 76.733358 seconds old, received at 2015-04-10 19:31:52.288360: osd_op(client.64987185.0:26635606 rbd_data.1b652a2ae8944a.0000000000000623 [set-alloc-hint object_size 4194304 write_size 4194304,write 1282048~4096] 5.64d42a36 ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 17
[and finally]
2015-04-10 19:33:09.024361 7fad5c83b700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6832/4257 pipe(0x37dcb80 sd=35 :55060 s=2 pgs=1719 cs=3359 l=0 c=0x1131f420).fault, initiating reconnect
2015-04-10 19:33:09.024418 7fad82616700 0 log_channel(default) log [WRN] : map e74309 wrongly marked me down
2015-04-10 19:33:09.024466 7fad53fb4700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6827/4208 pipe(0x2b793600 sd=33 :36954 s=2 pgs=1731 cs=3403 l=0 c=0x1791ab00).fault, initiating reconnect
2015-04-10 19:33:09.024476 7fad67bdf700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=24 :50133 s=2 pgs=1720 cs=3401 l=0 c=0xbd1f2c0).fault, initiating reconnect
2015-04-10 19:33:09.024553 7fad65cc7700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=29 :45548 s=2 pgs=1725 cs=3379 l=0 c=0x138922c0).fault, initiating reconnect
2015-04-10 19:33:09.024629 7fad53eb3700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6807/3575 pipe(0x2cf8e080 sd=37 :51884 s=2 pgs=1759 cs=3457 l=0 c=0x138669a0).fault, initiating reconnect
2015-04-10 19:33:09.024783 7fad650bb700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=29 :45548 s=1 pgs=1725 cs=3380 l=0 c=0x138922c0).fault
2015-04-10 19:33:09.025056 7fad6218c700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6837/4409 pipe(0x2b793b80 sd=38 :53747 s=2 pgs=1761 cs=3457 l=0 c=0x21e8b420).fault, initiating reconnect
2015-04-10 19:33:09.025062 7fad61580700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=24 :50140 s=4 pgs=1720 cs=3402 l=0 c=0xbd1f2c0).connect got RESETSESSION but no longer connecting
2015-04-10 19:33:16.999741 7fad5f964700 0 -- 192.168.168.200:6846/1003738 >> 192.168.168.200:6837/4266 pipe(0xa711580 sd=257 :6846 s=0 pgs=0 cs=0 l=0 c=0x1afbf840).accept connect_seq 0 vs existing 0 state connecting
2015-04-10 19:33:16.999883 7fad5f863700 0 -- 192.168.168.200:6846/1003738 >> 192.168.168.200:6827/3938 pipe(0x2c48a8c0 sd=260 :6846 s=0 pgs=0 cs=0 l=0 c=0x18a85580).accept connect_seq 0 vs existing 0 state connecting
2015-04-10 19:36:26.247402 7fad6bde9700 0 log_channel(default) log [INF] : 5.299 deep-scrub ok
2015-04-10 19:40:18.577423 7fad725f6700 0 <cls> cls/rgw/cls_rgw.cc:1458: gc_iterate_entries end_key=1_01428691218.577419000
2015-04-10 19:42:22.709291 7fad6edef700 0 log_channel(default) log [INF] : 5.2ae deep-scrub ok
2015-04-10 19:45:51.790224 7fad6bde9700 0 log_channel(default) log [INF] : 5.2bb deep-scrub ok
2015-04-10 19:48:17.022413 7fad5f863700 0 -- 192.168.168.200:6846/1003738 >> 192.168.168.200:6827/3938 pipe(0x2c48a8c0 sd=260 :6846 s=2 pgs=63 cs=1 l=0 c=0x3f81160).fault with nothing to send, going to standby
In the past I have been asked to verify that the networking is working okay. I've ran days and days of various tests and verified that the network is not the cause of the problems. The network is running perfectly well with no errors reported on the interfaces nor any delays. I ran multitude of tcp and udp tests including firing hundreds to thousands connections per second for weeks with 0% packet loss or any other network related errors.
Does anyone have any idea what could be causing the osds to be marked down during the deep scrub activity?
I have enabled the following tuning options in the ceph.conf:
#change to decrease rebuild/recovery priority (should make guest vms more responsive) and decrease scrubbing priority
osd recovery max chunk = 8388608
osd recovery op priority = 1
osd max backfills = 1
osd recovery max active = 1
osd recovery threads = 1
osd_disk_thread_ioprio_priority = 7
osd_disk_thread_ioprio_class = idle
#reporting of down osds
mon osd min down reporters = 6
mon osd report timeout = 1800
mon osd min down reports = 7
osd heartbeat grace = 60
Many thanks for your help
Andrei
I was wondering if anyone noticed that the deep scrubbing process causes some osd to go down?
I have been keeping an eye on a few remaining stability issues in my test cluster. One of the unsolved issues is the occasional reporting of osd(s) going down and coming back up after about 20-30 seconds. This happens to various osds throughout the cluster. I have a small cluster of just 2 osd servers with 9 osds each.
The common trend that i see week after week is that whenever there is a long deep scrubbing activity on the cluster it triggers one or more osds to go down for a short period of time. After the osd is marked down, it goes back up after about 20 seconds. Obviously there is a repair process that kicks in which causes more load on the cluster. While looking at the logs, i've not seen the osds being marked down when the cluster is not deep scrubbing. It _always_ happens when there is a deep scrub activity. I am seeing the reports of osds going down about 3-4 times a week.
The latest happened just recently with the following log entries:
2015-04-10 19:32:48.330430 mon.0 192.168.168.13:6789/0 3441533 : cluster [INF] pgmap v50849466: 8508 pgs: 8506 active+clean, 2 active+clean+scrubbing+deep; 13213 GB data, 26896 GB used, 23310 GB / 50206 GB avail; 1005 B/s rd, 1005
B/s wr, 0 op/s
2015-04-10 19:32:52.950633 mon.0 192.168.168.13:6789/0 3441542 : cluster [INF] osd.6 192.168.168.200:6816/3738 failed (5 reports from 5 peers after 60.747890 >= grace 46.701350)
2015-04-10 19:32:53.121904 mon.0 192.168.168.13:6789/0 3441544 : cluster [INF] osdmap e74309: 18 osds: 17 up, 18 in
2015-04-10 19:32:53.231730 mon.0 192.168.168.13:6789/0 3441545 : cluster [INF] pgmap v50849467: 8508 pgs: 599 stale+active+clean, 7907 active+clean, 1 stale+active+clean+scrubbing+deep, 1 active+clean+scrubbing+deep; 13213 GB data, 26896 GB used, 23310 GB / 50206 GB avail; 375 B/s rd, 0 op/s
osd.6 logs around the same time are:
2015-04-10 19:16:29.110617 7fad6d5ec700 0 log_channel(default) log [INF] : 5.3d7 deep-scrub ok
2015-04-10 19:27:47.561389 7fad6bde9700 0 log_channel(default) log [INF] : 5.276 deep-scrub ok
2015-04-10 19:31:11.611321 7fad6d5ec700 0 log_channel(default) log [INF] : 5.287 deep-scrub ok
2015-04-10 19:31:53.339881 7fad7ce0b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad735f8700' had timed out after 15
2015-04-10 19:31:53.339887 7fad7ce0b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad745fa700' had timed out after 15
2015-04-10 19:31:53.339890 7fad7ce0b700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad705f2700' had timed out after 15
2015-04-10 19:31:53.340050 7fad7e60e700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad735f8700' had timed out after 15
2015-04-10 19:31:53.340053 7fad7e60e700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fad745fa700' had timed out after 15
[.....]
2015-04-10 19:32:53.010609 7fad7e60e700 1 heartbeat_map is_healthy 'FileStore::op_tp thread 0x7fad86132700' had timed out after 60
2015-04-10 19:32:53.010611 7fad7e60e700 1 heartbeat_map is_healthy 'FileStore::op_tp thread 0x7fad88937700' had timed out after 60
2015-04-10 19:32:53.111470 7fad66ed2700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6837/4409 pipe(0x2b793b80 sd=179 :6817 s=2 pgs=5 cs=1 l=0 c=0x21e8b420).fault with nothing to send, going to standby
2015-04-10 19:32:53.111496 7fad6329d700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6827/4208 pipe(0x2b793600 sd=172 :6817 s=2 pgs=7 cs=1 l=0 c=0x1791ab00).fault with nothing to send, going to standby
2015-04-10 19:32:53.111463 7fad55bd0700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6822/3910 pipe(0x2cb55dc0 sd=262 :6817 s=2 pgs=8 cs=1 l=0 c=0xe7802c0).fault with nothing to send, going to standby
2015-04-10 19:32:53.121815 7fad6218c700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6807/3575 pipe(0x2cf8e080 sd=294 :6817 s=2 pgs=4 cs=1 l=0 c=0x138669a0).fault with nothing to send, going to standby
2015-04-10 19:32:53.121856 7fad67bdf700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=190 :6817 s=2 pgs=9 cs=1 l=0 c=0x138922c0).fault with nothing to send, going to standby
2015-04-10 19:32:53.123545 7fad651bc700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6801/3053 pipe(0x15e538c0 sd=260 :6817 s=2 pgs=1 cs=1 l=0 c=0x16bf09a0).fault with nothing to send, going to standby
2015-04-10 19:32:53.128729 7fad53eb3700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6832/4257 pipe(0x37dcb80 sd=311 :6817 s=2 pgs=3 cs=1 l=0 c=0x1131f420).fault with nothing to send, going to standby
2015-04-10 19:32:53.132691 7fad53fb4700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6812/3674 pipe(0x37dbdc0 sd=417 :6817 s=2 pgs=3 cs=1 l=0 c=0x1c0badc0).fault with nothing to send, going to standby
2015-04-10 19:32:53.139856 7fad65cc7700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=365 :6817 s=2 pgs=5 cs=1 l=0 c=0xbd1f2c0).fault with nothing to send, going to standby
[ followed by about 500 or so lines which look similar to:]
2015-04-10 19:33:09.021252 7fad65cc7700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=24 :45523 s=2 pgs=1721 cs=3371 l=0 c=0x138922c0).fault, initiating reconnect
2015-04-10 19:33:09.021280 7fad53eb3700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6807/3575 pipe(0x2cf8e080 sd=37 :51859 s=2 pgs=1755 cs=3449 l=0 c=0x138669a0).fault, initiating reconnect
2015-04-10 19:33:09.021443 7fad66ed2700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6812/3674 pipe(0x37dbdc0 sd=18 :46453 s=2 pgs=1782 cs=3489 l=0 c=0x1c0badc0).fault, initiating reconnect
2015-04-10 19:33:09.021702 7fad6218c700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6837/4409 pipe(0x2b793b80 sd=38 :53724 s=2 pgs=1757 cs=3449 l=0 c=0x21e8b420).fault, initiating reconnect
[followed by:]
2015-04-10 19:33:09.021830 7fad8e142700 0 log_channel(default) log [WRN] : 6 slow requests, 6 included below; oldest blocked for > 94.284115 secs
2015-04-10 19:33:09.021834 7fad67bdf700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=29 :50115 s=2 pgs=1717 cs=3395 l=0 c=0xbd1f2c0).fault, initiating reconnect
2015-04-10 19:33:09.021840 7fad8e142700 0 log_channel(default) log [WRN] : slow request 62.902554 seconds old, received at 2015-04-10 19:32:06.119164: osd_op(client.64965167.0:1562644 rbd_data.1f264b2ae8944a.0000000000000400 [set-alloc-hint object_size 4194304 write_size 4194304,write 1155072~4096] 5.f4cd34bb ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 13
2015-04-10 19:33:09.021846 7fad8e142700 0 log_channel(default) log [WRN] : slow request 63.004012 seconds old, received at 2015-04-10 19:32:06.017706: osd_op(client.69637439.0:278581863 rbd_data.265f967a5f7514.0000000000064e2e [set-alloc-hint object_size 4194304 write_size 4194304,write 1040384~4096] 5.bf3d2652 snapc ac=[ac] ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 11
2015-04-10 19:33:09.021851 7fad8e142700 0 log_channel(default) log [WRN] : slow request 94.284115 seconds old, received at 2015-04-10 19:31:34.737603: osd_sub_op(unknown.0.0:0 5.299 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[]) currently started
2015-04-10 19:33:09.021856 7fad8e142700 0 log_channel(default) log [WRN] : slow request 92.669022 seconds old, received at 2015-04-10 19:31:36.352696: osd_op(client.69645050.0:2750479 rbd_data.1b704a8f51a837.000000000000023d [stat,set-alloc-hint object_size 4194304 write_size 4194304,write 1449984~4096] 5.44a257d7 snapc 9cc=[9cc,9c1,9b5,9a9,99d,991,984,972,953,2f8] ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 17
2015-04-10 19:33:09.021861 7fad8e142700 0 log_channel(default) log [WRN] : slow request 76.733358 seconds old, received at 2015-04-10 19:31:52.288360: osd_op(client.64987185.0:26635606 rbd_data.1b652a2ae8944a.0000000000000623 [set-alloc-hint object_size 4194304 write_size 4194304,write 1282048~4096] 5.64d42a36 ack+ondisk+write+known_if_redirected e74308) currently waiting for subops from 17
[and finally]
2015-04-10 19:33:09.024361 7fad5c83b700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6832/4257 pipe(0x37dcb80 sd=35 :55060 s=2 pgs=1719 cs=3359 l=0 c=0x1131f420).fault, initiating reconnect
2015-04-10 19:33:09.024418 7fad82616700 0 log_channel(default) log [WRN] : map e74309 wrongly marked me down
2015-04-10 19:33:09.024466 7fad53fb4700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6827/4208 pipe(0x2b793600 sd=33 :36954 s=2 pgs=1731 cs=3403 l=0 c=0x1791ab00).fault, initiating reconnect
2015-04-10 19:33:09.024476 7fad67bdf700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=24 :50133 s=2 pgs=1720 cs=3401 l=0 c=0xbd1f2c0).fault, initiating reconnect
2015-04-10 19:33:09.024553 7fad65cc7700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=29 :45548 s=2 pgs=1725 cs=3379 l=0 c=0x138922c0).fault, initiating reconnect
2015-04-10 19:33:09.024629 7fad53eb3700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6807/3575 pipe(0x2cf8e080 sd=37 :51884 s=2 pgs=1759 cs=3457 l=0 c=0x138669a0).fault, initiating reconnect
2015-04-10 19:33:09.024783 7fad650bb700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6842/4442 pipe(0x2b792580 sd=29 :45548 s=1 pgs=1725 cs=3380 l=0 c=0x138922c0).fault
2015-04-10 19:33:09.025056 7fad6218c700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6837/4409 pipe(0x2b793b80 sd=38 :53747 s=2 pgs=1761 cs=3457 l=0 c=0x21e8b420).fault, initiating reconnect
2015-04-10 19:33:09.025062 7fad61580700 0 -- 192.168.168.200:6817/3738 >> 192.168.168.201:6817/3864 pipe(0x2cf8eb80 sd=24 :50140 s=4 pgs=1720 cs=3402 l=0 c=0xbd1f2c0).connect got RESETSESSION but no longer connecting
2015-04-10 19:33:16.999741 7fad5f964700 0 -- 192.168.168.200:6846/1003738 >> 192.168.168.200:6837/4266 pipe(0xa711580 sd=257 :6846 s=0 pgs=0 cs=0 l=0 c=0x1afbf840).accept connect_seq 0 vs existing 0 state connecting
2015-04-10 19:33:16.999883 7fad5f863700 0 -- 192.168.168.200:6846/1003738 >> 192.168.168.200:6827/3938 pipe(0x2c48a8c0 sd=260 :6846 s=0 pgs=0 cs=0 l=0 c=0x18a85580).accept connect_seq 0 vs existing 0 state connecting
2015-04-10 19:36:26.247402 7fad6bde9700 0 log_channel(default) log [INF] : 5.299 deep-scrub ok
2015-04-10 19:40:18.577423 7fad725f6700 0 <cls> cls/rgw/cls_rgw.cc:1458: gc_iterate_entries end_key=1_01428691218.577419000
2015-04-10 19:42:22.709291 7fad6edef700 0 log_channel(default) log [INF] : 5.2ae deep-scrub ok
2015-04-10 19:45:51.790224 7fad6bde9700 0 log_channel(default) log [INF] : 5.2bb deep-scrub ok
2015-04-10 19:48:17.022413 7fad5f863700 0 -- 192.168.168.200:6846/1003738 >> 192.168.168.200:6827/3938 pipe(0x2c48a8c0 sd=260 :6846 s=2 pgs=63 cs=1 l=0 c=0x3f81160).fault with nothing to send, going to standby
In the past I have been asked to verify that the networking is working okay. I've ran days and days of various tests and verified that the network is not the cause of the problems. The network is running perfectly well with no errors reported on the interfaces nor any delays. I ran multitude of tcp and udp tests including firing hundreds to thousands connections per second for weeks with 0% packet loss or any other network related errors.
Does anyone have any idea what could be causing the osds to be marked down during the deep scrub activity?
I have enabled the following tuning options in the ceph.conf:
#change to decrease rebuild/recovery priority (should make guest vms more responsive) and decrease scrubbing priority
osd recovery max chunk = 8388608
osd recovery op priority = 1
osd max backfills = 1
osd recovery max active = 1
osd recovery threads = 1
osd_disk_thread_ioprio_priority = 7
osd_disk_thread_ioprio_class = idle
#reporting of down osds
mon osd min down reporters = 6
mon osd report timeout = 1800
mon osd min down reports = 7
osd heartbeat grace = 60
Many thanks for your help
Andrei
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
