User, Sys and Real Times in GC Log

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.