The Unspoken - Application Times

Sometimes it is interesting to know how long your application runs between garbage collections. That can be calculated from the GC logs but a convenient way to see that information is through the command line flags -XX:+PrintGCApplicationStoppedTime and -XX:+PrintGCApplicationConcurrentTime. Adding these to your command line produces output such as this.

Application time: 0.2863875 seconds
Total time for which application threads were stopped: 0.0225087 seconds
Application time: 0.1476791 seconds
Total time for which application threads were stopped: 0.0255697 seconds

The application ran (reported in the first line) for about 287 milliseconds and then was stopped for about 22 milliseconds (reported in the second line).

The flags can be used separately or together.

Add -XX:+PrintGCTimeStamps -XX:+PrintGCDetails and you get

Application time: 0.1325032 seconds
20.149: [GC (Allocation Failure) 20.149: [ParNew: 78656K->8704K(78656K), 0.02215
98 secs] 225454K->158894K(253440K), 0.0222106 secs] [Times: user=0.13 sys=0.00,
real=0.03 secs]
Total time for which application threads were stopped: 0.0224188 seconds

When the flags was first implemented the "stopped" time really was the GC stopped time but it was later changed to include the complete stopped time. There is other work that may be done during a "safepoint" (period during which the application is halted and the VM can do some work without the application changing). All that is now included in the "stopped" time. In the example above I would say that GC was the only thing happening during the safepoint (GC time being 0.0222106 secs and the complete time being nearly the same at 0.0224188 secs). I can't speak authoritatively about what else can happen because I just don't know. But to give one example I've heard about is compiled code deoptimization. When the code for a JIT'ed method needs to be thrown away (typically because some assumption made during the compilation has been violated), the VM has to switch from the compiled code to interpreting that method again. That switch is done at a safepoint (but don't quote me on that because its not my area).

Comments:

Post a Comment:
Comments are closed for this entry.
About

jonthecollector

Search

Categories
Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today