idle cpu usage

[Liam Slusser]

Good Afternoon All,

I'm trying to track down idle CPU across my V cluster. Without any
client activity all 4 of my V servers have a load avg of around 0.3
and the V java process is actively using 10% cpu on one core (it jumps
up and down a bit).

The jvisualvm tool (Java VisualVM) shows a number of "running" threads
but nothing stands out. Jconsole also shows nothing out of the
ordinary. No GCs and a beautiful saw tooth memory usage pattern.

If i kill and restart V the cpu usage goes back to zero. The bdb file
timestamps show no access/writes since last nights cleanup job.

Where should I start in tracking down this problem? Anybody else
having this issue? I've searched the mailing lists and I found a few
people talking about bdb cleaner threads running out of control but as
far as I can tell there has been no access to the bdb files since the
previous nights cleanup job.

4 server cluster of Voldemort 0.81-release w/ java 1.6.0_21 on Centos 5.5 x64
bdb with ~4 million keys
6g JVM heap, 4g bdb cache

thanks,
liam

[Geir Magnusson Jr.]

6G of heap? what GC config are you using? if you log GC activity, what do you see?

> --
> You received this message because you are subscribed to the Google Groups "project-voldemort" group.
> To post to this group, send email to project-...@googlegroups.com.
> To unsubscribe from this group, send email to project-voldem...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/project-voldemort?hl=en.
>

[Liam Slusser]

Here is a picture of the last few hours of jconsole:
http://i.imgur.com/mNez6.png

I just noticed but it looks like the CPU usage has a similar pattern
to the memory usage - could the CPU usage be java doing memory
management?

My GC configuration is as follows:

-XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintTenuringDistribution
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-Xloggc:/home/voldemort/data/var/log/gc.log

My full java opts:

-server -Xms6g -Xmx6g -XX:NewSize=1024m -XX:MaxNewSize=1024m
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:CMSInitiatingOccupancyFraction=70 -Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=9000
-Dcom.sun.management.jmxremote.ssl=false
-Dcom.sun.management.jmxremote.authenticate=false
-XX:+PrintTenuringDistribution -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps -Xloggc:/home/voldemort/data/var/log/gc.log

Here is the last few lines of the gc.log. From the log it hasn't done
any FULL GCs, just partials.

506384.851: [CMS-concurrent-sweep-start]
506385.257: [CMS-concurrent-sweep: 0.406/0.406 secs] [Times: user=0.41
sys=0.00, real=0.41 secs]
506385.257: [CMS-concurrent-reset-start]
506385.294: [CMS-concurrent-reset: 0.036/0.036 secs] [Times: user=0.03
sys=0.00, real=0.03 secs]
506385.704: [GC [1 CMS-initial-mark: 4173005K(5095424K)]
4188334K(6039168K), 0.0183520 secs] [Times: user=0.02 sys=0.00,
real=0.02 secs]
506385.723: [CMS-concurrent-mark-start]
506386.791: [CMS-concurrent-mark: 1.068/1.069 secs] [Times: user=1.08
sys=0.00, real=1.07 secs]
506386.791: [CMS-concurrent-preclean-start]
506386.806: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times:
user=0.01 sys=0.00, real=0.02 secs]
506386.806: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 506391.855:
[CMS-concurrent-abortable-preclean: 0.826/5.050 secs] [Times:
user=0.83 sys=0.01, real=5.04 secs]
506391.856: [GC[YG occupancy: 21921 K (943744 K)]506391.856: [Rescan
(parallel) , 0.0097870 secs]506391.866: [weak refs processing,
0.0000100 secs] [1 CMS-remark: 4173005K(5095424K)] 4194926K(6039168K),
0.0099160 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
506391.866: [CMS-concurrent-sweep-start]
506392.272: [CMS-concurrent-sweep: 0.406/0.406 secs] [Times: user=0.40
sys=0.00, real=0.40 secs]
506392.272: [CMS-concurrent-reset-start]
506392.309: [CMS-concurrent-reset: 0.036/0.036 secs] [Times: user=0.04
sys=0.00, real=0.04 secs]
506392.721: [GC [1 CMS-initial-mark: 4173005K(5095424K)]
4194927K(6039168K), 0.0254570 secs]

[Geir Magnusson Jr.]

On Mar 17, 2011, at 12:25 AM, Liam Slusser wrote:

> Here is a picture of the last few hours of jconsole:
> http://i.imgur.com/mNez6.png
>
> I just noticed but it looks like the CPU usage has a similar pattern
> to the memory usage - could the CPU usage be java doing memory
> management?

Funny that :)

>
> My GC configuration is as follows:
>
> -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
> -XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintTenuringDistribution
> -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
> -Xloggc:/home/voldemort/data/var/log/gc.log

I think you're just watching the concurrent GC working.

geir