In the Garbage Collection log file, 3 types of time are reported for every single GC event:
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.
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:
You are going to see output like this:
Fig: result of “time ls” command
The ‘time ls’ command first displays the output of execution of the “ls” command, which lists all the directories/files in the current directory:
Fig: output of “ls”
Next you see the amount of time it’s taken to execute “ls”, which is:
Fig: time taken to execute “ls”
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 in StackOverflow 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.
[Times: user=11.53 sys=1.38, real=1.03 secs]
[Times: user=0.09 sys=0.00, real=0.09 secs]
How Mahatma Gandhi Helped Me
I still haven’t answered the question how Mahatma Gandhi helped me. Following was one of his immortal quote on customers:
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 thehttp://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.