GC Log Output 1

[SamBones]

Can anyone explain this GC log line?

2014-04-22T12:20:41.635-0400: 469154.330: [GC 469154.330: 
[ParNew: 891798K->104831K(943744K), [highlight #FCE94F]6.7735900 secs[/highlight]] 2514763K->1808044K(8283776K), [highlight #FCE94F]21.4037500 secs[/highlight]] 
[Times: user=[highlight #FCE94F]65.62[/highlight] sys=0.00, real=[highlight #FCE94F]21.40 secs[/highlight]]

It's a new generation collection on a system using CMS. It's version 1.6.0_31.

According to this line, the Parallel New collection took 6.77 seconds, but the elapsed real time was 21.40 seconds. Also, under Times, the "user" time is 65.62. I'm not sure what these numbers are saying.

 

[mikrom]

Maybe have a look at these links

http://stackoverflow.com/questions/1833496/understanding-javas-gc-logs

http://stackoverflow.com/questions/13311416/what-do-real-user-and-sys-mean-in-the-java-cms-gc-log

http://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1

 

[SamBones]

Thanks for the links mikrom.

For the most part I understand "what" the different times are. What's confusing me is that I'm used to seeing them all pretty much within a fraction of a second apart from each other. What I'm trying to figure out is why there is such a huge difference in the numbers. Just trying to figure out why a GC needing 65.62 seconds of user CPU, reports that it took only 6.77 seconds, but also 21.0 real elapsed time.

I think I have the 65.62 seconds verses 6.77 seconds figured. I've got 12 threads assigned as GC threads, so if 12 threads were each working for 6+ seconds, that gets us in the neighborhood of 65.62 seconds. Not exact, but probably close enough considering overhead for thread coordination and such.

But, why is the elapsed time 21.4 seconds? I would think the threads would be acting in parallel.

My machine has 24 processors, so the threads shouldn't be competing for CPU resources.

 

[mikrom]

But, why is the elapsed time 21.4 seconds?

I think, that here

http://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1

it's explained:

As a result, on a multicore system, the user and/or sys time (as well as their sum) can actually exceed the real time.

 

[SamBones]

Thanks, that makes sense.