Strange behavior of OSD after an IO error

Strange behavior of OSD after an IO error

[Vincent Godin]

I have a pretty big ceph cluster in jewel 10.2.7 (2 PB) and IO errors
are common. I notice two different behaviors of OSDs when they
encounter an IO error

On JBOD mode, the OSD get the IO error and then abort ... The pgs are
peering on others OSDs, the OSD restart, get it's pgs and everything
is going as usual. Ceph health is OK and the degraded object is not
declared to the cluster. So, if another read is needed on the same
object, the process will restart (abort, perring, restart, peering).
Only a deep-scrub will tell the cluster that one pg have a degraded
object. Then a repair command will repair the pg (only a write
operation can force a disk to reallocate a bad sector). Why the
degraded object is not declared when the first read operation get the
IO error ? If we have multiple IO errors on different OSDs, different
read operations will make them flap till a deep-scrub ... The abort
operation seems to be the current behavior according to the code !!!
How the rbd_client deals with that (IO error or retry till the new
peering of the pg ?)

osd log

IO error and abort

2017-09-27 00:55:52.100678 7faceba7b700 -1
filestore(/var/lib/ceph/osd/ceph-276)
FileStore::read(9.103_head/#9:c086eeb2:::rbd_data.6592c12eb141f2.0000000000058795:head#)
pread error: (5) Input/output error
2017-09-27 00:55:52.128147 7faceba7b700 -1 os/filestore/FileStore.cc:
In function 'virtual int FileStore::read(const coll_t&, const
ghobject_t&, uint64_t, size_t, ceph::bufferlist&, uint32_t, bool) '
thread 7faceba7b700 time 2017-09-27 00:55:52.101208
os/filestore/FileStore.cc: 3016: FAILED assert(0 == "eio on pread")

 ceph version 10.2.6 (656b5b63ed7c43bd014bcafd81b001959d5f089f)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
const*)+0x85) [0x7fad141219f5]
 2: (FileStore::read(coll_t const&, ghobject_t const&, unsigned long,
unsigned long, ceph::buffer::list&, unsigned int, bool)+0xd91)
[0x7fad13df0661]
...

then restart

2017-09-27 00:56:26.859560 7fd53b8b0800  0 osd.276 341224 load_pgs
2017-09-27 00:56:35.881155 7fd53b8b0800  0 osd.276 341224 load_pgs
opened 167 pgs
2017-09-27 00:56:35.881531 7fd53b8b0800  0 osd.276 341224 using 0 op
queue with priority op cut off at 64.
2017-09-27 00:56:35.883165 7fd53b8b0800 -1 osd.276 341224
log_to_monitors {default=true}
2017-09-27 00:56:36.875207 7fd53b8b0800  0 osd.276 341224 done with
init, starting boot process

then deep-scrub (manually)

2017-09-27 10:34:22.481133 7fd50b196700  0 log_channel(cluster) log
[INF] : 9.103 deep-scrub starts
2017-09-27 10:44:05.819995 7fd50b196700 -1 log_channel(cluster) log
[ERR] : 9.103 shard 276: soid
9:c086eeb2:::rbd_data.6592c12eb141f2.0000000000058795:head candidate
had a read error
2017-09-27 10:55:22.272655 7fd508991700 -1 log_channel(cluster) log
[ERR] : 9.103 deep-scrub 0 missing, 1 inconsistent objects
2017-09-27 10:55:22.272663 7fd508991700 -1 log_channel(cluster) log
[ERR] : 9.103 deep-scrub 1 errors

then repair

2017-09-27 11:01:10.648292 7fd50b196700  0 log_channel(cluster) log
[INF] : 9.103 repair starts
2017-09-27 11:08:57.329571 7fd50b196700 -1 log_channel(cluster) log
[ERR] : 9.103 shard 276: soid
9:c086eeb2:::rbd_data.6592c12eb141f2.0000000000058795:head candidate
had a read error
2017-09-27 11:18:42.498541 7fd50b196700 -1 log_channel(cluster) log
[ERR] : 9.103 repair 0 missing, 1 inconsistent objects
2017-09-27 11:18:42.498730 7fd50b196700 -1 log_channel(cluster) log
[ERR] : 9.103 repair 1 errors, 1 fixed


The second behavior is more linked to the hardware and i just want to
give a drawback of using raid0 disk

On our cluster, whe used OSD hosts with JBOD and some olders with RAID0 disks
On RAID0 hosts, we notice than when a IO error occured, the OSD never
catch the information (it only appears in dmesg). On OSD log, we can
only see the thread timing out and blocked requests. The OSD behaviour
then depend of the load. Sometime it survive, sometime not but from a
client side, i think it's an IO error for sure. It's probably linked
to my hardware (SmartArray on HP SL4540) but maybe not ...

Re: Strange behavior of OSD after an IO error

[David Zafman]

The support for this was included in the Luminous release: 
https://github.com/ceph/ceph/pull/14760

David


On 9/27/17 7:37 AM, Vincent Godin wrote:
> I have a pretty big ceph cluster in jewel 10.2.7 (2 PB) and IO errors
> are common. I notice two different behaviors of OSDs when they
> encounter an IO error
>
> On JBOD mode, the OSD get the IO error and then abort ... The pgs are
> peering on others OSDs, the OSD restart, get it's pgs and everything
> is going as usual. Ceph health is OK and the degraded object is not
> declared to the cluster. So, if another read is needed on the same
> object, the process will restart (abort, perring, restart, peering).
> Only a deep-scrub will tell the cluster that one pg have a degraded
> object. Then a repair command will repair the pg (only a write
> operation can force a disk to reallocate a bad sector). Why the
> degraded object is not declared when the first read operation get the
> IO error ? If we have multiple IO errors on different OSDs, different
> read operations will make them flap till a deep-scrub ... The abort
> operation seems to be the current behavior according to the code !!!
> How the rbd_client deals with that (IO error or retry till the new
> peering of the pg ?)
>
> osd log
>
> IO error and abort
>
> 2017-09-27 00:55:52.100678 7faceba7b700 -1
> filestore(/var/lib/ceph/osd/ceph-276)
> FileStore::read(9.103_head/#9:c086eeb2:::rbd_data.6592c12eb141f2.0000000000058795:head#)
> pread error: (5) Input/output error
> 2017-09-27 00:55:52.128147 7faceba7b700 -1 os/filestore/FileStore.cc:
> In function 'virtual int FileStore::read(const coll_t&, const
> ghobject_t&, uint64_t, size_t, ceph::bufferlist&, uint32_t, bool) '
> thread 7faceba7b700 time 2017-09-27 00:55:52.101208
> os/filestore/FileStore.cc: 3016: FAILED assert(0 == "eio on pread")
>
>   ceph version 10.2.6 (656b5b63ed7c43bd014bcafd81b001959d5f089f)
>   1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> const*)+0x85) [0x7fad141219f5]
>   2: (FileStore::read(coll_t const&, ghobject_t const&, unsigned long,
> unsigned long, ceph::buffer::list&, unsigned int, bool)+0xd91)
> [0x7fad13df0661]
> ...
>
> then restart
>
> 2017-09-27 00:56:26.859560 7fd53b8b0800  0 osd.276 341224 load_pgs
> 2017-09-27 00:56:35.881155 7fd53b8b0800  0 osd.276 341224 load_pgs
> opened 167 pgs
> 2017-09-27 00:56:35.881531 7fd53b8b0800  0 osd.276 341224 using 0 op
> queue with priority op cut off at 64.
> 2017-09-27 00:56:35.883165 7fd53b8b0800 -1 osd.276 341224
> log_to_monitors {default=true}
> 2017-09-27 00:56:36.875207 7fd53b8b0800  0 osd.276 341224 done with
> init, starting boot process
>
> then deep-scrub (manually)
>
> 2017-09-27 10:34:22.481133 7fd50b196700  0 log_channel(cluster) log
> [INF] : 9.103 deep-scrub starts
> 2017-09-27 10:44:05.819995 7fd50b196700 -1 log_channel(cluster) log
> [ERR] : 9.103 shard 276: soid
> 9:c086eeb2:::rbd_data.6592c12eb141f2.0000000000058795:head candidate
> had a read error
> 2017-09-27 10:55:22.272655 7fd508991700 -1 log_channel(cluster) log
> [ERR] : 9.103 deep-scrub 0 missing, 1 inconsistent objects
> 2017-09-27 10:55:22.272663 7fd508991700 -1 log_channel(cluster) log
> [ERR] : 9.103 deep-scrub 1 errors
>
> then repair
>
> 2017-09-27 11:01:10.648292 7fd50b196700  0 log_channel(cluster) log
> [INF] : 9.103 repair starts
> 2017-09-27 11:08:57.329571 7fd50b196700 -1 log_channel(cluster) log
> [ERR] : 9.103 shard 276: soid
> 9:c086eeb2:::rbd_data.6592c12eb141f2.0000000000058795:head candidate
> had a read error
> 2017-09-27 11:18:42.498541 7fd50b196700 -1 log_channel(cluster) log
> [ERR] : 9.103 repair 0 missing, 1 inconsistent objects
> 2017-09-27 11:18:42.498730 7fd50b196700 -1 log_channel(cluster) log
> [ERR] : 9.103 repair 1 errors, 1 fixed
>
>
> The second behavior is more linked to the hardware and i just want to
> give a drawback of using raid0 disk
>
> On our cluster, whe used OSD hosts with JBOD and some olders with RAID0 disks
> On RAID0 hosts, we notice than when a IO error occured, the OSD never
> catch the information (it only appears in dmesg). On OSD log, we can
> only see the thread timing out and blocked requests. The OSD behaviour
> then depend of the load. Sometime it survive, sometime not but from a
> client side, i think it's an IO error for sure. It's probably linked
> to my hardware (SmartArray on HP SL4540) but maybe not ...
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html