i left a disk out at boot , why no resilver?

[SMnasMAN]

i’m still testing/ Learning/playing with free Nas for the next month or two, so I don’t have any real data on it (other than a lot of test data like large /dev/urandom files and some test ISOs i copy over)

I had shut down my system, and i accidentally slid out one disk of a 12 disk raid Z1. when I booted the system up the pool ofcourse showed up as degraded.
about five or 10 minutes after seeing this, I went and re-inserted that disk. and the pool went to HEALTHY. (?)

shouldn’t the pool have automatically started re-silvering, or require intervention on my part to replace (or remove and re-add) that one disk as the pool had already gone degraded?

it’s worth mentioning that during this DEGRADED time , the pool was not accessed or used in anyway (ie no user r / w IO) during those 10 or 15 minutes.

i’m asking to learn/understand- but it would seem to me that during the time the pool was degraded that one disk should now be out of sync , thus the pool should auto re-silver or at least *not* be marked as healthy . ( or is it because ZFS can tell that no I/O was performed while the disk was missing, thus nothing is out of sync?).

for example, what if (at system startup), this had been a single disk that was on the fritz and couldn’t power/spin up for five or 10 minutes, and then was able to spin up, but during that 10 minutes I had been reading and writing data to the pool .

( or are scenarios like this why it’s important to schedule scrubs on a frequent basis?)


Thanks

 

[MikeyG]

I have noticed something similar, even on pools with a lot of data. What I've assumed is that when it detects the missing disk that was part of the pool, it does a "catch up re-silver" where whatever data is not in sync since it was removed is written. I've seen the disk have a heavy write load for a few seconds, then stop and the pool go healthy without requiring the hours long re-silver process. I don't know how it would be tracking that exactly though. Similar to how during a scrub only the data written is read back, and not every sector of every disk. Maybe this part of having a COW file system? Would be curious to know a more official answer to this though.

 

[SMnasMAN]

thanks for reply. i def wouldn’t *assume* anything , so i agree a official answer would be great.

I certainly didn’t see anything in the logs related to this (after I inserted the missing drive) , nor anything when i checked zpool staus -v. , and I didn’t notice any disk IO on the disk LED beyond 1 or 2 sec (if that).

i will test this more later tonight and update, hopefully someone else has some more solid/official info in the mean time.

tks

 

[Johnnie Black]

If you look at the output of zpool status you should see a line similar to:

resilvered a few bytes in so much time with 0 errors

 

[SMnasMAN]

so ive tested this again, this time with consant writting to the pool from (12x disk rdz1):
dd if=/dev/urandom of=blah.dd bs=8M count=100k

1- i pulled one of the disks, FN showed DEGRADED, (and the writes as seen by disk LEDs resumed)
about 2 minutes later i pushed the disk back in, the pool went to HEALTHY (and the writes as seen by disk LEDs resumed)

about 15minutes later i did the exact same thing, with the exact same disk, same scenario.
here are the log messages

Code:

Jan  3 23:00:47 freenas         (da12:mps0:0:5:0): WRITE(10). CDB: 2a 00 f0 88 4f f8 00 00 18 00 length 12288 SMID 577 terminated ioc 804b loginfo 31110d00 scsi 0 state c xfer 0
Jan  3 23:00:47 freenas (da12:mps0:0:5:0): WRITE(10). CDB: 2a 00 f0 88 4f f8 00 00 18 00
Jan  3 23:00:47 freenas (da12:mps0:0:5:0): CAM status: CCB request completed with an error
Jan  3 23:00:47 freenas (da12:mps0:0:5:0): Retrying command
Jan  3 23:00:48 freenas mps0: mpssas_prepare_remove: Sending reset for target ID 5
Jan  3 23:00:48 freenas da12 at mps0 bus 0 scbus2 target 5 lun 0
Jan  3 23:00:48 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173
Jan  3 23:00:48 freenas mps0: da12: <ATA Hitachi HUS72404 A5F0> s/n PCHVHM1B             detached
Jan  3 23:00:48 freenas (da12:mps0:0:5:0): WRITE(10). CDB: 2a 00 f0 88 4f f8 00 00 18 00
Jan  3 23:00:48 freenas Unfreezing devq for target ID 5
Jan  3 23:00:48 freenas (da12:mps0:0:5:0): CAM status: CCB request aborted by the host
Jan  3 23:00:48 freenas (da12:mps0:0:5:0): Error 5, Periph was invalidated
Jan  3 23:00:48 freenas GEOM_MIRROR: Device swap1: provider da12p1 disconnected.
Jan  3 23:00:48 freenas (da12:mps0:0:5:0): Periph destroyed
Jan  3 23:00:50 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173

Jan  3 23:02:51 freenas mps0: SAS Address for SATA device = 737e5c1790c3dcb4
Jan  3 23:02:51 freenas mps0: SAS Address from SATA device = 737e5c1790c3dcb4
Jan  3 23:02:51 freenas da12 at mps0 bus 0 scbus2 target 5 lun 0
Jan  3 23:02:51 freenas da12: <ATA Hitachi HUS72404 A5F0> Fixed Direct Access SPC-4 SCSI device
Jan  3 23:02:51 freenas da12: Serial Number PCHVHM1B
Jan  3 23:02:51 freenas da12: 600.000MB/s transfers
Jan  3 23:02:51 freenas da12: Command Queueing enabled
Jan  3 23:02:51 freenas da12: 3815447MB (7814037168 512 byte sectors)
Jan  3 23:02:51 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=14288572928810984592
Jan  3 23:02:51 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=7101654273334322128
Jan  3 23:02:51 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=13733655008980643034
Jan  3 23:02:51 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=14185762264907364071
Jan  3 23:02:51 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=18243972532056628131
Jan  3 23:02:51 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=5831967058495583272
Jan  3 23:02:52 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=12522633057879393081
Jan  3 23:02:52 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173
Jan  3 23:02:52 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=18150942564094537261
Jan  3 23:02:52 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=4184126336002118391
Jan  3 23:02:52 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=4262714046301300370
Jan  3 23:02:52 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=14754857558554933470


Jan  3 23:13:43 freenas         (da12:mps0:0:5:0): WRITE(10). CDB: 2a 00 f1 4e fb 70 00 00 18 00 length 12288 SMID 485 terminated ioc 804b loginfo 31110d00 scsi 0 state c xfer 0
Jan  3 23:13:43 freenas (da12:mps0:0:5:0): WRITE(10). CDB: 2a 00 f1 4e fb 70 00 00 18 00
Jan  3 23:13:43 freenas (da12:mps0:0:5:0): CAM status: CCB request completed with an error
Jan  3 23:13:43 freenas (da12:mps0:0:5:0): Retrying command
Jan  3 23:13:43 freenas mps0: mpssas_prepare_remove: Sending reset for target ID 5
Jan  3 23:13:43 freenas da12 at mps0 bus 0 scbus2 target 5 lun 0
Jan  3 23:13:43 freenas mps0: da12: <ATA Hitachi HUS72404 A5F0> s/n PCHVHM1B             detached
Jan  3 23:13:43 freenas Unfreezing devq for target ID 5
Jan  3 23:13:43 freenas (da12:mps0:0:5:0): WRITE(10). CDB: 2a 00 f1 4e fb 70 00 00 18 00
Jan  3 23:13:43 freenas (da12:mps0:0:5:0): CAM status: CCB request aborted by the host
Jan  3 23:13:43 freenas (da12:mps0:0:5:0): Error 5, Periph was invalidated
Jan  3 23:13:43 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173
Jan  3 23:13:43 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173
Jan  3 23:15:44 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173
Jan  3 23:15:44 freenas GEOM_ELI: Device mirror/swap1.eli destroyed.
Jan  3 23:15:45 freenas (da12:mps0:0:5:0): Periph destroyed
Jan  3 23:15:45 freenas GEOM_MIRROR: Device swap1: provider destroyed.
Jan  3 23:15:45 freenas GEOM_MIRROR: Device swap1 destroyed.
Jan  3 23:15:46 freenas GEOM_MIRROR: Device mirror/swap1 launched (2/2).
Jan  3 23:15:47 freenas GEOM_ELI: Device mirror/swap1.eli created.
Jan  3 23:15:47 freenas GEOM_ELI: Encryption: AES-XTS 128
Jan  3 23:15:47 freenas GEOM_ELI:     Crypto: hardware
Jan  3 23:19:58 freenas mps0: SAS Address for SATA device = 737e5c1790c3dcb4
Jan  3 23:19:58 freenas mps0: SAS Address from SATA device = 737e5c1790c3dcb4
Jan  3 23:19:58 freenas da12 at mps0 bus 0 scbus2 target 5 lun 0
Jan  3 23:19:58 freenas da12: <ATA Hitachi HUS72404 A5F0> Fixed Direct Access SPC-4 SCSI device
Jan  3 23:19:58 freenas da12: Serial Number PCHVHM1B
Jan  3 23:19:58 freenas da12: 600.000MB/s transfers
Jan  3 23:19:58 freenas da12: Command Queueing enabled
Jan  3 23:19:58 freenas da12: 3815447MB (7814037168 512 byte sectors)
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=14288572928810984592
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=7101654273334322128
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=13733655008980643034
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=14185762264907364071
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=18243972532056628131
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=5831967058495583272
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=12522633057879393081
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=15242145880798891173
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=18150942564094537261
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=4184126336002118391
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=4262714046301300370
Jan  3 23:19:59 freenas ZFS: vdev state changed, pool_guid=16709539263909507437 vdev_guid=14754857558554933470
root@freenas:~ #

So to make things more interesting, i made a new (different/separate from pool above) 3 disk raidz1 (with 3x ssds as all its all i had free in the system).
THIS TIME i want to test remove DISK A, reinsert it, (so back to healthy, BUT IT DID AUTO DO A RESILVER this time, and completed in 10seconds AND ONLY for 680mb , which makes sense as the amount of urandom data DD had written while DISK A was gone)

I then remove DISK B , reinsert it (i think this should break the pool if no resilvers are done?) -- it again did a AUTO re-silver for 2.96gb (as i had left diskB pulled for a bit longer, but not much)

DISK A pull/reconnect:

pool: testSSD
state: DEGRADED
status: One or more devices has been removed by the administrator.
Sufficient replicas exist for the pool to continue functioning in a
degraded state.
action: Online the device using 'zpool online' or replace the device with
'zpool replace'.
scan: resilvered 680M in 0 days 00:00:10 with 0 errors on Fri Jan 4 01:55:48 2019
config:

DISK B pull/reconnect:
pool: testSSD
state: ONLINE
scan: resilvered 2.96G in 0 days 00:00:38 with 0 errors on Fri Jan 4 01:59:01 2019
config:

(at this point i know the scenario is pretty a normal as ZFS is auto doing, and completing its resilvering)

now with the pool back to healthy (after A and B pull/replace and their auto resilver), i wanted to try this with DISK C , i pull that one, and the disk IO on the other 2 stops for good, for once. and when i re-insert it a minute or 2 later, still no disk io. The pool shows as healthy too. In the alerts though it says "unable to open /dev/ada3" so its kindof hung. (i think this is an issue either with the SSD or more likely the intel sas SCU,).

tomorrow im going to test my 12x HDD pool with some more pull and replace to see if i see it do the auto-resilver there. (it certainly was not showing that in the zpool status, like it did on this 2nd, 3x SSD pool).

(so far, ive been very impressed with ZFS 's performance/handling of all this BS im throwing at it to better learn)

 

[SMnasMAN]

If you look at the output of zpool status you should see a line similar to:

resilvered a few bytes in so much time with 0 errors

this is what i expected, but it def was not there on the 12x rdz1 HDD test pool. im going to re check/retest tomorow, but if its there, it should be a decent amount of data as im writing random data to these pools at 108 MB/s the entire time im doing all this (so with the disk gone for around 2 minutes it should be afew GB resilver

 

[SMnasMAN]

well some bad news- So while the pulling / re-inserting of disks for the SSD rdz1 lastnight seemed to go well (re-silvering and scrubs too). my FN sys rebooted/crashed on 4 x different occasions in past 12-18h , each time 10m to 1.5hours into my loop of dd writing random data to that same 3x SSD pool (this was after all my pulling/inserting was done). So it appears that something silently was messed up on that pool, even though it was not apparent in anyway.

3x of the crashes/panics it was fatal trap 12: page faults
(this test system, in this exact config has not crashed once in nearly a month of 24x7 , non stop, stress testing. All memory,4x 32gb ecc, is on QVL and has been individually tested for days in memtestv8 pro).

So what ive found in forums is that unexpected crashes like this can sometime be caused by a corrupt zpool (or corrupt data on pool). To test this hypothesis, i deleted the pool, wiped all 3x SSDs (with write all 0s) , and then created a new pool (same as before, 3x rdz1). And on that new pool, im now 3h 5min into my same random data write test, and not one reboot nor panic (before anywhere from 10m to 1.5h it FN would panic)

ill keep updating, and maybe do the pull and re-insert tests again , just to double verify.