Wait Reason: CACHE

[skt_skt]

i am looking at a process whihc is taking 70% CPU utilization on TOP.
what does the wait reason is CACHE means in glance output.


tusc is reporting as below


[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324166.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324167.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] poll(0x11d275e0, 2, 250) ....................................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] select(107, 0x11a2e984, 0x11a2ea84, 0x11a2eb84, 0x11a2e978) .................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324168.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324169.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x12232958, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324170.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324171.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324172.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] poll(0x11d275e0, 2, 250) ....................................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] select(107, 0x11a2e984, 0x11a2ea84, 0x11a2eb84, 0x11a2e978) .................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324173.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] poll(0x11d275e0, 2, 250) ....................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324174.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] select(107, 0x11a2e984, 0x11a2ea84, 0x11a2eb84, 0x11a2e978) .................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324175.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] ksleep(PTH_CONDVAR_OBJECT, 0xa47e8, 0xa47f0, 0x12b3b460) ....................................... = -ETIMEDOUT
[5527] gettimeofday(0x12b3b468, NULL) ................................................................. = 0
[5527] clock_gettime(CLOCK_REALTIME, 0x12b3b500) ...................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] poll(0x11d275e0, 2, 250) ....................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324176.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] select(107, 0x11a2e984, 0x11a2ea84, 0x11a2eb84, 0x11a2e978) .................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324177.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324178.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324179.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324180.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324181.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324182.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324183.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] poll(0x11d275e0, 2, 250) ....................................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] select(107, 0x11a2e984, 0x11a2ea84, 0x11a2eb84, 0x11a2e978) .................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324184.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x12232958, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324185.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324186.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324187.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324188.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324189.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] poll(0x11d275e0, 2, 250) ....................................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] ioctl(106, FIONREAD, 0x11a2e970) ............................................................... = 0
[5527] select(107, 0x11a2e984, 0x11a2ea84, 0x11a2eb84, 0x11a2e978) .................................... = 0
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
[5527] open("/eb_rao0_p/applmgr/p599comn/html/cabo/images/cache/gantt/gtrb324190.png", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0666) ERR#17 EEXIST
[5527] nanosleep(0x122b3358, NULL) .................................................................... = 0
( Detaching from process 5527 ("/opt/java1.4.2.02/jre/bin/PA_RISC2.0/java -DCLIENT_PROCESSID=55") )

[Tim Nelson]

The explanation I have always gotten is just what it says. Waiting for the filesystem buffer cache to flush / update.

I typically saw it in Oracle environments.

[skt_skt]

any recommendation interms of tuning it to have better performance..(does the bsize of file system matters here?)

[Tim Nelson]

I never had the opportunities to test but some suggestions were to remove buffer cache from the equation but using Online-JFS buffer options or use raw disk.

This is a question still on my list as well.

Is this a situation where the system is performing so well that waiting on CACHE is the only item listed as a wait ?

[A. Clay Stephenson · Accepted solution]

Assuming this is a vxfs filesystem, blocksize has no bearing on performance. Unlike hfs (ufs) filesystems, vxfs filesystems are extent-based rather than block-based. This means that the i/o is done in large chunks regardless of the blocksize. There is absolutely no reason to tie filesystem block size to database block size for vxfs.


I notice that your tusc output shows many attempts to create files that already exist. I don't know how smart this code actually is.

[skt_skt]

Q.Is this a situation where the system is performing so well that waiting on CACHE is the only item listed as a wait?

A.This is DB server and and the reason to analyse this is to make sure that the db programs are run in the efficient way.(obeviously there was a concern from DBA team);

I am planning to use a tracing tool(aps32) ,when the usage goes high, which can collect much information from java perspecive

#file aps32
aps32: PA-RISC1.1 executable -not stripped

./aps32 -help

usage: aps32 [-]
-c : -c : generate core of target process
-C : -C : collect samplefile data, no display
-d : -d : defered shared library loading
-g : -g : start gui at startup
-G : -G : use current gui files
-h : -h : program usage
-H : -H : program help
-i : -i100 : collection interval in MilliSec, or
-I : -I : Interactive mode
-l : -l1955 : lwp to trace within process
-J : -J : enable tracing of Java methods
-m : -m100 : number of minutes to sample
-n : -n : print 1 stack marker on traces, default none
-N : -N : renice aps32 to -20 (must be root/superuser)
-M : -M : trace process every -Mseconds if in sycalltrace
-o : -olog : file to log ascii data to, default stdout
-p : -p1234 : pid of process
-P : -Pjava : program name (optional)
-r : -rslog : record to playback file, default SampleFile
-R : -Rslog : read from playback file, default SampleFile
-s : -s100 : number of samples to take, default 100
-S : -Sbrk : trace only selected syscalls
-SS : -SS : single step process
-t : -t6 : stacktrace depth, default 6
-T : -T : take trace at syscall exits
-u : -u10 : update screen rate (samples), default 10
-U : -U10 : Update screen rate (seconds), default 10
-Z : -Z : collect registers at snapshot
-z : -z : trace on signal
@(#)aps32 application program sampler V2.4 built Aug 16 2007 at 15:52:27
@(#)+java stacktraces Copyright (c) gene.bradley@hp.com (HP)
@(#)To be used with Permission from Hewlett-Packard Company
@(#)No unauthorized duplication or dissassembly

[skt_skt]

analysing the trace files points to the bug in the code which most of the time CPU time are spent in open fucntion.

Call Summary Sorted by number of calls

Calls Per% Act CPU% Function Name
1918 95.76% 1816 99.31% open
28 1.40% 10 0.10% ksleep
12 0.60% 3 0.15% jni_GetStringCritical__FP7JNIEnv_P8_jstringPUc
5 0.25% 3 0.02% sched_yield
5 0.25% 5 0.08% Interpreted#java/io/File::createTempFile(Ljava/lang/String;Ljava/lang/String;Ljava/io/File;)Lja
va/io/File;
4 0.20% 2 0.00% JVM_Open
4 0.20% 2 0.06% mallinfo
3 0.15% 2 0.02% Compiled#java/io/UnixFileSystem::createFileExclusively(Ljava/lang/String;)Z
3 0.15% 1 0.01% Compiled#java/io/File::generateFile(Ljava/lang/String;Ljava/lang/String;Ljava/io/File;)Ljava/io
/File;
3 0.15% 1 0.00% _open_sys
3 0.15% 1 0.03% Compiled#java/io/UnixFileSystem::normalize(Ljava/lang/String;)Ljava/lang/String;
2 0.10% 1 0.02% Compiled#java/io/File::(Ljava/io/File;Ljava/lang/String;)V
2 0.10% 1 0.05% __errno
2 0.10% 1 0.06% __thread_main
2 0.10% 1 0.02% Compiled#java/io/UnixFileSystem::resolve(Ljava/lang/String;Ljava/lang/String;)Ljava/lang/String
;
2 0.10% 1 0.02% Compiled#java/io/File::checkAndCreate(Ljava/lang/String;Ljava/lang/SecurityManager;)Z
1 0.05% 1 0.01% unlock__5MutexFv
1 0.05% 1 0.02% Compiled#java/lang/StringBuffer::append(Ljava/lang/String;)Ljava/lang/StringBuffer;
1 0.05% 1 0.02% _i2c_adapter
1 0.05% 1 0.00% open64
1 0.05% 1 0.00% $$dyncall_external_20


********************************************************************************

Call Summary Sorted by CPU Usage

Calls Per% Act CPU% WCPU% Function Name
1918 95.76% 1816 99.31% 41.60% open
12 0.60% 3 0.15% 0.06% ksleep
28 1.40% 10 0.10% 0.04% jni_GetStringCritical__FP7JNIEnv_P8_jstringPUc
5 0.25% 5 0.08% 0.03% sched_yield
4 0.20% 2 0.06% 0.03% Interpreted#java/io/File::createTempFile(Ljava/lang/String;Ljava/lang/String;Ljava/io/Fi
le;)Ljava/io/File;
2 0.10% 1 0.06% 0.03% JVM_Open
2 0.10% 1 0.05% 0.02% mallinfo
3 0.15% 1 0.03% 0.01% Compiled#java/io/UnixFileSystem::createFileExclusively(Ljava/lang/String;)Z
1 0.05% 1 0.02% 0.01% Compiled#java/io/File::generateFile(Ljava/lang/String;Ljava/lang/String;Ljava/io/File;)L
java/io/File;
2 0.10% 1 0.02% 0.01% _open_sys
3 0.15% 2 0.02% 0.01% Compiled#java/io/UnixFileSystem::normalize(Ljava/lang/String;)Ljava/lang/String;
2 0.10% 1 0.02% 0.01% Compiled#java/io/File::(Ljava/io/File;Ljava/lang/String;)V
5 0.25% 3 0.02% 0.01% __errno
2 0.10% 1 0.02% 0.01% __thread_main
1 0.05% 1 0.02% 0.01% Compiled#java/io/UnixFileSystem::resolve(Ljava/lang/String;Ljava/lang/String;)Ljava/lang
/String;
3 0.15% 1 0.01% 0.01% Compiled#java/io/File::checkAndCreate(Ljava/lang/String;Ljava/lang/SecurityManager;)Z
1 0.05% 1 0.01% 0.00% unlock__5MutexFv
3 0.15% 1 0.00% 0.00% Compiled#java/lang/StringBuffer::append(Ljava/lang/String;)Ljava/lang/StringBuffer;
4 0.20% 2 0.00% 0.00% _i2c_adapter
1 0.05% 1 0.00% 0.00% open64
1 0.05% 1 0.00% 0.00% $$dyncall_external_20

[skt_skt]

bug in the code.