5

I'm having a hard time figure out the reason cause high iowait on my server.

This is log of iostat -xm 5 5

Linux 2.6.32-358.6.1.el6.x86_64 (prod-1.localdomain)    09/28/2013  _x86_64_    (16 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           6.98    0.05    3.72    3.54    0.00   85.71

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdb               0.08   120.88   30.27    1.72     0.96     0.48    92.20     0.34   10.67   3.79  12.13
sda               7.63    37.19    8.96    4.89     0.35     0.16    76.40     0.16   11.63   2.19   3.04

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5.41    0.00    6.20   37.65    0.00   50.74

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdb               0.00   109.80  186.20    1.40     3.75     0.43    45.66    98.21  519.80   5.33 100.00
sda              33.20     3.40   18.00    2.00     0.37     0.02    40.32     0.07    3.41   3.17   6.34

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5.55    0.00    7.42   30.06    0.00   56.97

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdb               0.00     0.00  196.00    0.00     3.91     0.00    40.85   100.41  506.01   5.10 100.00
sda               0.00     2.40    1.80    2.60     0.05     0.02    30.91     0.01    2.95   2.73   1.20

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5.71    0.00    7.04   31.76    0.00   55.49

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdb               0.00   100.00  189.00    1.20     3.72     0.40    44.33    95.32  514.88   5.26 100.00
sda              33.20     4.20   19.20    5.20     0.39     0.04    35.80     0.02    1.01   0.79   1.92

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          61.93    0.00   10.08   14.99    0.00   12.99

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdb               0.00     0.40  185.40    1.40     3.76     0.01    41.31    83.22  431.16   5.28  98.62
sda              33.20     5.40    9.60    4.00     0.21     0.04    37.65     0.02    1.24   1.04   1.42

As you can see, all the metrics is normal except await and %util is insanely high. So I think maybe something is wrong with /dev/sdb.

But smartctl report no useful information.

smartctl 5.43 2012-06-30 r3573 [x86_64-linux-2.6.32-358.6.1.el6.x86_64] (local build)
Copyright (C) 2002-12 by Bruce Allen, http://smartmontools.sourceforge.net

=== START OF INFORMATION SECTION ===
Model Family:     Western Digital RE4 Serial ATA
Device Model:     WDC WD2003FYYS-02W0B1
Serial Number:    WD-WMAY04093732
LU WWN Device Id: 5 0014ee 05877b196
Firmware Version: 01.01D02
User Capacity:    2,000,398,934,016 bytes [2.00 TB]
Sector Size:      512 bytes logical/physical
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   8
ATA Standard is:  Exact ATA specification draft version not indicated
Local Time is:    Sat Sep 28 09:05:30 2013 ICT
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x84) Offline data collection activity
                    was suspended by an interrupting command from host.
                    Auto Offline Data Collection: Enabled.
Self-test execution status:      (   0) The previous self-test routine completed
                    without error or no self-test has ever 
                    been run.
Total time to complete Offline 
data collection:        (29160) seconds.
Offline data collection
capabilities:            (0x7b) SMART execute Offline immediate.
                    Auto Offline data collection on/off support.
                    Suspend Offline collection upon new
                    command.
                    Offline surface scan supported.
                    Self-test supported.
                    Conveyance Self-test supported.
                    Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                    power-saving mode.
                    Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                    General Purpose Logging supported.
Short self-test routine 
recommended polling time:    (   2) minutes.
Extended self-test routine
recommended polling time:    ( 283) minutes.
Conveyance self-test routine
recommended polling time:    (   5) minutes.
SCT capabilities:          (0x303f) SCT Status supported.
                    SCT Error Recovery Control supported.
                    SCT Feature Control supported.
                    SCT Data Table supported.

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   253   253   021    Pre-fail  Always       -       9100
  4 Start_Stop_Count        0x0032   100   100   000    Old_age   Always       -       42
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   090   090   000    Old_age   Always       -       7373
 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       -       40
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       31
193 Load_Cycle_Count        0x0032   200   200   000    Old_age   Always       -       10
194 Temperature_Celsius     0x0022   123   107   000    Old_age   Always       -       29
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   200   200   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
No self-tests have been logged.  [To run self-tests, use: smartctl -t]


SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

I'm stuck here and do not know the next move to resolve the problem.

Any help will be greatly appreciated!

Update:

@MichaelHampton

My self test log, no interest information. smartctl -l selftest /dev/sdb

smartctl 5.43 2012-06-30 r3573 [x86_64-linux-2.6.32-358.6.1.el6.x86_64] (local build)
Copyright (C) 2002-12 by Bruce Allen, http://smartmontools.sourceforge.net

=== START OF READ SMART DATA SECTION ===
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%      7380       

@Mife

My pidstat -d 1 30 result.

Linux 2.6.32-358.6.1.el6.x86_64 (cass-23_120.localdomain)   09/28/2013  _x86_64_    (16 CPU)

05:57:43 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command

05:57:44 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command

05:57:45 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:46 PM      1555    736.00      0.00      0.00  java
05:57:46 PM     16698      0.00      4.00      0.00  java

05:57:46 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:47 PM       552      0.00     68.00      0.00  jbd2/sda3-8
05:57:47 PM      1555    352.00      0.00      0.00  java
05:57:47 PM     16698      0.00     12.00      0.00  java
05:57:47 PM     18074      0.00      4.00      0.00  java
05:57:47 PM     19295   1564.00      0.00      0.00  java

05:57:47 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:48 PM      1554   3128.00      8.00      4.00  xinetd
05:57:48 PM      1570    840.00      0.00      0.00  gmond
05:57:48 PM      2183      0.00      4.00      0.00  java
05:57:48 PM      2394     64.00      0.00      0.00  rsync
05:57:48 PM      2395    324.00      0.00      0.00  ssh
05:57:48 PM     13280     28.00      0.00      0.00  downloadm_new.s
05:57:48 PM     19295   1724.00      0.00      0.00  java

05:57:48 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:49 PM     19295   1744.00      0.00      0.00  java

05:57:49 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:50 PM      1083      0.00      8.00      0.00  flush-8:0
05:57:50 PM      1086      0.00      8.00      0.00  java
05:57:50 PM      2183      0.00     12.00      0.00  java
05:57:50 PM     13280    388.00      0.00      0.00  downloadm_new.s
05:57:50 PM     18074      0.00      4.00      0.00  java
05:57:50 PM     19295   1728.00      0.00      0.00  java

05:57:50 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:51 PM      2183      0.00      4.00      0.00  java
05:57:51 PM      2400      8.00      0.00      0.00  sleep
05:57:51 PM     18074      0.00      4.00      0.00  java
05:57:51 PM     19295   1680.00      0.00      0.00  java

05:57:51 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:52 PM       552      0.00     28.00      0.00  jbd2/sda3-8
05:57:52 PM      1112      0.00      4.00      0.00  jbd2/sda4-8
05:57:52 PM      2183      0.00      8.00      0.00  java
05:57:52 PM     16698      0.00      4.00      0.00  java
05:57:52 PM     18074      0.00      4.00      0.00  java
05:57:52 PM     19295   1672.00      0.00      0.00  java

05:57:52 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:53 PM      1555    376.00     20.00      0.00  java
05:57:53 PM      1570    792.00      0.00      0.00  gmond
05:57:53 PM     19295   1568.00      8.00      0.00  java

05:57:53 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:54 PM      3734    844.00    188.00      0.00  java
05:57:54 PM     19295   1672.00      0.00      0.00  java

05:57:54 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:55 PM      1083      0.00     20.00      0.00  flush-8:0
05:57:55 PM      3734   2620.00   1156.00      0.00  java
05:57:55 PM      4327      0.00      8.00      0.00  java
05:57:55 PM      9677      0.00      8.00      0.00  java
05:57:55 PM     16613      0.00      8.00      0.00  java
05:57:55 PM     19295   1272.00      8.00      0.00  java
05:57:55 PM     19426      0.00      8.00      0.00  java

05:57:55 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:56 PM      3734   3592.00   1200.00      0.00  java
05:57:56 PM     19295    332.00      0.00      0.00  java
05:57:56 PM     19426      0.00      4.00      0.00  java

05:57:56 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:57 PM       552      0.00     36.00      0.00  jbd2/sda3-8
05:57:57 PM      2405   1068.00     32.00      0.00  java
05:57:57 PM      3734   2972.00    828.00      0.00  java
05:57:57 PM      5457      0.00      8.00      0.00  java
05:57:57 PM      9677  28424.00    144.00     20.00  java
05:57:57 PM     16698      0.00      8.00      0.00  java
05:57:57 PM     18074      0.00      4.00      0.00  java
05:57:57 PM     19295      0.00      4.00      0.00  java

05:57:57 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:58 PM      2183      0.00      4.00      0.00  java
05:57:58 PM      2222      0.00      4.00      0.00  pidstat
05:57:58 PM      2405    500.00      0.00      0.00  java
05:57:58 PM      3734   4016.00    720.00      0.00  java
05:57:58 PM      5457      0.00      8.00      0.00  java
05:57:58 PM     16698      0.00      4.00      0.00  java

05:57:58 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:57:59 PM      1112      0.00      8.00      0.00  jbd2/sda4-8
05:57:59 PM      3734   4572.00    372.00      0.00  java

05:57:59 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:00 PM      1083      0.00     32.00      0.00  flush-8:0
05:58:00 PM      2405    496.00      0.00      0.00  java
05:58:00 PM      3734   5412.00      4.00      0.00  java
05:58:00 PM      5457      0.00     16.00      0.00  java
05:58:00 PM     11681      0.00      8.00      0.00  java
05:58:00 PM     14824      0.00      8.00      0.00  java
05:58:00 PM     16698      0.00     12.00      0.00  java
05:58:00 PM     17694      0.00      8.00      0.00  java
05:58:00 PM     18074      0.00     12.00      0.00  java
05:58:00 PM     18129      0.00      8.00      0.00  java
05:58:00 PM     19542      0.00      8.00      0.00  java

05:58:00 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:01 PM      3734   3888.00      0.00      0.00  java
05:58:01 PM      3813      8.00     12.00      0.00  java
05:58:01 PM     13280     28.00      0.00      0.00  downloadm_new.s
05:58:01 PM     18074      0.00      8.00      0.00  java

05:58:01 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:02 PM       552      0.00     44.00      0.00  jbd2/sda3-8
05:58:02 PM      1129      0.00     16.00      0.00  jbd2/sdb1-8
05:58:02 PM      2405    256.00      0.00      0.00  java
05:58:02 PM      3734   1200.00   1128.00      0.00  java
05:58:02 PM     16698      0.00      4.00      0.00  java
05:58:02 PM     18074      0.00      8.00      0.00  java

05:58:02 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:03 PM      1570   1172.00      0.00      0.00  gmond
05:58:03 PM      2183      0.00      4.00      0.00  java
05:58:03 PM      2405    256.00      0.00      0.00  java
05:58:03 PM      2442     92.00      0.00      0.00  rsync
05:58:03 PM      2443    916.00      0.00      0.00  ssh
05:58:03 PM      3734    576.00      0.00      0.00  java
05:58:03 PM      9677      0.00      4.00      0.00  java
05:58:03 PM     13280     56.00   8996.00      0.00  downloadm_new.s

05:58:03 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:04 PM      2183      0.00      4.00      0.00  java
05:58:04 PM      2405    256.00      0.00      0.00  java
05:58:04 PM      2443      8.00      0.00      0.00  ssh
05:58:04 PM      3734   2032.00     16.00      0.00  java

05:58:04 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:05 PM      1083      0.00      4.00      0.00  flush-8:0
05:58:05 PM      2405    224.00      0.00      0.00  java
05:58:05 PM      2446    160.00      0.00      0.00  sleep
05:58:05 PM      3734   5344.00    648.00      0.00  java
05:58:05 PM      3813      0.00      8.00      0.00  java
05:58:05 PM     13280   1016.00      0.00      0.00  downloadm_new.s

05:58:05 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:06 PM      2405     16.00      0.00      0.00  java
05:58:06 PM      3734   6196.00    344.00      0.00  java

05:58:06 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:07 PM       552      0.00      8.00      0.00  jbd2/sda3-8
05:58:07 PM      2405    112.00      0.00      0.00  java
05:58:07 PM      3734   3532.00      0.00      0.00  java
05:58:07 PM     16698      0.00      4.00      0.00  java
05:58:07 PM     18074      0.00      4.00      0.00  java

05:58:07 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:08 PM      1570   1172.00      0.00      0.00  gmond
05:58:08 PM      2183      0.00      4.00      0.00  java
05:58:08 PM      2405    352.00      0.00      0.00  java
05:58:08 PM      3734   4588.00      0.00      0.00  java
05:58:08 PM     16698      0.00      8.00      0.00  java

05:58:08 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:09 PM      2222      0.00      4.00      0.00  pidstat
05:58:09 PM      2405    368.00      0.00      0.00  java
05:58:09 PM      3734   1720.00      0.00      0.00  java
05:58:09 PM     16698      0.00      4.00      0.00  java

05:58:09 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:10 PM      1083      0.00      8.00      0.00  flush-8:0
05:58:10 PM      2405    480.00      0.00      0.00  java
05:58:10 PM      3734     40.00     16.00      0.00  java
05:58:10 PM     17768      0.00      8.00      0.00  java

05:58:10 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:11 PM      2405    608.00      0.00      0.00  java
05:58:11 PM      3734    264.00      0.00      0.00  java
05:58:11 PM     19426      0.00      4.00      0.00  java

05:58:11 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:12 PM      1129      0.00     24.00      0.00  jbd2/sdb1-8
05:58:12 PM      2405    240.00      0.00      0.00  java
05:58:12 PM     18074      0.00      8.00      0.00  java

05:58:12 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
05:58:13 PM      1570   1172.00      0.00      0.00  gmond
05:58:13 PM      2183      0.00      4.00      0.00  java
05:58:13 PM      2405    128.00      0.00      0.00  java
05:58:13 PM     18074      0.00      4.00      0.00  java

Average:          PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
Average:          552      0.00      6.13      0.00  jbd2/sda3-8
Average:         1083      0.00      2.40      0.00  flush-8:0
Average:         1086      0.00      0.27      0.00  java
Average:         1112      0.00      0.40      0.00  jbd2/sda4-8
Average:         1129      0.00      1.33      0.00  jbd2/sdb1-8
Average:         1554    104.16      0.27      0.13  xinetd
Average:         1570    171.43      0.00      0.00  gmond
Average:         2183      0.00      1.60      0.00  java
Average:         2222      0.00      0.27      0.00  pidstat
Average:         2405    178.49      1.07      0.00  java
Average:         2446      5.33      0.00      0.00  sleep
Average:         3734   1778.49    220.45      0.00  java
Average:         3813      0.27      0.67      0.00  java
Average:         4327      0.00      0.27      0.00  java
Average:         5457      0.00      1.07      0.00  java
Average:         9677    946.52      5.19      0.67  java
Average:        11681      0.00      0.27      0.00  java
Average:        13280     50.48    299.57      0.00  downloadm_new.s
Average:        14824      0.00      0.27      0.00  java
Average:        16613      0.00      0.27      0.00  java
Average:        16698      0.00      2.13      0.00  java
Average:        17694      0.00      0.27      0.00  java
Average:        17768      0.00      0.27      0.00  java
Average:        18074      0.00      2.13      0.00  java
Average:        18129      0.00      0.27      0.00  java
Average:        19295    498.04      0.67      0.00  java
Average:        19426      0.00      0.53      0.00  java
Average:        19542      0.00      0.27      0.00  java

@kworr

This is my mount options for /dev/sdb1.

% mount | grep sdb
/dev/sdb1 on /backup type ext4 (rw,noatime,commit=100)

Update2 How many IOPS to expect of your hard disk.

7,200 rpm SATA drives   HDD     ~75-100 IOPS[2]     SATA 3 Gb/s     
10,000 rpm SATA drives  HDD     ~125-150 IOPS[2]    SATA 3 Gbit/s   
10,000 rpm SAS drives   HDD     ~140 IOPS[2]            SAS     
15,000 rpm SAS drives   HDD     ~175-210 IOPS[2]    SAS     
7
  • 1
    Run a self-test smartctl -t long /dev/sdb and come back in a few hours with the results. Sep 28, 2013 at 2:28
  • 1
    If you rule out hardware it could be file system fragmentation or difficult io patterns causing issues for you. Check sar to see when the wait started and iotop to see what processes are hogging io. Also, update that kernel, it has vulnerabilities.
    – Jesse
    Sep 28, 2013 at 2:43
  • @MichaelHampton I will post the result within a few hours.
    – favadi
    Sep 28, 2013 at 2:53
  • 1
    Run pidstat -d 1 30 and see what comes up. Sep 28, 2013 at 6:39
  • 1
    You missed a high avgqu-sz. Looks like your load is like writing/reading small blocks so you are just hitting the drive queue limit. Can you share some info about fs and mount options?
    – kworr
    Sep 28, 2013 at 7:42

1 Answer 1

4

There is quite a lot of stuff happening here, but the pid 3734, a java process appears to be your culprit. You should find out what that is doing, what arguments were passed to it, what its parent pid is and a little about what it is meant to do.

Over a 30 second period of 1 second samples java uses 1778.49 read kb/sec, there is also other java processes, pids 9677 and 19295 using 946.52 and 498.04 read kb/sec respectively.

I'm in no position to tell you whether what they are doing is wrong or right, but you're high I/O is due to those java processes mainly.

2
  • The process 3734 is a cassandra process, its parent pid is 1. My question: why with that small io speed (< 4 MB/s), those processes can saturate /dev/sdb?
    – favadi
    Sep 29, 2013 at 0:42
  • 1
    This is not about device speed, but IOPS. The device clearly does not handle more than ~200 iops per second, the iostat shows its doing ~200 reads a second and getting 100% device utilisation. It is entirely plausible these java processes contribute to these IOPS. Sep 29, 2013 at 6:30

You must log in to answer this question.

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