Friday September 29, 2006 Java - why does my JVM use CPU when idle?
Have you ever wondered why an otherwise idle Java process sits there
in an endless loop scheduling a thread, calling poll,
regularly eating a small amount of CPU?
I always used to think that this was because of things like the garbage-collector and the JIT compiler, but it's not...
On a Unix box, an otherwise idle JVM calls poll() 20
times per second, creating a measurable CPU load as seen with 'uptime'
You can see this CPU usage by writing a simple Java application that does nothing except wait - you'll have to interrupt this application by killing it with control-c, since it just sleeps for a very long time:
package idle;
public class Main {
public static void main(String[] args) {
try {
Thread.currentThread().sleep(99999999);
} catch (InterruptedException ex) {
ex.printStackTrace();
}
}
}
|
If you compile this up, start the process and then look at what it's doing, you see this (from a Solaris machine - but the same holds true on other platforms):
$ java idle.Main & $ jps 43204 Jps 41818 Main $ truss -u libc -dp 41818 2>&1|head -50 Base time stamp: 1159529119.5139 [ Fri Sep 29 13:25:19 MEST 2006 ] /14: 0.3257 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.3261 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.3437 <- libc:gethrtime() = 0x46c64b /14@14: 0.3441 -> libc:gethrtime(0xc6, 0xf1d129d8, 0xfef41d48, 0xfeef0000) /14@14: 0.3443 <- libc:gethrtime() = 0x46c64b /14@14: 0.3446 <- libc:poll() = 0 /14@14: 0.3448 -> libc:poll(0x0, 0x0, 0x32, 0xf4240) /6: 0.3260 lwp_cond_wait(0x00036648, 0x00036630, 0xF877FA48, 0) Err#62 ETIM E /6@6: 0.3600 -> libc:gettimeofday(0xf877fb18, 0x0, 0xb, 0x3e8) /6@6: 0.3605 <- libc:_lwp_cond_timedwait() = 0x36648 /6@6: 0.3608 -> libc:_lwp_cond_timedwait(0x36648, 0x36630, 0xf877fb20, 0x3e8) /14: 0.4110 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.4113 <- libc:poll() = 0 /14@14: 0.4126 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.4132 <- libc:gethrtime() = 0x46c64b /14@14: 0.4141 -> libc:gethrtime(0xc6, 0xf5f613fc, 0xfef41d48, 0xfeef0000) /14@14: 0.4149 <- libc:gethrtime() = 0x46c64b /14@14: 0.4162 -> libc:poll(0x0, 0x0, 0x32, 0xf4240) /14: 0.4670 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.4672 <- libc:poll() = 0 /14@14: 0.4685 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.4695 <- libc:gethrtime() = 0x46c64b /14@14: 0.4699 -> libc:gethrtime(0xc6, 0xf95099a0, 0xfef41d48, 0xfeef0000) /14@14: 0.4705 <- libc:gethrtime() = 0x46c64b /14@14: 0.4717 -> libc:poll(0x0, 0x0, 0x32, 0xf4240) /14: 0.5230 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.5232 <- libc:poll() = 0 /14@14: 0.5245 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.5253 <- libc:gethrtime() = 0x46c64b /14@14: 0.5262 -> libc:gethrtime(0xc6, 0xfc9f810c, 0xfef41d48, 0xfeef0000) /14@14: 0.5271 <- libc:gethrtime() = 0x46c64b /14@14: 0.5298 -> libc:poll(0x0, 0x0, 0x32, 0xf4240) /14: 0.5820 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.5822 <- libc:poll() = 0 /14@14: 0.5834 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.5839 <- libc:gethrtime() = 0x46c64b /14@14: 0.5848 -> libc:gethrtime(0xc7, 0x22e594, 0xfef41d48, 0xfeef0000) /14@14: 0.5855 <- libc:gethrtime() = 0x46c64b /14@14: 0.5874 -> libc:poll(0x0, 0x0, 0x32, 0xf4240) /14: 0.6390 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.6392 <- libc:poll() = 0 /14@14: 0.6411 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.6417 <- libc:gethrtime() = 0x46c64b /14@14: 0.6426 -> libc:gethrtime(0xc7, 0x395075c, 0xfef41d48, 0xfeef0000) /14@14: 0.6436 <- libc:gethrtime() = 0x46c64b /14@14: 0.6448 -> libc:poll(0x0, 0x0, 0x32, 0xf4240) /14: 0.6959 pollsys(0x00000000, 0, 0xB3A7FCF0, 0x00000000) = 0 /14@14: 0.6962 <- libc:poll() = 0 /14@14: 0.6975 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.6989 <- libc:gethrtime() = 0x46c64b /14@14: 0.6997 -> libc:gethrtime(0xc7, 0x6fb093c, 0xfef41d48, 0xfeef0000) |
A thread is being woken up 20 times per second and is calling
poll() ; getthrtime(); getthrtime() each time it is woken
up. This causes the application to remain rather 'hot' for the
scheduler, and to eat up unnecessary CPU cycles.
I always thought that the CPU usage during idle times of a JVM were for garbage collection and JIT compilation - that's the only thing that should be going on behind my back, right? But my application is doing nothing - so is GC being called so often? What for? And what might be JIT compiling? There's no code being called!
It turns out that tha vast majority of these system calls are
not for GC and not for JIT compilation - they're to wake up a
thread that is for gathering statistics about the VM, which are
written to a temporary directory with a name such as
/tmp/hsperfdata_${USER}/${PID}, and which can be explored
using the jstat tool.
Let's take a look at some of this data - note that the various jstat options are self-documented, I just chose one of them:
$ jstat -class file:///tmp/hsperfdata_nstephen/41818 Loaded Bytes Unloaded Bytes Time 312 322.8 0 0.0 0.11 |
Now, it's all very well collecting this data if I want it collected, and it's OK for this to have an impact on the platform behavior to collect the data (after all, we cannot escape the observer effect), but I'd really like to be able to decide not to collect this data, and hence not incur the cost of doing so.
It turns out that this was actually much worse in much older JVMs, since the JVM timer thread would wake up every tick to see if there was work to do - there was a bug filed against it then:
... and there's a new bug filed against the current behavior too:So how can you switch this off?
Well, the honest answer is that I don't think that you can switch this off, but you can work around the problem by changing the frequency at which this thread is woken up, such that it becomes background noise.
By using a Sun-specific java command-line option, you can change
the rate of sampling to be much lower - as described in the bug
entry's workaround, it suggests you change the frequency to be that of
the other background activities of the JVM for much-needed things like
GC and JIT compilation. The hidden extended option to add to your command line is this: -XX:PerfDataSamplingInterval=500.
For a complete list of all the JVM flags, including this one, you could do worse than look here. Remember, many of these flags are non-standard and hence won't be supported on all versions of JVMs.
So does it work? Let's find out!
$ java -XX:PerfDataSamplingInterval=500 idle.Main & $ jps 43666 Jps 43555 Main $ truss -u libc -dp 43555 2>&1|head -50 Base time stamp: 1159530801.2075 [ Fri Sep 29 13:53:21 MEST 2006 ] /6: 0.4730 lwp_cond_wait(0x00036678, 0x00036660, 0xF877F9C8, 0) Err#62 ETIME /14: 0.4730 pollsys(0x00000000, 0, 0xB3A7FD70, 0x00000000) = 0 /6@6: 0.4751 -> libc:gettimeofday(0xf877fa98, 0x0, 0xb, 0x3e8) /14@14: 0.4755 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 0.4935 <- libc:gethrtime() = 0x46c7d3 /6@6: 0.4942 <- libc:_lwp_cond_timedwait() = 0x36678 /6@6: 0.5005 -> libc:_lwp_cond_timedwait(0x36678, 0x36660, 0xf877faa0, 0x3e8) /14@14: 0.5136 -> libc:gethrtime(0xa, 0x14bf2034, 0xfef41d48, 0xfeef0000) /14@14: 0.5167 <- libc:gethrtime() = 0x46c7d3 /14@14: 0.5175 <- libc:poll() = 0 /14@14: 0.5181 -> libc:poll(0x0, 0x0, 0x1f4, 0xf4240) /14: 1.0312 pollsys(0x00000000, 0, 0xB3A7FD70, 0x00000000) = 0 /14@14: 1.0314 <- libc:poll() = 0 /14@14: 1.0329 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 1.0337 <- libc:gethrtime() = 0x46c7d3 /14@14: 1.0343 -> libc:gethrtime(0xa, 0x34f2ef70, 0xfef41d48, 0xfeef0000) /14@14: 1.0347 <- libc:gethrtime() = 0x46c7d3 /14@14: 1.0362 -> libc:poll(0x0, 0x0, 0x1f4, 0xf4240) /6: 1.4961 lwp_cond_wait(0x00036678, 0x00036660, 0xF877F9C8, 0) Err#62 ETIME /6@6: 1.4974 <- libc:_lwp_cond_timedwait() = 62 /6@6: 1.4979 -> libc:gettimeofday(0xf877fa98, 0x0, 0xb, 0x3e8) /6@6: 1.5099 <- libc:gettimeofday() = 0 /6@6: 1.5124 -> libc:_lwp_cond_timedwait(0x36678, 0x36660, 0xf877faa0, 0x3e8) /14: 1.5372 pollsys(0x00000000, 0, 0xB3A7FD70, 0x00000000) = 0 /14@14: 1.5374 <- libc:poll() = 0 /14@14: 1.5386 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 1.5397 <- libc:gethrtime() = 0x46c7d3 /14@14: 1.5403 -> libc:gethrtime(0xa, 0x53164efc, 0xfef41d48, 0xfeef0000) /14@14: 1.5407 <- libc:gethrtime() = 0x46c7d3 /14@14: 1.5416 -> libc:poll(0x0, 0x0, 0x1f4, 0xf4240) /14: 2.0432 pollsys(0x00000000, 0, 0xB3A7FD70, 0x00000000) = 0 /14@14: 2.0434 <- libc:poll() = 0 /14@14: 2.0445 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 2.0455 <- libc:gethrtime() = 0x46c7d3 /14@14: 2.0464 -> libc:gethrtime(0xa, 0x7140c240, 0xfef41d48, 0xfeef0000) /14@14: 2.0470 <- libc:gethrtime() = 0x46c7d3 /14@14: 2.0483 -> libc:poll(0x0, 0x0, 0x1f4, 0xf4240) /6: 2.5111 lwp_cond_wait(0x00036678, 0x00036660, 0xF877F9C8, 0) Err#62 ETIME /6@6: 2.5127 <- libc:_lwp_cond_timedwait() = 62 /6@6: 2.5134 -> libc:gettimeofday(0xf877fa98, 0x0, 0xb, 0x3e8) /6@6: 2.5139 <- libc:gettimeofday() = 0 /6@6: 2.5151 -> libc:_lwp_cond_timedwait(0x36678, 0x36660, 0xf877faa0, 0x3e8) /14: 2.5492 pollsys(0x00000000, 0, 0xB3A7FD70, 0x00000000) = 0 /14@14: 2.5495 <- libc:poll() = 0 /14@14: 2.5504 -> libc:gethrtime(0x0, 0x0, 0x0, 0x0) /14@14: 2.5510 <- libc:gethrtime() = 0x46c7d3 |
Well, yes, it'd appear to work just fine - we've reduced frequency from twenty times a second to twice a second - a factor 10 better than before.
But does jstat still work? Yes it does! I can't guarantee that it's as accurate as before for everything, but it's still collecting data and this data is still accessible:
$ jstat -class file:///tmp/hsperfdata_nstephen/43555 Loaded Bytes Unloaded Bytes Time 312 322.8 0 0.0 0.07 |
So, with my daemonized Java process, my machine's CPU usage as indicated by 'uptime', when otherwise idle, is now 10 times closer to zero, which is good news as far as I'm concerned.
( Sep 29 2006, 03:00:00 PM CEST ) Permalink