Take the 2-minute tour ×
Unix & Linux Stack Exchange is a question and answer site for users of Linux, FreeBSD and other Un*x-like operating systems.. It's 100% free, no registration required.

I have RHEL 5.4 kernel 2.6.18-164.el5 and I am experiencing very bad disk performance that happens randomly during working with Oracle.

Nothing appears in the logs.

When it happens, I see one CPU core stuck at 100% system time in top:

Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :  1.0%us,  0.0%sy,  0.0%ni, 99.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  1.0%us,  0.0%sy,  0.0%ni, 99.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu4  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu5  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu6  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu7  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu8  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu9  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu10 :  0.0%us,100.0%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu11 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu12 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu13 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu14 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu15 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   8097368k total,  5761028k used,  2336340k free,   602024k buffers
Swap:  2088440k total,        0k used,  2088440k free,  3070188k cached

Checking disk writes with dd I get same on top and it shows:

time dd if=/dev/zero of=1000 bs=2M count=500 conv=fdatasync

79+0 records in
79+0 records out
165675008 bytes (166 MB) copied, 279.746 seconds, 592 kB/s

real    4m40.565s
user    0m0.000s
sys 4m40.521s 

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
8557 root      25   0 65212 2640 2548 R 99.8  0.0   3:02.99 dd

During normal operations I get:

500+0 records in
500+0 records out
1048576000 bytes (1.0 GB) copied, 9.24778 seconds, 113 MB/s

real    0m9.249s
user    0m0.001s
sys 0m1.772s

The disks are two 15k RPM SAS in a RAID1 configuration managed by a MegaRAID SAS9261-8i controller.

I have already upgraded both the driver and the firmware of the controller.

The strange problem is that the system can work fine for weeks and all disk benchmarks show good results.

How can this poor disk performance be debugged?

for Patrick request this is the output during 100%sy

top - 14:12:57 up 13 days, 15:49,  3 users,  load average: 1.28, 1.48, 1.17
Tasks: 424 total,   2 running, 422 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu4  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu5  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu6  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu7  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu8  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu9  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu10 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu11 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu12 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu13 :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu14 :  0.0%us,100.0%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu15 :  0.0%us,  1.0%sy,  0.0%ni, 99.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   8097368k total,  6167440k used,  1929928k free,   306644k buffers
Swap:  2088440k total,        4k used,  2088436k free,  3638216k cached

mpstat -P ALL 3 1

02:13:19 PM  CPU   %user   %nice    %sys %iowait    %irq   %soft  %steal   %idle    intr/s
02:13:22 PM  all    0.06    0.00    6.50    0.00    0.02    0.00    0.00   93.42   1077.00
02:13:22 PM    0    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00   1001.33
02:13:22 PM    1    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM    2    0.00    0.00    0.00    0.00    0.33    0.00    0.00   99.67     43.67
02:13:22 PM    3    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM    4    0.00    0.00    0.00    0.33    0.00    0.00    0.00   99.67     16.33
02:13:22 PM    5    0.33    0.00    2.99    0.00    0.00    0.00    0.00   96.68      0.00
02:13:22 PM    6    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.33
02:13:22 PM    7    0.33    0.00    0.00    0.00    0.00    0.00    0.00   99.67      0.00
02:13:22 PM    8    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM    9    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM   10    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM   11    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM   12    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM   13    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
02:13:22 PM   14    0.00    0.00  100.00    0.00    0.00    0.00    0.00    0.00     14.33
02:13:22 PM   15    0.66    0.00    1.00    0.00    0.00    0.00    0.00   98.34      0.00

Average:     CPU   %user   %nice    %sys %iowait    %irq   %soft  %steal   %idle    intr/s
Average:     all    0.06    0.00    6.50    0.00    0.02    0.00    0.00   93.42   1077.00
Average:       0    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00   1001.33
Average:       1    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:       2    0.00    0.00    0.00    0.00    0.33    0.00    0.00   99.67     43.67
Average:       3    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:       4    0.00    0.00    0.00    0.33    0.00    0.00    0.00   99.67     16.33
Average:       5    0.33    0.00    2.99    0.00    0.00    0.00    0.00   96.68      0.00
Average:       6    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.33
Average:       7    0.33    0.00    0.00    0.00    0.00    0.00    0.00   99.67      0.00
Average:       8    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:       9    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:      10    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:      11    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:      12    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:      13    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00      0.00
Average:      14    0.00    0.00  100.00    0.00    0.00    0.00    0.00    0.00     14.33
Average:      15    0.66    0.00    1.00    0.00    0.00    0.00    0.00   98.34      0.00

sar -I XALL 3 1 interrupts higher than 0

Average:         INTR    intr/s
Average:            0   1000.33
Average:           51      7.33
Average:           59      1.00
Average:           75     23.33
Average:          218     61.67
Average:          233      0.33

it seems not interrupts issue

share|improve this question
    
2.6.18 is an ancient kernel ( it was released in 2006! ). You really should upgrade. –  psusi Jan 11 '12 at 15:18
    
@psusi Given the user running RHEL and Oracle that may not be an option... –  Karlson Jan 12 '12 at 14:59
2  
@psusi redhat backports critical fixes to older kernels. It may be 2.6.18, but its still up to date with fixes. The only thing missing vs newer kernels would be features. –  Patrick Jan 14 '12 at 2:36
    
redhat ports some features as well –  rvs Jan 15 '12 at 9:00
    
I deleted my answer as its obviously incorrect based on the info you provided. This shows that its not interrupts or anything, but really is the kernel consuming all the CPU time. I cannot think of why this would be. The only thing I can think of is something wrong with the filesystem (and so filesystem driver is eating CPU). You might also try upgrading to one of the later RHEL5 point releases (5.7 is the latest). –  Patrick Jan 15 '12 at 17:01

2 Answers 2

time dd if=/dev/zero of=1000 bs=2M count=500 conv=fdatasync

...

real 4m40.565s

user 0m0.000s

sys 4m40.521s

Well it's certainly got nothing to do with the fact you're normally running Oracle (NB, while /dev/zero will generate output quickly, writing lots of null bytes to a Unix filesystem is not a very good benchmark due to sparse file support - in this case performance is so bad that the problem is still evidenct though).

Even your 'normal' timings seem rather slow - but again there is a huge gulf between these and the poor performance.

On an oldish, 2 core single SATA box I get:

real    0m6.961s
user    0m0.001s
sys     0m1.459s

Can you easily switch around your disk config (e.g. bypass the megaRAID controller and use mdadm (software) raid? (NB I've had some serious issues running MySQL on top of an md device previously - while that may have just been me / old bugs now fixed, I'd recommend planning for a worst-case outcome when testing this).

The occassional poor performance suggests that disk may be going off line then getting rebuilt - any errors being reported?

share|improve this answer
    
The megaraid tool not showing any errors. I prefer not touch the raid configuration for now since the OS is on it. I wonder what is the reason of 1 cpu core stuck on 100.0%sy. –  user14199 Jan 11 '12 at 12:35
    
also i want to add that the first indication of the problem is this situation when i see 1 cpu core stuck on 100%sy so i think the issue related somehow to the kernel –  user14199 Jan 11 '12 at 14:16
2  
what are you talking about with sparse file support? writing out zeros has nothing to do with sparse files. –  Patrick Jan 11 '12 at 23:38
    
@Patrick: suggest you go do some background reading –  symcbean Jan 13 '12 at 14:43
1  
@symcbean A sparse file when read back is presented as zeros. Writing zeros out does not create a sparse file. You have to seek to a position in the file which does not exist and then everything before that position is filled in as zeros even though you didnt actually write anything there. –  Patrick Jan 14 '12 at 0:03

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

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