In the Garbage Collection log file, 3 types of time are reported for every single GC event:
- ‘user’
- ‘sys’
- ‘real’
Example: [Times: user=11.53 sys=1.38, real=1.03 secs].
For any engineer who is analyzing the GC logs will have following two questions:
- What is the difference between ‘user’, ‘sys’, and ‘real’ times?
- Which time should I use for measurement?
When I started with Garbage Collection, I had question #1. However, this knowledge, which I have shared below, was easy to gain.
However, as the author of http://gceasy.io/ (a universal garbage collection log analysis tool), I was constantly asking myself question #2. Since http://gceasy.io reports several insightful metrics and graphs, on which time should I standardize? Now that http://gceasy.io is widely adopted, there is a great responsibility to represent the facts accurately. But Mahatma Gandhi helped me to clarify question #2. Really he did help me. You might wonder what Mahatma Gandhi has to do with Garbage collection logging times. Am I making any sense here? My wife keeps saying I talk non-sense most of the time (which is true as well). But in this case, I might be able to convenience you, my friend.
History
Before even getting into GC Time, let’s just take couple minutes to learn about the Unix command “time.”
When you issue the below UNIX command:
time ls
You are going to see output like this:
The ‘time ls’ command first displays the output of execution of the “ls” command, which lists all the directories/files in the current directory:
Next you see the amount of time it’s taken to execute “ls”, which is:
Note here “real,” “user,” “sys” times are displayed. This is the same data that we see in GC logs. Below is a great definition provided inStackOverflow for each of these times:
Real is wall clock time – time from start to finish of the call. This is all elapsed time including time slices used by other processes and time the process spends blocked (for example if it is waiting for I/O to complete).
User is the amount of CPU time spent in user-mode code (outside the kernel) within the process. This is only actual CPU time used in executing the process. Other processes and time the process spends blocked do not count towards this figure.
Sys is the amount of CPU time spent in the kernel within the process. This means executing CPU time spent in system calls within the kernel, as opposed to library code, which is still running in user-space. Like ‘user’, this is only CPU time used by the process.
User+Sys will tell you how much actual CPU time your process used. Note that this is across all CPUs, so if the process has multiple threads, it could potentially exceed the wall clock time reported by Real.
Java GC Times
This is the same concept that is applied in GC logging as well. Let’s look at couple examples to understand this concept better.
Example 1:
[Times: user=11.53 sys=1.38, real=1.03 secs]
In this example: ‘user’ + ‘sys’ is much greater than ‘real’ time. That’s because this log time is collected from the JVM, where multiple GC threads are configured on a multi-core/multi-processors server. As multiple threads execute GC in parallel, the workload is shared amongst these threads. Thus actual clock time (‘real’) is much less than total CPU time (‘user’ + ‘sys’).
Example 2:
[Times: user=0.09 sys=0.00, real=0.09 secs]
Above is an example of GC Times collected from a Serial Garbage Collector. As Serial Garbage collector always uses a single thread only, real time is equal to the sum of user and system times.
How Gandhi Helped Me?
According to Gandhi, the Customer is the primary focus. Similarly, when you are looking at performance optimization, you are primarily optimizing response time for your customer. The customer doesn’t care how many GC threads you use or how many processors you have. What matters is how many seconds he has to wait before he sees his screen painted with data. For that reason, I have used “real” time, which is basically the “clock time” for all the metrics and graphs in the http://gceasy.io/ (universal garbage collection log analysis tool).
But it doesn’t mean ‘sys’ or ‘user’ times are not important. They are also important to see whether you want to increase your GC thread count or CPU processor count, to reduce your GC pause times.
link: https://blog.gceasy.io/2016/04/06/gc-logging-user-sys-real-which-time-to-use/
