5

Before I begin, a quick disclaimer. I'm basically a developer forced into a sysadmin role by circumstances, so I apologize in advance if I say something stupid or seem like I don't know what I'm doing.

So, we are having problems with one of the HDD-s on our main server. /dev/sda has two partitions, one mounted as / and another used as PostgreSQL data drive (/dev/sda2).

$ df -h
Filesystem                                              Size  Used Avail Use% Mounted on
rootfs                                                   92G   13G   75G  14% /
udev                                                     10M     0   10M   0% /dev
tmpfs                                                   1.6G   12M  1.6G   1% /run
/dev/disk/by-uuid/8ffca87a-ffe4-4c39-ab30-352b61f039f8   92G   13G   75G  14% /
tmpfs                                                   5.0M     0  5.0M   0% /run/lock
tmpfs                                                   3.2G     0  3.2G   0% /run/shm
/dev/sda2                                               826G   66G  719G   9% /var/lib/data/vol1
/dev/sdb1                                               917G   75G  797G   9% /var/lib/data/vol2

(/dev/sda1 is mounted using its UUID for some reason)

Lately, it started experiencing intervals of 100% IO R/W, during which the system is practically blocked and unable to perform the simplest tasks.

A brief excerpt from dmesg:

[6554534.743764] INFO: task /usr/bin/monito:29408 blocked for more than 120 seconds.
[6554534.743828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[6554534.743889] /usr/bin/monito D ffff88041fcd3780     0 29408      1 0x00000000
[6554534.743891]  ffff880101906780 0000000000000082 ffff880100000000 ffff88040f2c0100
[6554534.743893]  0000000000013780 ffff880187b45fd8 ffff880187b45fd8 ffff880101906780
[6554534.743895]  0000000000000246 000000018134fb39 ffff88041ffc8328 ffff88039bac2dd8
[6554534.743896] Call Trace:
[6554534.743899]  [<ffffffffa019e660>] ? do_get_write_access+0x1ad/0x36a [jbd2]
...

We know this is triggered by PostgreSQL queries. Here's iotop output while this is happening:

22609 be/4 postgres  441.12 K/s    0.00 B/s  0.00 % 98.46 % postgres: db_name~a_1 127.0.0.1(33183) SELECT
24359 be/4 postgres  988.02 K/s    0.00 B/s  0.00 % 98.22 % postgres: db_name~a_1 127.0.0.1(34194) SELECT

You might be thinking: "Just optimize you DB, man. Where's the mystery?" However, take into consideration 3 things:

  • There's another instance of the same application, running the same database schema on /dev/sdb, under similar load. The I/O pressure there is normal, rarely over 10-20%.

  • Look at the combined throughput of the two PostgreSQL processes in that listing. It barely passes 1MB/s. That seems way too low for a database process (which should be optimized to be as sequential as possible).

  • Whatever the load on HDD, it should never block completely they way it does here, to the point of producing kernel errors and a simple ls taking a minute to complete.

My conclusion from all this is that /dev/sda is failing and needs to be replaced. And herein lies the problem. Before I contact the host company, I need to provide some proof that the HDD is truly failing. However...

smartctl /dev/sda --all
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 INFORMATION SECTION ===
Device Model:     WDC WD1003FBYZ-010FB0
...
=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED
...
SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0027   100   253   021    Pre-fail  Always       -       0
  4 Start_Stop_Count        0x0032   100   100   000    Old_age   Always       -       2
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   100   253   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   098   098   000    Old_age   Always       -       2114
 10 Spin_Retry_Count        0x0032   100   253   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   253   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       2
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       2
193 Load_Cycle_Count        0x0032   200   200   000    Old_age   Always       -       9
194 Temperature_Celsius     0x0022   112   109   000    Old_age   Always       -       35
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0030   100   253   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   200   000    Old_age   Offline      -       0

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%      2108         -

...

(truncated output, drop me a comment if I cut out too much)

As you can see, smartctl says everything is OK. I even did a full test and no error was found.

So I'm at a loss here. Everything points towards a failing hard drive, yet S.M.A.R.T monitoring doesn't detect anything.

My questions:

  • Is my diagnosis correct? Is the drive really failing?
  • If yes, how do I get some report on this, that I can show to the hosting company so they would agree to replace it?
  • If no, what is the next most likely culprit?

UPDATE 1

As per Baruch's advice, I executed discscan. Unfortunately, it found nothing I can point at.

diskscan /dev/sda
diskscan version HEAD

I: Validating path /dev/sda
I: Opened disk /dev/sda sector size 512 num bytes 1000204885504
I: Scanning disk /dev/sda in 65536 byte steps
I: Scan started at: Sun Aug 31 04:21:33 2014

Access time histogram:
       1: 14138808
      10: 923503
     100: 183268
     500: 15944
    1000: 436
    2000: 1
    3000: 0
    4000: 0
    5000: 0
    6000: 0
    7000: 0
    8000: 0
    9000: 0
   10000: 0
   15000: 0
   20000: 0
   25000: 0
   30000: 0
above that: 0
 1290 |                                                                       
      |                                                                       
      |                              ^                                        
      |                                                                       
      |                                                                       
 1075 |                                                                       
      |                                                                       
      |                          ^                                            
      |                                                                       
      |                                                                       
  860 |                                ^                                      
      |                                           ^               ^           
      |                                                                       
      |                           ^ ^           ^                          ^ ^
      |                  ^              ^^   ^     ^                          
  645 |                   ^^       ^  ^   ^^^ ^  ^    ^ ^^^^^       ^^      ^ 
      |        ^       ^        ^                            ^   ^ ^  ^^^ ^   
      | ^ ^       ^         ^                  ^       ^       ^^             
      |    ^                 ^                      ^         ^               
      |         ^     ^                              ^                   ^    
  430 |  ^  ^^^  ^ ^ ^                                                        
      |                                                                       
      |             ^   ^     ^^                                              
      |                                                                       
      |                                                                       
  215 |                                                                       
      |                                                                       
      |                                                                       
      | **********************************************************************
      | ______________________________________________________________________
      +-----------------------------------------------------------------------
Conclusion: passed
I: Scan ended at: Sun Aug 31 09:22:34 2014

I: Scan took 18061 second
I: Closed disk /dev/sda

I also updated my partial backups and am about to make a full backup before I proceed.

Next steps:

I installed iosnoop script (suggested by Baruch). I can get it to collect latencies, but I can't figure out how I can make it produce anything that would be actionable info for the hosting company.

Baruch's third suggestion is above my head ATM. I will look into it more and update if I figure out something.

If I don't figure out anything by tomorrow, I will recommend just buying another disk anyway and transferring sda there. Then we will know if there was a disk issue or something else, and proceed from there.

UPDATE 2

Executed smartctl -x. Nothing much to see, but here's a pastebin with full results.

Enabled verbose scsi logging as per Baruch's instructions. I'm getting a lot of stuff like this in my /var/log/messages:

Aug 31 15:28:07 swfemail kernel: [7539683.491379] sd 0:0:0:0: [sda] Send: 
Aug 31 15:28:07 swfemail kernel: [7539683.491382] sd 0:0:0:0: [sda] CDB: Write(10): 2a 00 01 3f ce 80 00 00 10 00
Aug 31 15:28:07 swfemail kernel: [7539683.491526] sd 0:0:0:0: [sda] Send: 
Aug 31 15:28:07 swfemail kernel: [7539683.491528] sd 0:0:0:0: [sda] CDB: Synchronize Cache(10): 35 00 00 00 00 00 00 00 00 00
Aug 31 15:28:08 swfemail kernel: [7539684.411573] sd 0:0:0:0: [sda] Send: 
Aug 31 15:28:08 swfemail kernel: [7539684.411576] sd 0:0:0:0: [sda] CDB: Write(10): 2a 00 01 b6 da d0 00 00 08 00
Aug 31 15:28:08 swfemail kernel: [7539684.411597] sd 0:0:0:0: [sda] Send: 
Aug 31 15:28:08 swfemail kernel: [7539684.411598] sd 0:0:0:0: [sda] CDB: Write(10): 2a 00 01 b6 ba d0 00 00 08 00
Aug 31 15:28:08 swfemail kernel: [7539684.411639] sd 0:0:0:0: [sda] Send: 
Aug 31 15:28:08 swfemail kernel: [7539684.411639] sd 0:0:0:0: [sda] CDB: Write(10): 2a 00 05 c6 18 88 00 00 a8 00
Aug 31 15:28:08 swfemail kernel: [7539684.412056] sd 0:0:0:0: [sda] Send: 
Aug 31 15:28:08 swfemail kernel: [7539684.412057] sd 0:0:0:0: [sda] CDB: Synchronize Cache(10): 35 00 00 00 00 00 00 00 00 00

Nothing overly useful so far, but the disk has entered a "quiet" phase. I will try to catch the output once it starts blocking again.

Belatedly I thought to check older kernel error messages. Nothing pops out as a direct error. Just a bunch of timeout warnings.

UPDATE 3

Tried reading off scsi logs during the 100% pressure time window. No ERROR or TIMEOUT entries :-(

We added another HDD. Currently I'm cloning it with dd if=/dev/sda of=/dev/sdc bs=32M (later I'll do another pass with rsync while offline). I expect this to be done by the end of the day.

I will update again in a few days with results.

UPDATE 4

Due to issues with our hosting company, we weren't able to fully switch to a new disk. Until the issues are resolved, we compromised with moving only the database to the new disk. Here's the current layout (only pertinent devices):

/dev/sdc1                                       92G   23G   65G  26% /
/dev/sdb1                                      917G  170G  701G  20% /var/lib/data/vol2
/dev/sda2                                      826G   71G  714G   9% /var/lib/data/vol1

/dev/sdc is the (potentially) bad disk. /dev/sda is the new disk that now has the database.

The next step is monitoring the situation and seeing whether the 100% usage bursts return. I will update (and hopefully post the accepted answer) in a few days.

  • 2
    Do you have backups and can you restore successfully from them? If not, you need to make that priority one, even above replacing this disk. – Michael Hampton Aug 30 '14 at 20:34
  • Few partial backups. I can restore mostly everything from scratch, but not easily or quickly. Obviously, I would prefer if I could get a new HDD while this one is still working and then sync in flight. – panta82 Aug 30 '14 at 20:38
  • Your host isn't likely to cooperate with that. Better get your backup squared away now. – Michael Hampton Aug 30 '14 at 21:05
  • 4
    S.M.A.R.T. doesn't capture all error or failure conditions. It shouldn't be used alone in determining drive health. – ewwhite Aug 31 '14 at 3:44
  • 1
    The presence of a SMART error is a prediction that a drive will soon fail. The absence of such an error, however, is not a prediction that the drive will not fail. – Rob Moir Aug 31 '14 at 5:38
5

You are most likely having a disk problem. The disk is failing and one fairly common failure method is to have higher latencies due to increased number of retries on certain problematic areas on the disk, these areas when hit will cause a chain reaction of other IOs waiting on them and if there were multiple IOs to the affected area you'll see such a problem as there will be multiple IOs blocking for >10 seconds.

I can recommend testing the disk with diskscan it will show you the latency graph across the disk. It can work in read-only mode so it is not destructive at all. You can also ask it to fix areas that are readable but very slow, but first test the disk to see how it behaves.

It is possible that the problem is intermittent and so will not be noticed by diskscan. You can run iosnoop to collect histories of all IOs and their latencies. The script adds some overhead but works very nicely. It may need some scripting around for a longer logging session if the problem only happens infrequently.

You can increase the scsi subsystem logging level to try to get more information out of the kernel, if you use an LSI SAS HBA to access the disks you can increase the logging level of the mpt2sas driver to get more info out of it as well. Both can help seeing if there are timeouts and aborts in the kernel. Check to see if you can see log messages in the kernel pertaining timeouts and aborts already, they may serve as another clue.

Edit 1:

To enable SCSI debug logging you can use the command: echo 9411 > /proc/sys/dev/scsi/logging_level you may need to use a different location for the sys file.

Also try to run smartctl with -x option it will show a few last errors if there are any.

  • Thanks, updated the question. +1, but no accepted answer yet :-( – panta82 Aug 31 '14 at 14:43
  • Did. Updated the question. – panta82 Aug 31 '14 at 19:46
  • I can't see anything special in the new info as well. If and when the disk acts up again it might provide an insight into the disk problems. – Baruch Even Sep 2 '14 at 3:08

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.