Solaris 10, cvm & high CPU usage

Tinkster · 09-18-2010, 06:37 PM

Hi,

Just wondering whether it's "normal" for Solaris' "Common
Agent Container" and some other basic java processes that
come with the OS for whatever reason to consume ~ 20%
CPU just running by themselves.

Most of our Midrange systems are running on Linux, I was
hired for my Linux skills, but find myself looking after
several Solaris machines as well while I'm on-call. And
they're costing me lots of sleep with alerts for high CPU
usage (when apps kick in, e.g. Oracle or Sun LDAP Directory
have actual load) the machines easily sit on 95-100%
CPU for extended periods of time - I get alerted after
6 consecutive 5 minute intervals over 95%.

I'm wondering whether there's a way to stop Solaris
from "playing with itself". If I could eliminate those
20% base load for cvm (and the xVM Ops Centre agent)
I could get away w/o being woken every so often. Our
in-house Solaris resource seems to be happy w/ the
status quo, I'm not. Which is why I'm asking here ;D

Cheers,
Tink

ilikejam · 09-18-2010, 08:26 PM

Hi Tink.

We don't use any Veritas software on our Solaris kit any more, so I can't really comment on the xVM stuff. 20% CPU time sounds pretty suspect though.

The Common Agent (cacao) stuff shouldn't be using noticeable CPU time. I'd check the logs at:
/var/cacao/instances/*/logs/*
for weirdness.

Could you post a prstat run so we can see what's chewing on the CPUs? Might be worth running a 'truss -p <pid>' to see what the troublesome processes are up to as well.

Dave

Tinkster · 09-19-2010, 11:04 AM

Not sure whether it was a veritas product at any stage - I'm
talking about xVM Ops Center ... Owned by "someone", then Sun,
now Oracle.

Cheers,
Tink

jlliagre · 09-19-2010, 04:57 PM

I guess xVM was confused with VXVM, quite different beasts ...
My first move would be to figure out what the busy processes are doing during these peak periods. Useful tools would be "prstat -L" to identify the threads consuming the CPU and then repeat "pstack and/or jstack" at regular intervals to identify what code is called. "dtrace" might also help there.

Tinkster · 09-20-2010, 09:00 PM

I've had a go at truss - in 30 seconds it produced a file of 5.5MB.

Code:

# truss -adlfo /tmp/cvm -p   10429
# ls -l /tmp/cvm 
-rw-r--r--   1 root     root     5574712 Sep 21 13:44 /tmp/cvm
# awk '{$1=$2="";print $0}' /tmp/cvm | sort |uniq -c | sort -n
 277   lwp_unpark(72) = 0
 295   stat("/usr/lib/cacao/lib/shared/libc.so.1", 0xFFBFF618) Err#2 ENOENT
 302   lwp_exit()
 302   lwp_sigmask(SIG_SETMASK, 0xFFBFFEFF, 0x0000FFF7) = 0xFFBFFEFF [0x0000FFFF]
 303   lwp_create() (returning as new lwp ...) = 0
 309   close(-1) Err#9 EBADF
 311   lwp_unpark(45) = 0
 320   lwp_unpark(63) = 0
 326   lwp_unpark(73) = 0
 334   open("/platform/SUNW,Sun-Fire-V240/lib/libc_psr.so.1", O_RDONLY) = 3
 334   resolvepath("/platform/SUNW,Sun-Fire-V240/lib/libc_psr.so.1", "/platform/sun4u-us3/lib/libc_psr.so.1", 1023) = 37
 336   lwp_unpark(68) = 0
 338   lwp_unpark(61) = 0
 344   mmap(0x00000000, 136, PROT_READ, MAP_SHARED, 3, 0) = 0xFF3F0000
 344   munmap(0xFF3A0000, 32768) = 0
 344   open("/lib/libc.so.1", O_RDONLY) = 3
 344   open("/var/ld/ld.config", O_RDONLY) = 3
 344   resolvepath("/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14
 346   lwp_unpark(43) = 0
 347   lwp_unpark(69) = 0
 348   lwp_unpark(71) = 0
 367   lwp_unpark(70) = 0
 501   mmap(0x00010000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 0) = 0xFF3A0000
 592   mmap(0xFF3A0000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF3A0000
 780   mmap(0xFF360000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF360000
 819   stat("/usr/lib/cacao/lib/shared/libc.so.1", 0xFFBFF6C8) Err#2 ENOENT
2964   close(3) = 0
4427   lwp_park(0x00000000, 0) = 0
5398   lwp_sigmask(SIG_SETMASK, 0x00000000, 0x00000000) = 0xFFBFFEFF [0x0000FFFF]

Not quite sure whether any of this is normal or to be expected, as I
have nothing to compare it to. :} I thought that the line in red was
a bit suspicious.

Cheers,
Tink

Tinkster · 09-20-2010, 09:00 PM

I've had a go at truss - in 30 seconds it produced a file of 5.5MB.

Code:

# truss -adlfo /tmp/cvm -p   10429
# ls -l /tmp/cvm 
-rw-r--r--   1 root     root     5574712 Sep 21 13:44 /tmp/cvm
# awk '{$1=$2="";print $0}' /tmp/cvm | sort |uniq -c | sort -n
 277   lwp_unpark(72) = 0
 295   stat("/usr/lib/cacao/lib/shared/libc.so.1", 0xFFBFF618) Err#2 ENOENT
 302   lwp_exit()
 302   lwp_sigmask(SIG_SETMASK, 0xFFBFFEFF, 0x0000FFF7) = 0xFFBFFEFF [0x0000FFFF]
 303   lwp_create() (returning as new lwp ...) = 0
 309   close(-1) Err#9 EBADF
 311   lwp_unpark(45) = 0
 320   lwp_unpark(63) = 0
 326   lwp_unpark(73) = 0
 334   open("/platform/SUNW,Sun-Fire-V240/lib/libc_psr.so.1", O_RDONLY) = 3
 334   resolvepath("/platform/SUNW,Sun-Fire-V240/lib/libc_psr.so.1", "/platform/sun4u-us3/lib/libc_psr.so.1", 1023) = 37
 336   lwp_unpark(68) = 0
 338   lwp_unpark(61) = 0
 344   mmap(0x00000000, 136, PROT_READ, MAP_SHARED, 3, 0) = 0xFF3F0000
 344   munmap(0xFF3A0000, 32768) = 0
 344   open("/lib/libc.so.1", O_RDONLY) = 3
 344   open("/var/ld/ld.config", O_RDONLY) = 3
 344   resolvepath("/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14
 346   lwp_unpark(43) = 0
 347   lwp_unpark(69) = 0
 348   lwp_unpark(71) = 0
 367   lwp_unpark(70) = 0
 501   mmap(0x00010000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 0) = 0xFF3A0000
 592   mmap(0xFF3A0000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF3A0000
 780   mmap(0xFF360000, 32768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF360000
 819   stat("/usr/lib/cacao/lib/shared/libc.so.1", 0xFFBFF6C8) Err#2 ENOENT
2964   close(3) = 0
4427   lwp_park(0x00000000, 0) = 0
5398   lwp_sigmask(SIG_SETMASK, 0x00000000, 0x00000000) = 0xFFBFFEFF [0x0000FFFF]

Not quite sure whether any of this is normal or to be expected, as I
have nothing to compare it to. :} I thought that the line in red was
a bit suspicious.

Cheers,
Tink

jlliagre · 09-21-2010, 02:45 AM

Hi Tinkster. There is nothing really suspicious in your stats. Is the CPU load mostly in userland or in the kernel ? Please try what I suggested (prstat then [p/j]stack) instead of directly suspecting system calls.

Tinkster · 09-21-2010, 01:45 PM

Quote:

Originally Posted by jlliagre

Hi Tinkster. There is nothing really suspicious in your stats. Is the CPU load mostly in userland or in the kernel ? Please try what I suggested (prstat then [p/j]stack) instead of directly suspecting system calls.

OK, I picked out the two busiest LWPs (busy at the time,
and very high in over-all CPU time).

Userspace has roughly double the CPU usage of Kernel,
e.g. 30% idle, 45% User, 25% Kernel

Code:

10429:  /usr/lib/cacao/me/cdc/bin/cvm -Xmx128M
-Dcom.sun.management.jmxremote
-----------------  lwp# 23 / thread# 23  --------------------
 ff1c6118 read     (38, f63fb3e0, 5)
 000e3f08 POSIXioRead (38, f63fb3e0, 5, 27ac00, 98d54, 9a4b4) + c
 000e76e4 Java_java_net_SocketInputStream_socketRead0 (78ada4, 78fae0,
f63fb3e0,
 78fae8, 0, 5) + 190
 000f54ec CVMjniInvokeNative (78ada4, e7554, 78fae0, 71a2a0, 6, 0) + 134
 00075194 CVMinvokeJNIHelper (78ad78, 8181f8, f1698, 78fac0, 8181f8, 284)
+ 26c
 000f2ba8 CVMgcUnsafeExecuteJavaMethod (78fae0, 81843c, 0, 78fac0, 0,
512c68) +
35e8
 0009e720 CVMjniInvoke (0, 78f50c, 2000000, 27a000, f63fbe9c, 0) + 1e0
 0009fdf4 CVMjniCallVoidMethod (78ada4, 78f50c, 2a9970, 0, 9fdc0,
ff1f1810) + 34
 000a6f04 start_func (78a7c0, 0, ff1f3700, 0, ff054200, 1) + 1b0
 000e3998 start_func (0, f63fc000, 0, 0, e3980, 1) + 18
 ff1c5238 _lwp_start (0, 0, 0, 0, 0, 0)


10429:  /usr/lib/cacao/me/cdc/bin/cvm -Xmx128M
-Dcom.sun.management.jmxremote
-----------------  lwp# 45 / thread# 45  --------------------
 ff1c6aac __fork1  (1, 4a, 0, ff1be8b8, ff1f3700, ff05da00) + 8
 000e8f5c Java_java_lang_UNIXProcess_forkAndExec (95e76c, 2, a2d240, 0, 0,
96b34
4) + 3c4
 000f54ec CVMjniInvokeNative (95e76c, e8b98, 96b334, 7187dc, 7, 0) + 134
 00075194 CVMinvokeJNIHelper (95e740, 735764, f2624, f6ca41b0, 735764,
f6ca4168)
 + 26c
 000f2ba8 CVMgcUnsafeExecuteJavaMethod (96b334, 735ad2, 0, 96b310, ef5c0,
be8) +
 35e8
 0009e720 CVMjniInvoke (0, 96b2dc, 2000000, 27a000, f50fbb04, 0) + 1e0
 0009a09c CVMjniConstruct (95e76c, 96b2d8, 73579c, 9e218, f50fbb04, 1) +
a4
 0009a158 CVMjniNewObjectV (95e76c, 96b2d8, 73579c, f50fbbd8, 9a13c,
f6ca4149) +
 1c
 000a242c JNU_NewObjectByName (95e76c, 1137d8, 1137f0, 96b2d8, 0, 0) + 88
 000e79b4 Java_java_lang_Runtime_execInternal (95e76c, 96b2b0, 96b2b4, 0,
0, f50
fbce0) + 60
 000f54ec CVMjniInvokeNative (95e76c, e7954, 96b2b0, 1657c4, 4, 0) + 134
 00075194 CVMinvokeJNIHelper (95e740, 2abae8, f2624, d18, 2abae8, d1c) +
26c
 000f2ba8 CVMgcUnsafeExecuteJavaMethod (96b2b0, 1dbfe4, f6ca4104, 96b290,
ef5c0,
 95e6f0) + 35e8
 0009e720 CVMjniInvoke (0, 96ab14, 2000000, 27a000, f50fbe9c, 0) + 1e0
 0009fdf4 CVMjniCallVoidMethod (95e76c, 96ab14, 2a9970, 0, 9fdc0,
ff1f1810) + 34
 000a6f04 start_func (95e6d8, 0, ff1f3700, 0, ff05da00, 1) + 1b0
 000e3998 start_func (0, f50fc000, 0, 0, e3980, 1) + 18
 ff1c5238 _lwp_start (0, 0, 0, 0, 0, 0)