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.