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 UNIX command time first. time is a utility which 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. Manual for 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 – it is 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 time of CPU which 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 time of CPU spent on the kernel (system) code only within the given process – so similarly as in user time, other processes and the time when our process is blocked are not included.

 

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 the 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.

 

Real time is equal user + sys time

That’s a typical situation when 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.

 

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 lack of CPU or there is a heavy I/O activity in the system. Lack of CPU is when the application doesn’t get enough CPU cycles to run because these 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.

One response to “User, Sys and Real Times in GC Log

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.