Jon Masamitsu's Weblog

  • Java
    April 18, 2013

The Unspoken - Application Times

Guest Author
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).

Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.