Question about GC logging timestamps

[Shawn Heisey]

I have a question about java GC logging.  Here's a log entry that I'm 
looking at:

2013-01-04T16:37:32.694-0700: 101832.244: [GC 101832.244: [ParNew: 
3722124K->419392K(3774912K), 9.1200100 secs] 
5800224K->2591046K(7969216K), 9.1201970 secs] [Times: user=10.46 
sys=45.66, real=9.12 secs]

This is a GC that took over 9 seconds.  The timestamp is at 16:37:32 ... 
but is that the time that the GC started, or is it the time that it 
ended?  If it is the start time, then the problem I am investigating is 
most likely caused by GC pauses, but if it is end time, then I need to 
look for another cause.

I have been unable to find any definitive answer one way or the other. 
I even went as far as grabbing the OpenJDK source and trying to decipher 
that, but that proved too large a task.  I'm actually using the Oracle 
JVM, but I couldn't locate the full Oracle source code.

If anyone knows the answer to this question, please let me know.  An 
official URL explaining the situation would be very nice.

Thanks,
Shawn