High iowait for unknown reason
17,234
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.
Related videos on Youtube
![Jenna Raine - See you later (ten years) [Lyrics] 'Cause time wasn't in our favor {TikTok Song}](https://i.ytimg.com/vi/bhjwDkqfg18/hq720.jpg?sqp=-oaymwEcCNAFEJQDSFXyq4qpAw4IARUAAIhCGAFwAcABBg==&rs=AOn4CLD4lRPqRmMeiEkmVtqCtdiWUZeobw)
03 : 42
Jenna Raine - See you later (ten years) [Lyrics] 'Cause time wasn't in our favor {TikTok Song}
07 : 14
Troubleshooting IO performance issues on Linux
08 : 08
Vaccine Induced Liver Injury/ Hepatitis, Myth or Fact? Peer Reviewed Case Report
08 : 25
NO SOONER...THAN, HARDLY...WHEN VỪA MỚI...THÌ ĐÃ, CẤU TRÚC TIẾNG ANH HAY, HỮU ÍCH TRONG GIAO TIẾP
02 : 18
DevOps & SysAdmins: High iowait for unknown reason
Author by
favadi
Updated on September 18, 2022Comments
-
favadi over 1 year
I'm having a hard time figure out the reason cause high iowait on my server.
This is log of
iostat -xm 5 5Linux 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.42As 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
smartctlreport 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/sdbsmartctl 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 30result.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-
Admin over 10 yearsRun a self-testsmartctl -t long /dev/sdband come back in a few hours with the results. -
Admin over 10 yearsIf 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.
-
Admin over 10 years@MichaelHampton I will post the result within a few hours.
-
Admin over 10 years@Jesse I know the process cause the high io. How can I know if my file system is fragmentation or the program have difficult io patterns? And thank you for your advice about the kernel.
-
Admin over 10 yearsRun
pidstat -d 1 30and see what comes up. -
Admin over 10 yearsYou 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?
-
-
favadi over 10 yearsThe process 3734 is a
cassandraprocess, its parent pid is 1. My question: why with that small io speed (< 4 MB/s), those processes can saturate /dev/sdb? -
Matthew Ife over 10 yearsThis 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.