8

I was under the impression that if an I/O error occurs during a read from a ZFS pool, two things will happen:

  1. The failure will be recorded in either the READ or CKSUM statistic of the relevant device, propagating upwards toward the pool level.
    • Redundant data will be used to reconstruct the requested block, return the requested block to the caller and if the duff drive is still functional rewrite the block to it, OR
    • An I/O error will be returned if redundant data is not available to correct for the read error.

It appears that one of the disks in my mirror setup has developed a bad sector. That by itself is not alarming; such things happen, and that's exactly why I have redundancy (a two-way mirror, to be exact). Every time I scrub the pool or read through the files in a particular directory (I haven't bothered yet to determine exactly which file is at fault), the following pops up in dmesg, obviously with varying timestamps:

Nov  1 09:54:26 yeono kernel: [302621.236549] ata6.00: exception Emask 0x0 SAct 0x9c10 SErr 0x0 action 0x0
Nov  1 09:54:26 yeono kernel: [302621.236557] ata6.00: irq_stat 0x40000008
Nov  1 09:54:26 yeono kernel: [302621.236566] ata6.00: failed command: READ FPDMA QUEUED
Nov  1 09:54:26 yeono kernel: [302621.236578] ata6.00: cmd 60/a8:78:18:5a:12/00:00:5c:01:00/40 tag 15 ncq 86016 in
Nov  1 09:54:26 yeono kernel: [302621.236580]          res 41/40:a8:18:5a:12/00:00:5c:01:00/00 Emask 0x409 (media error) <F>
Nov  1 09:54:26 yeono kernel: [302621.236585] ata6.00: status: { DRDY ERR }
Nov  1 09:54:26 yeono kernel: [302621.236589] ata6.00: error: { UNC }
Nov  1 09:54:26 yeono kernel: [302621.238214] ata6.00: configured for UDMA/133

This is a fairly up to date Debian Wheezy, kernel 3.2.0-4-amd64 #1 SMP Debian 3.2.63-2 x86_64, ZoL 0.6.3. Package versions are current at debian-zfs=7~wheezy, libzfs2=0.6.3-1~wheezy, zfs-dkms=0.6.3-1~wheezy, zfs-initramfs=0.6.3-1~wheezy, zfsutils=0.6.3-1~wheezy, zfsonlinux=3~wheezy, linux-image-amd64=3.2+46, linux-image-3.2.0-4-amd64=3.2.63-2. The only package pinning that I know of is for ZoL, for which I have (as provided by the zfsonlinux package):

Package: *
Pin: release o=archive.zfsonlinux.org
Pin-Priority: 1001

Running hdparm -R on the drive reports that Write-Read-Verify is turned on (this is a Seagate, so has that feature and I use it as an extra safety net; the additional write latency is not a problem since my interactive use pattern is very read-heavy):

/dev/disk/by-id/ata-ST4000NM0033-9ZM170_XXXXXXXX:
 write-read-verify =  2

Even given the clear indication that something is amiss, zpool status claims that there is no problem with the pool:

  pool: akita
 state: ONLINE
  scan: scrub repaired 0 in 8h16m with 0 errors on Sat Nov  1 10:46:03 2014
config:

        NAME                        STATE     READ WRITE CKSUM
        akita                       ONLINE       0     0     0
          mirror-0                  ONLINE       0     0     0
            wwn-0x5000c50065e8414a  ONLINE       0     0     0
            wwn-0x5000c500645b0fec  ONLINE       0     0     0

errors: No known data errors

This error has been showing up in the logs regularly for the last several days now (since Oct 27) so I'm not terribly inclined to write it off as merely a fluke. I run the disks with quite short SCTERC timeouts; 1.5 seconds read (to recover quickly from read errors), 10 seconds write. I have confirmed that these values are active on the drive in question.

smartd keeps pestering me (which in itself is a good thing!) about the fact that the ATA error count is climbing:

The following warning/error was logged by the smartd daemon:

Device: /dev/disk/by-id/ata-ST4000NM0033-9ZM170_XXXXXXXX [SAT], ATA error count increased from 4 to 5

For details see host's SYSLOG.

Running smartctl --attributes on the drive in question yields the following:

smartctl 5.41 2011-06-09 r3365 [x86_64-linux-3.2.0-4-amd64] (local build)
Copyright (C) 2002-11 by Bruce Allen, http://smartmontools.sourceforge.net

=== START OF READ SMART DATA SECTION ===
SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000f   076   063   044    Pre-fail  Always       -       48910012
  3 Spin_Up_Time            0x0003   091   091   000    Pre-fail  Always       -       0
  4 Start_Stop_Count        0x0032   100   100   020    Old_age   Always       -       97
  5 Reallocated_Sector_Ct   0x0033   100   100   010    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000f   092   060   030    Pre-fail  Always       -       1698336160
  9 Power_On_Hours          0x0032   089   089   000    Old_age   Always       -       9887
 10 Spin_Retry_Count        0x0013   100   100   097    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   020    Old_age   Always       -       98
184 End-to-End_Error        0x0032   100   100   099    Old_age   Always       -       0
187 Reported_Uncorrect      0x0032   095   095   000    Old_age   Always       -       5
188 Command_Timeout         0x0032   100   099   000    Old_age   Always       -       10
189 High_Fly_Writes         0x003a   100   100   000    Old_age   Always       -       0
190 Airflow_Temperature_Cel 0x0022   058   052   045    Old_age   Always       -       42 (Min/Max 20/45)
191 G-Sense_Error_Rate      0x0032   100   100   000    Old_age   Always       -       0
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       61
193 Load_Cycle_Count        0x0032   100   100   000    Old_age   Always       -       492
194 Temperature_Celsius     0x0022   042   048   000    Old_age   Always       -       42 (0 11 0 0)
195 Hardware_ECC_Recovered  0x001a   052   008   000    Old_age   Always       -       48910012
197 Current_Pending_Sector  0x0012   100   100   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0010   100   100   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x003e   200   200   000    Old_age   Always       -       0

Nothing glaringly out of the ordinary there. Note that this is an enterprise drive, so five years warranty and rated for 24x7 operation (meaning it's meant to be reliable for over 40,000 hours of operation, compared to the just under 10,000 hours under its belt so far). Notice the number 5 in attribute 187 Reported_Uncorrect; that's where the problem is. Also note the fairly low Start_Stop_Count and Power_Cycle_Count values of under 100 each.

Not that I think it's relevant in this case, but yes, the system does have ECC RAM.

Non-default properties of the root file system on the pool are:

NAME   PROPERTY              VALUE                  SOURCE
akita  type                  filesystem             -
akita  creation              Thu Sep 12 18:03 2013  -
akita  used                  3,14T                  -
akita  available             434G                   -
akita  referenced            136K                   -
akita  compressratio         1.04x                  -
akita  mounted               no                     -
akita  mountpoint            none                   local
akita  version               5                      -
akita  utf8only              off                    -
akita  normalization         none                   -
akita  casesensitivity       sensitive              -
akita  usedbysnapshots       0                      -
akita  usedbydataset         136K                   -
akita  usedbychildren        3,14T                  -
akita  usedbyrefreservation  0                      -
akita  sync                  standard               local
akita  refcompressratio      1.00x                  -
akita  written               0                      -
akita  logicalused           2,32T                  -
akita  logicalreferenced     15K                    -

and correspondingly for the pool itself:

NAME   PROPERTY               VALUE                  SOURCE
akita  size                   3,62T                  -
akita  capacity               62%                    -
akita  health                 ONLINE                 -
akita  dedupratio             1.00x                  -
akita  free                   1,36T                  -
akita  allocated              2,27T                  -
akita  readonly               off                    -
akita  ashift                 12                     local
akita  expandsize             0                      -
akita  feature@async_destroy  enabled                local
akita  feature@empty_bpobj    active                 local
akita  feature@lz4_compress   active                 local

These lists were obtained by running {zfs,zpool} get all akita | grep -v default.

Now for the questions:

  1. Why isn't ZFS reporting anything about the read problem? It's clearly recovering from it.

  2. Why isn't ZFS automatically rewriting the duff sector that the drive is clearly having trouble reading, in turn hopefully triggering a relocation by the drive, given that sufficient redundancy exists for automatic repair in the read request path?

8
  • I dunno. Maybe you're not hitting the affected files. Or perhaps none of the files are affected at this point.
    – ewwhite
    Nov 1, 2014 at 12:33
  • @ewwhite During a scrub, running which has repeatedly triggered the error showing up in the system log? (The error also showed up when I burned a set of files to DVD, which was what originally had me looking into this.) There is also a ton of snapshots on the pool going quite a way back.
    – user
    Nov 1, 2014 at 12:38
  • Upvoted because I'm not sure why you're encountering this with ZFS - It could be interesting to see if this is a bug... However from a sysadmin's perspective, spinning disks are consumables. I have disks that are DOA, die within a few weeks, die after a year... and some fail at 5 years. If you suspect severe problems, replace the drive.
    – ewwhite
    Nov 1, 2014 at 12:44
  • 1
    Right. Did you also post to the ZFS group?
    – ewwhite
    Nov 1, 2014 at 12:48
  • 1
    I don't have an answer for you, but I've seen similar behavior on FreeBSD. A failing drive which resulted in decreased performance and lots of errors printed to the console, but which failed to increment any zpool-level error counters. I have not yet found an explanation, but it may at least be worth considering that this is not a Linux-specific phenomenon.
    – Charley
    May 11, 2015 at 11:36

2 Answers 2

1

I suspect the ATA driver is retrying the read operation a couple of times when it receives an error before passing the error back to the filesystem driver.

What this means is by the time the ZFS filesystem driver gets the result of the read the data is all there, and correct, but it likely took a bit longer than normal to happen. There is of course no error counter for higher-than-average latency, so nothing logged.

The fact that the SMART value for Reported_Uncorrect is not 0 makes me suspect that the cause of the failure is the disk itself, as opposed to say the SATA cable or SATA controller being flakey.

If this is the case, most likely the disk will eventually die more and start failing to read even after however many retries the block device driver is attempting. As such my advice would be to replace the disk.

Trigging a long SMART test would likely fail on the affected blocks, if you wanted to make the error go away rewriting those blocks (with dd for example) should cause the disk to swap out those sectors, but in my experience is once a drive starts to go it's better to just replace it and be done with it.

0

I had a bad SCSI disk with a ZFS raid on Solaris. I was scanning the log files for information on error messages to gather proof the disk was bad and get Oracle to cover it on the hardware maintenance. I ran grep for certain strings in error logs and these lines showing disk errors would be in my console screen. When "Explorer" (the system log and reporting tool for Solaris) was run and sent to Oracle, they said there was no errors on the disks. But I had them on my screen history. I checked and it was indeed gone from the logs on disk.

Here is what was going on... ZFS promises zero file system errors, not zero data errors. When a serious corruption is encountered, it rolls back the transaction, doing whatever is required to make the file system integrity good. As a result, file updates are lost when it rolls back to an earlier version of the file prior to the corruption, and therefore data loss may occur. But your file system is error free.

Perhaps for simple errors, ZFS can rollback and rewrite the data in another attempt, but it seems in serious cases of bad disk behaviour, it can get into a catch-22 where data isn't being recovered and written. If you need to gather evidence on disk errors, make them come on the screen and don't rely on proof which will reside on disk, where data is potentially being reset by ZFS transaction rollbacks.

4
  • Two things. One, I don't quite see how this answers the question; perhaps you can clarify? Two, this answer appears to be factually incorrect. In the words of one of the original ZFS team leads, "note that ZFS end-to-end data integrity doesn't require any special hardware" (my emphasis). If a system crash happens you can lose the currently-outstanding txg, and zpool import -F can be used if recent txgs are unusable, but claims of automatic txg rollbacks would IMO require citations.
    – user
    May 28, 2015 at 18:50
  • The OP asked : "Why isn't ZFS reporting anything about the read problem". I am answering that. ZFS can't report to files on disk when it can't write to the disk. ZFS cannot be perfect when hardware performance is not perfect. All it can hope to achieve is protection against file system corruption. "End to end data integrity" depends on what is meant by "data" and "integrity". I believe it means "no corruption", not "all your data will be written/read perfectly under any conditions". There is a way to test for the loss under /var, check /var/log files for missing hours/days. I saw that.
    – labradort
    May 29, 2015 at 13:53
  • (1) I am the OP. (2) As shown in the question, the vdev is a mirror configuration. (3) Claims are that once data on ZFS has made it to persistent storage, it will remain there and either be readable or the I/O operation will return a read error. (4) The OS clearly detected the I/O problem, and either the kernel itself or ZFS recovered from it (since the read operation succeeded), yet the I/O error was not recorded in the pool stats.
    – user
    May 29, 2015 at 14:34
  • My ZFS was a mirror too. But firmware errors can spew junk causing no disks to work properly. Where are errors and pool stats written? To bad media. Look in the files in your /var/log area. Look at files which are constantly written to, for whatever your server does. If mail, look at maillog. If web, look at access log. Otherwise try messages. If I am right, there will be time gaps (in my case, days missing) from the log files. That is your proof that data is being lost. Don't believe me. Don't look for citations. Look at your files, and that may confirm what is happening.
    – labradort
    Jun 1, 2015 at 19:47

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .