Over a million developers have joined DZone.
{{announcement.body}}
{{announcement.title}}

GC Explained: Times

DZone's Guide to

GC Explained: Times

You can never know too much about Garbage Collection in Java. Here are breakdowns of what user, sys, and real time means in your GC log.

· Java Zone
Free Resource

Learn how to troubleshoot and diagnose some of the most common performance issues in Java today. Brought to you in partnership with AppDynamics.

Have you ever wondered what user, sys , and real times in a GC log mean? Well, I have, a couple of times at least. Let’s say that we have the following line after Full GC entry:

[Times: user=4.21 sys=0.03, real=0.75 secs]

To find out what they represent, we should check the UNIX command time first. time is a utility that executes the command that you put after it and prints time statistics. For example, time ps will show running processes together with the info about how much time it took to invoke ps.

94880 ttys017    0:00.19 -bash
3574 ttys018    0:00.03 -bash
3850 ttys019    0:00.09 -bash

real 0m0.066s
user 0m0.005s
sys 0m0.053s

 

As you can see, the output also contains real, user, and sys times. The manual for the time command gives a little bit more information about the terms:

These statistics consist of (i) the elapsed real time between invocation and termination, (ii) the user CPU time, and (iii) the system CPU time

  • real: The user-perceived time it took to execute the command from the start to the end of the call, including time slices used by other processes and the time when our process is blocked (e.g. I/O waiting). The synonyms are wall clock time and elapsed real time.

  • user: The CPU time that was spent on non-kernel (user-mode) code only within the given process — so other processes and the time when our process is blocked are not included.

  • sys: The CPU time spent on the kernel (system) code only within the given process. Similarly to user time, other processes and the time when our process is blocked are not included.

When real Time Is Lower Than user + sys Time

Let’s look at the GC log example from the top:

[Times: user=4.21 sys=0.03, real=0.75 secs]

What it basically says is that, in reality, from the user perspective, it took 0.75 seconds to complete. Kernel code was executed for 0.03 seconds and non-kernel code took 4.21 seconds. How is it possible that the real elapsed time is lower than user time? Well, it’s because the user code was executed by multiple threads and the statistics print the sum of all threads working on it. So basically, multiple GC threads were involved. 

When real Time Is Equals user + sys Time

That’s a typical situation when the Serial Garbage Collector is used. Because it runs only one GC thread, user + sys time will be more or less similar to the real time.

When real Time Is Greater Than user + sys Times

In certain circumstances, you might see real time to be greater than user + sys time. If it happens often and the differences are substantial, then it might mean that there is either a lack of CPU or there is heavy I/O activity in the system. Lack of CPU is when the application doesn’t get enough CPU cycles to run because they are shared among too many processes. The solution might be to add more CPU cores or to reduce the number of the most CPU-consuming processes. Heavy I/O is well explained in this LinkedIn article.

Understand the needs and benefits around implementing the right monitoring solution for a growing containerized market. Brought to you in partnership with AppDynamics.

Topics:
java ,java gc ,real time ,user time ,sys time ,java performance ,tutorial

Published at DZone with permission of Grzegorz Mirek, DZone MVB. See the original article here.

Opinions expressed by DZone contributors are their own.

{{ parent.title || parent.header.title}}

{{ parent.tldr }}

{{ parent.urlSource.name }}