High load, low CPU use, low memory use, high %iowait (%wa)

Duboux · Apr 16, 2012

Hi,

I'm having some odd problems with my server.
It shows a high load, but the rest of the information I see with "top" makes it look like there's nothing busy going on.

It started with this:

Code:

top - 10:44:04 up 113 days, 7:41, 1 user, load average: 8.75, 9.27, 8.99
Tasks: 1059 total, 1 running, 1028 sleeping, 0 stopped, 30 zombie
Cpu(s): 1.2%us, 0.6%sy, 0.1%ni, 82.1%id, [COLOR="Red"]15.6%wa[/COLOR], 0.1%hi, 0.3%si, 0.0%st
Mem: 2049080k total, 1973000k used, 76080k free, 133816k buffers
Swap: 4095992k total, 12k used, 4095980k free, 998116k cached

and after a reboot:

Code:

top - 09:51:10 up 21:51,  1 user,  load average: 8.12, 7.92, 8.69
Tasks: 1397 total,   1 running, 1374 sleeping,   0 stopped,  22 zombie
Cpu(s):  0.3%us,  0.5%sy,  0.0%ni,  0.0%id, [COLOR="Red"]98.9%wa[/COLOR],  0.2%hi,  0.2%si,  0.0%st
Mem:   2049072k total,  2036928k used,    12144k free,    62944k buffers
Swap:  4095992k total,      104k used,  4095888k free,   746988k cached

And it doesn't seem to have heavy processes..

Code:

top - 22:43:44 up 2 days, 13:05,  1 user,  load average: 3.87, 4.07, 4.23
Tasks: 191 total,   1 running, 190 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.3%us,  0.3%sy,  0.0%ni, 35.1%id, [COLOR="Red"]64.2%wa[/COLOR],  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.0%us,  0.0%sy,  0.0%ni,  0.0%id,[COLOR="Red"]100.0%wa[/COLOR],  0.0%hi,  0.0%si,  0.0%st
Mem:   2049044k total,  2036900k used,    12144k free,    26148k buffers
Swap:  4095992k total,      100k used,  4095892k free,  1277908k cached

  PID  PPID  UID USER     RUSER    TTY       PR  NI  VIRT SWAP  RES nDRT    TIME+  %CPU %MEM S COMMAND
 8242  3207    0 root     root     pts/0     15   0 12756  11m 1208    0   0:03.99  0.7  0.1 R top
    1     0    0 root     root     ?         15   0 10364 9716  648    0   0:02.88  0.0  0.0 S init [3]
    2     1    0 root     root     ?         RT  -5     0    0    0    0   0:00.19  0.0  0.0 S [migration/0]
    3     1    0 root     root     ?         34  19     0    0    0    0   0:00.36  0.0  0.0 S [ksoftirqd/0]
    4     1    0 root     root     ?         RT  -5     0    0    0    0   0:00.00  0.0  0.0 S [watchdog/0]

I noticed the extreme %wa values, meaning the CPU's are waiting for things to happen before they do anything themselves..
So there must be something wrong, like IRQ interupts, or I/O errors, bad disk segments, memory problem, etc..

I checked dmesg and /var/log/messages for anything that could relate to such failures, but nothing was written about it..

I did some tests:

Code:

avg-cpu:  %user   %nice %system [COLOR="Red"]%iowait[/COLOR]  %steal   %idle
           0.00    0.00    0.00   [COLOR="Red"]49.75[/COLOR]    0.00   50.25

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
hda               0.00   198.00  0.00  0.00     0.00     0.00     0.00    68.08    0.00   0.00 100.10
hda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
hda2              0.00   198.00  0.00  0.00     0.00     0.00     0.00    68.08    0.00   0.00 100.10
dm-0              0.00     0.00  0.00 286.00     0.00  2288.00     8.00   166.79    0.00   3.50 100.10
dm-1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system [COLOR="Red"]%iowait[/COLOR]  %steal   %idle
           0.00    0.00    0.50   [COLOR="Red"]91.04[/COLOR]    0.00    8.46

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
hda               0.00     4.95  0.00 10.89     0.00   102.97     9.45   122.03 4958.18  91.09  99.21
hda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
hda2              0.00     4.95  0.00 10.89     0.00   102.97     9.45   122.03 4958.18  91.09  99.21
dm-0              0.00     0.00  0.00 27.72     0.00   221.78     8.00   327.89 2301.79  35.79  99.21
dm-1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

(who is dm-0 and dm-1 ? -->
[root@server ~]# dmsetup ls
VolGroup00-LogVol01 (253, 1)
VolGroup00-LogVol00 (253, 0)
)

Checked if the disk was full:

Code:

[root@server ~]# df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/VolGroup00-LogVol00
                      899G   23G  830G   3% /
/dev/hda1              99M   47M   48M  50% /boot
tmpfs                1001M     0 1001M   0% /dev/shm

Code:

[root@server ~]# dmesg |grep hda
hda: WDC WD10EARS-003BB1, ATA DISK drive
hda: max request size: 512KiB
hda: 1953525168 sectors (1000204 MB), CHS=65535/255/63
hda: cache flushes supported
 hda: hda1 hda2
EXT3 FS on hda1, internal journal

I checked the speed of the disk 3 times:

Code:

[root@server rsync]# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   4128 MB in  2.00 seconds = 2064.56 MB/sec
 Timing buffered disk reads:    8 MB in  3.36 seconds =   [COLOR="Red"]2.38 MB/sec[/COLOR]

 Timing cached reads:   4156 MB in  2.00 seconds = 2078.69 MB/sec
 Timing buffered disk reads:    6 MB in  3.34 seconds =   [COLOR="Red"]1.80 MB/sec[/COLOR]

 Timing cached reads:   4132 MB in  2.00 seconds = 2067.08 MB/sec
 Timing buffered disk reads:    2 MB in  4.51 seconds = [COLOR="Red"]453.69 kB/sec[/COLOR]

Getting some info from the disk:

Code:

[root@server rsync]# hdparm -i /dev/hda

/dev/hda:

 Model=WDC WD10EARS-003BB1, FwRev=80.00A80, SerialNo=WD-WCAV5L679802
 Config={ HardSect NotMFM HdSw>15uSec SpinMotCtl Fixed DTR>5Mbs FmtGapReq }
 RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=50
 BuffType=unknown, BuffSize=0kB, MaxMultSect=16, MultSect=16
 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=268435455
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio3 pio4
 DMA modes:  mdma0 mdma1 mdma2
 UDMA modes: udma0 udma1 udma2
 AdvancedPM=no WriteCache=enabled
 Drive conforms to: Unspecified:  ATA/ATAPI-1 ATA/ATAPI-2 ATA/ATAPI-3 ATA/ATAPI-4 ATA/ATAPI-5 ATA/ATAPI-6 ATA/ATAPI-7

 * signifies the current active mode

and here's what caught my eye:

Code:

[root@server rsync]# hdparm -I /dev/hda

[SIZE="2"]/dev/hda:

ATA device, with non-removable media
        Model Number:       WDC WD10EARS-003BB1
        Serial Number:      WD-WCAV5L679802
        Firmware Revision:  80.00A80
Transport: Serial, SATA 1.0a, SATA II Extensions, SATA Rev 2.5
Standards:
        Supported: 8 7 6 5
        Likely used: 8[/SIZE]
Configuration:
        Logical         max     [COLOR="Red"]current[/COLOR]
        cylinders       16383   65535
        [COLOR="Red"]heads[/COLOR]           16      [COLOR="Red"][B]1[/B][/COLOR]
        sectors/track   63      63
        --
[SIZE="2"]        CHS current addressable sectors:    4128705
        LBA    user addressable sectors:  268435455
        LBA48  user addressable sectors: 1953525168
        device size with M = 1024*1024:      953869 MBytes
        device size with M = 1000*1000:     1000204 MBytes (1000 GB)
Capabilities:
        LBA, IORDY(can be disabled)
        Queue depth: 32
        Standby timer values: spec'd by Standard, with device specific minimum
        R/W multiple sector transfer: Max = 16  Current = 16
        Recommended acoustic management value: 128, current value: 254
        DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 *udma5 udma6
             Cycle time: min=120ns recommended=120ns
        PIO: pio0 pio1 pio2 pio3 pio4
             Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
        Enabled Supported:
           *    SMART feature set
                Security Mode feature set
           *    Power Management feature set
           *    Write cache
           *    Look-ahead
           *    Host Protected Area feature set
           *    WRITE_BUFFER command
           *    READ_BUFFER command
           *    NOP cmd
           *    DOWNLOAD_MICROCODE
                Power-Up In Standby feature set
           *    SET_FEATURES required to spinup after power up
           *    SET_MAX security extension
                Automatic Acoustic Management feature set
           *    48-bit Address feature set
           *    Device Configuration Overlay feature set
           *    Mandatory FLUSH_CACHE
           *    FLUSH_CACHE_EXT
           *    SMART error logging
           *    SMART self-test
           *    General Purpose Logging feature set
           *    64-bit World wide name
           *    {READ,WRITE}_DMA_EXT_GPL commands
           *    Segmented DOWNLOAD_MICROCODE
           *    SATA-I signaling speed (1.5Gb/s)
           *    SATA-II signaling speed (3.0Gb/s)
           *    Native Command Queueing (NCQ)
           *    Host-initiated interface power management
           *    Phy event counters
           *    unknown 76[12]
                DMA Setup Auto-Activate optimization
           *    Software settings preservation
Security:
        Master password revision code = 65534
                supported
        not     enabled
        not     locked
                frozen
        not     expired: security count
                supported: enhanced erase
        228min for SECURITY ERASE UNIT. 228min for ENHANCED SECURITY ERASE UNIT.
Checksum: correct[/SIZE]

My conclusion:
It seems like my disk only uses 1 head to read/write data, instead of all the 16 it is supposed to use. And therefore is very slow, causing a system wide slow response, making processes pile up.

Am I correct, and what can I do ?
Can I configure this disk to use 16 heads ?
Can I just remove it, if I have another disk in raid-1 ?

The clients on this server complained that they haven't received email for 2 days now.
Is this related to this disk problem ?

Thanks

SeLLeRoNe · Apr 16, 2012

Regarding the email i can reply for sure, yes, it is related.

check /etc/exim.conf for those lines

deliver_queue_load_max = 50.0
queue_only_load = 25.0

Problably the second is set to 7.5 on your system, that will prevent queue run when system load is upper then 7.5, higher that value and restart exim.

Regarding the HD heads, sorry, dont know how help.

Regards

Duboux · Apr 16, 2012

thanks

It was set to:

Code:

#EDIT#20:
deliver_queue_load_max = 5.0
queue_only_load = 7.5
queue_run_max = 5

and now to the values you have too.

What type of response (or none at all ?) will the sending mail servers receive ?
Would they retry again in a day or 2 ?
And if that wouldn't work again, still retry ?

Duboux · Apr 16, 2012

btw, related to the high load and iowait..
a colleague of mine thinks it's not disk-related, but the dataskq process, being filled with too much stuff to do...

SeLLeRoNe · Apr 16, 2012

Actually the email that are not managed by exim cause of server load should stay in queue (check from directadmin), now that exim is enabled to work the queue on that load should start run the queue (older aswell ofc).

If you wanna manually start the retry on the queue use:

Code:

/usr/sbin/exim -d -M `ls /var/spool/exim/input/ | grep -- -H$ | cut -c 1-16`

Who sent email, if queue wasnt run cause of server load, didnt receive any advice about that, so, if now queue start, now email gonna have their try (and server response on fails).

Regarding the dataskq, i dont know, now many domains have you on the server? The dataskq should do nothing that hard usually, you can start in using debug with:

Code:

/usr/local/directadmin/dataskq d200

for see what it is doing (i suppose nothing)

What are the HW specs of the server? How many domains have it? What OS?

I would also suggest you to use htop for a better "report" than top command.

Regards

Duboux · Apr 16, 2012

There's like 40 domains on there.

And the queue is empty.
So I was thinking the email didn't arrive because exim was not running ?
Or does email get in the queue regardless if exim is turned on or off ?

SeLLeRoNe · Apr 16, 2012

Mail didnt arrive if exim wasnt running, but, who sent did receive an error (outgoing and incoming aswell).

But, exim was actually running i suppose, just wasnt performing the queue, just saving the incoming/outgoing emails.

I suppose, that if is empy, is cause already runned all the queue once you raised the value in conf file.

40 domains arent that much... what the debug say?

Regards

Duboux · Apr 16, 2012

You mean this ?

Code:

# /usr/local/directadmin/dataskq d200
Debug mode. Level 200

pidfile written
staring queue
done queue

Where do I read any debug ?

The log files in /var/log/directadmin/ are pretty empty..
the errortaskq.log mostly says something abt some errors on 1 user

# tail -50 /var/log/directadmin/errortaskq.log
2012:04:15-07:17:20: Unable to read /etc/virtual/<userdomain>_off/passwd
2012:04:15-07:23:41: Backup: <username> : Unable to get data from file: /var/named/<userdomain>.db
2012:04:16-00:40:39: Unable to delete bytes log: /var/log/httpd/domains/<userdomain>.bytes : Error truncating /var/log/httpd/domains/<userdomain>.bytes : No such file or directory<br>

2012:04:16-08:30:03: Unable to read /etc/virtual/<userdomain>_off/passwd
2012:04:16-08:37:16: Backup: <username> : Unable to get data from file: /var/named/<userdomain>.db
2012:04:16-09:27:01: service dovecot wasn't running, starting it <-- could have been me
2012:04:16-09:29:01: service dovecot wasn't running, starting it <-- could have been me

for the rest, some hardware info u asked for:

Code:

# fdisk -l

Disk /dev/hda: 1000.2 GB, 1000204886016 bytes
255 heads, 63 sectors/track, 121601 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes

   Device Boot      Start         End      Blocks   Id  System
/dev/hda1   *           1          13      104391   83  Linux
/dev/hda2              14      121601   976655610   8e  Linux LVM

Code:

# lspci
00:00.0 Host bridge: Intel Corporation 82946GZ/PL/GL Memory Controller Hub (rev 02)
00:02.0 VGA compatible controller: Intel Corporation 82946GZ/GL Integrated Graphics Controller (rev 02)
00:1c.0 PCI bridge: Intel Corporation N10/ICH 7 Family PCI Express Port 1 (rev 01)
00:1c.4 PCI bridge: Intel Corporation 82801GR/GH/GHM (ICH7 Family) PCI Express Port 5 (rev 01)
00:1c.5 PCI bridge: Intel Corporation 82801GR/GH/GHM (ICH7 Family) PCI Express Port 6 (rev 01)
00:1d.0 USB controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #1 (rev 01)
00:1d.1 USB controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #2 (rev 01)
00:1d.2 USB controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #3 (rev 01)
00:1d.3 USB controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #4 (rev 01)
00:1d.7 USB controller: Intel Corporation N10/ICH 7 Family USB2 EHCI Controller (rev 01)
00:1e.0 PCI bridge: Intel Corporation 82801 PCI Bridge (rev e1)
00:1f.0 ISA bridge: Intel Corporation 82801GB/GR (ICH7 Family) LPC Interface Bridge (rev 01)
00:1f.2 IDE interface: Intel Corporation N10/ICH7 Family SATA Controller [IDE mode] (rev 01)
00:1f.3 SMBus: Intel Corporation N10/ICH 7 Family SMBus Controller (rev 01)
06:00.0 Ethernet controller: Intel Corporation 82573L Gigabit Ethernet Controller
07:00.0 Ethernet controller: Intel Corporation 82573L Gigabit Ethernet Controller

SeLLeRoNe · Apr 16, 2012

Code:

staring queue
done queue

that is the debug

queue isnt doing anything, task run every minute but.. if the tasks file is empty it stop immediatly, that's why i suppose (and now im sure) that isnt dataskq that is overloading your server.

Maybe one of your customers have just a lot of traffic but from top command i dont see any process that use so much cpu.

Honestly ive no ideas about this :/

Sorry

Duboux · Apr 16, 2012

yeah, that's the weird thing.
The server doesn't seem that busy. The CPU's are just waiting for something before they continue processing the next item..

When after a while of keeping the server running, the queue goes up, I see a lot of tasks (lots of cronjobs imap logins), even > 1000, while there are only like 135 when the server is idle. So that large queue and load and zombies, make it look like the processes are causing this, but I doubt it.
Though doing killall -15 dataskq and killall -tar will get the load down.

But the %wa still shows alarming high...

Thanks for the exim help, btw

SeLLeRoNe · Apr 16, 2012

NP regarding exim... should be that a cause of a DDOS Attack? The queue (mail i suppose) was going up cause exim wanst "running" it for server load.

OFC the wait time is pretty high, so, should be a cpu issue maybe?

Since when this server is up? I suppose should be really an HW problem, but, dont sure about hd, i would think about motherboard or cpu.

Regards

Duboux · Apr 16, 2012

hmm.. I don't think it's because of a ddos attack.
Even when I stop all services that are shown in the DA-panel too, there is a high %iowait.

The server has been running nicely for a few years.

I just did a SMART test (short version)
which gave me the amount of hours the disk has been running:

Code:

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  Short offline       Completed without error       00%      6708         -

odd, that SMART tells me this disk hasn't been running for more than 280 days, lol =S

I'll google on some CPU and motherboard tests

High load, low CPU use, low memory use, high %iowait (%wa)

Duboux

Verified User

SeLLeRoNe

Super Moderator

Duboux

Verified User

Duboux

Verified User

SeLLeRoNe

Super Moderator

Duboux

Verified User

SeLLeRoNe

Super Moderator

Duboux

Verified User

SeLLeRoNe

Super Moderator

Duboux

Verified User

SeLLeRoNe

Super Moderator

Duboux

Verified User