Initial mark times

[Florian Binder]

Hi Bernd,

you have a very large young generation. This results, as you already 
mentioned, in a very large dataset for the initial-marking.
The initial marking is done single threaded and therefore takes a lot of 
time.
Your initial-mark phase ended at 11:05:33. It stopped the world for 
about 12 seconds (started at 11:05:21).
The "Finished cms..." information is for the concurrent marking phase 
which took 0.61 sec.

Have you tried to reduce your young generation? Maybe 1gb is enough?

This is all as far as I know. Hope somebody can confirm it or correct 
me, if I am wrong ;-)

-Flo


Am 01.10.2012 18:37, schrieb Bernd Eckenfels:
> Hello,
>
> in my logfile (Linux x64 1.6.0_33 d64), I see the following
> initial-mark which tooks 12real seconds. But if I look at the
> CMSStatistics I see no scanning thread took nearly as long as 12s. In
> addition to that a see a ParNew 10s after the initial-mark message.
> Does this perhaps mean, that the initial-mark was started at 11:05:33
> but did wait for the newGC.
>
> If yes, how long was the STW time?
>
> 2012-09-27T11:04:41.986-0800: [GC [ParNew:
> 13937708K->463860K(15099520K), 0.1200170 secs]
> 15849137K->2387363K(48653952K), 0.1222950 secs] [Times: user=1.62
> sys=0.01, real=0.12 secs]
>
> 2012-09-27T11:05:33.839-0800: [GC [1 CMS-initial-mark:
> 1923502K(33554432K)] 15661857K(48653952K), 12.1543770 secs] [Times:
> user=12.11 sys=0.00, real=12.16 secs]
> Finished cms space scanning in 4th thread: 0.207 sec
> Finished cms space scanning in 0th thread: 0.207 sec
> Finished cms space scanning in 1th thread: 0.207 sec
> Finished cms space scanning in 7th thread: 0.207 sec
> Finished cms space scanning in 13th thread: 0.207 sec
> Finished cms space scanning in 10th thread: 0.207 sec
> Finished cms space scanning in 8th thread: 0.207 sec
> Finished cms space scanning in 2th thread: 0.207 sec
> Finished cms space scanning in 3th thread: 0.207 sec
> Finished cms space scanning in 9th thread: 0.207 sec
> Finished cms space scanning in 11th thread: 0.207 sec
> Finished cms space scanning in 6th thread: 0.207 sec
> Finished cms space scanning in 5th thread: 0.208 sec
> Finished cms space scanning in 12th thread: 0.208 sec
> Finished perm space scanning in 11th thread: 0.051 sec
> Finished perm space scanning in 1th thread: 0.051 sec
> Finished perm space scanning in 3th thread: 0.051 sec
> Finished perm space scanning in 10th thread: 0.051 sec
> Finished perm space scanning in 8th thread: 0.051 sec
> Finished perm space scanning in 7th thread: 0.051 sec
> Finished perm space scanning in 13th thread: 0.051 sec
> Finished perm space scanning in 9th thread: 0.051 sec
> Finished perm space scanning in 6th thread: 0.051 sec
> Finished perm space scanning in 4th thread: 0.051 sec
> Finished perm space scanning in 5th thread: 0.051 sec
> Finished perm space scanning in 2th thread: 0.065 sec
> Finished perm space scanning in 0th thread: 0.089 sec
>
> 2012-09-27T11:05:46.300-0800: [GC [ParNew:
> 13885684K->569855K(15099520K), 0.1279470 secs]
> 15809187K->2493358K(48653952K), 0.1305190 secs] [Times: user=1.91
> sys=0.19, real=0.13 secs]
>
> Finished perm space scanning in 12th thread: 0.400 sec
> Finished work stealing in 12th thread: 0.000 sec
> Finished work stealing in 1th thread: 0.350 sec
> Finished work stealing in 5th thread: 0.348 sec
> Finished work stealing in 2th thread: 0.335 sec
> Finished work stealing in 6th thread: 0.349 sec
> Finished work stealing in 9th thread: 0.349 sec
> Finished work stealing in 3th thread: 0.350 sec
> Finished work stealing in 4th thread: 0.349 sec
> Finished work stealing in 10th thread: 0.350 sec
> Finished work stealing in 8th thread: 0.350 sec
> Finished work stealing in 11th thread: 0.350 sec
> Finished work stealing in 0th thread: 0.312 sec
> Finished work stealing in 13th thread: 0.349 sec
> Finished work stealing in 7th thread: 0.350 sec
>
> 2012-09-27T11:05:46.604-0800: [CMS-concurrent-mark: 0.320/0.608 secs]
> (CMS-concurrent-mark yielded 63 times)
>   [Times: user=7.42 sys=0.45, real=0.61 secs]
>   (cardTable: 1474 cards, re-scanned 39687 cards, 2 iterations)
>
> 2012-09-27T11:05:46.788-0800: [CMS-concurrent-preclean: 0.177/0.183
> secs] (CMS-concurrent-preclean yielded 0 times)
>
> The initial mark was starting 52s after the ParNew, it was therefore
> working on a larger dataset (I guess), but it does not explain the
> long wallclock time (based on the thread statistics). I see similiar
> patterns multiple times in this logfile:
>
> 2012-09-28T02:05:33.476-0800: [GC [ParNew:
> 13925727K->588390K(15099520K), 0.1312600 secs]
> 15435756K->2098425K(48653952K), 0.1342830 secs] [Times: user=2.37
> sys=0.02, real=0.13 secs]
> 2012-09-28T02:08:16.854-0800: [GC [1 CMS-initial-mark:
> 1510035K(33554432K)] 14963114K(48653952K), 11.8353220 secs] [Times:
> user=11.83 sys=0.01, real=11.83 secs]
>
> 2012-09-28T02:08:28.708-0800: [GC [ParNew:
> 13453093K->660355K(15099520K), 0.1979760 secs]
> 14963128K->2196124K(48653952K), 0.2009570 secs] [Times: user=2.52
> sys=0.00, real=0.20 secs]
>
> Finished cms space scanning in 1th thread: 0.558 sec
> Finished cms space scanning in 13th thread: 0.558 sec
> Finished cms space scanning in 10th thread: 0.558 sec
> Finished cms space scanning in 12th thread: 0.558 sec
> Finished cms space scanning in 8th thread: 0.558 sec
> Finished cms space scanning in 2th thread: 0.558 sec
> Finished cms space scanning in 11th thread: 0.558 sec
> Finished cms space scanning in 4th thread: 0.558 sec
> Finished cms space scanning in 5th thread: 0.558 sec
> Finished cms space scanning in 7th thread: 0.558 sec
> Finished cms space scanning in 3th thread: 0.558 sec
> Finished cms space scanning in 6th thread: 0.559 sec
> Finished cms space scanning in 9th thread: 0.560 sec
> Finished cms space scanning in 0th thread: 0.563 sec
> Finished perm space scanning in 9th thread: 0.050 sec
> Finished perm space scanning in 7th thread: 0.053 sec
> Finished perm space scanning in 12th thread: 0.053 sec
> Finished perm space scanning in 2th thread: 0.053 sec
> Finished perm space scanning in 1th thread: 0.053 sec
> Finished perm space scanning in 5th thread: 0.053 sec
> Finished perm space scanning in 4th thread: 0.053 sec
> Finished perm space scanning in 13th thread: 0.053 sec
> Finished perm space scanning in 11th thread: 0.053 sec
> Finished perm space scanning in 8th thread: 0.053 sec
> Finished perm space scanning in 3th thread: 0.053 sec
> Finished perm space scanning in 10th thread: 0.062 sec
> Finished perm space scanning in 0th thread: 0.096 sec
> Finished perm space scanning in 6th thread: 0.189 sec
> Finished work stealing in 8th thread: 0.137 sec
> Finished work stealing in 13th thread: 0.137 sec
> Finished work stealing in 0th thread: 0.089 sec
> Finished work stealing in 6th thread: 0.000 sec
> Finished work stealing in 7th thread: 0.137 sec
> Finished work stealing in 1th thread: 0.137 sec
> Finished work stealing in 11th thread: 0.137 sec
> Finished work stealing in 10th thread: 0.128 sec
> Finished work stealing in 4th thread: 0.137 sec
> Finished work stealing in 9th thread: 0.137 sec
> Finished work stealing in 2th thread: 0.137 sec
> Finished work stealing in 3th thread: 0.137 sec
> Finished work stealing in 5th thread: 0.137 sec
> Finished work stealing in 12th thread: 0.137 sec
>
> 2012-09-28T02:08:29.440-0800: [CMS-concurrent-mark: 0.402/0.748 secs]
> (CMS-concurrent-mark yielded 9 times)
>   [Times: user=12.12 sys=0.30, real=0.75 secs]
>   (cardTable: 5149 cards, re-scanned 56814 cards, 2 iterations)
>
> and here:
>
> 2012-09-28T09:07:35.539-0800: [GC [ParNew:
> 13892816K->612713K(15099520K), 0.1219960 secs]
> 15663242K->2392275K(48653952K), 0.1249600 secs] [Times: user=2.30
> sys=0.03, real=0.13 secs]
> 2012-09-28T09:09:39.083-0800: [GC [1 CMS-initial-mark:
> 1779561K(33554432K)] 11806175K(48653952K), 8.4227640 secs] [Times:
> user=8.39 sys=0.02, real=8.43 secs]
> 2012-09-28T09:09:47.523-0800: [GC [ParNew:
> 10026619K->586782K(15099520K), 0.1064270 secs]
> 11806181K->2366343K(48653952K), 0.1094300 secs] [Times: user=1.92
> sys=0.01, real=0.11 secs]
> Finished cms space scanning in 8th thread: 0.364 sec
> Finished cms space scanning in 9th thread: 0.364 sec
> Finished cms space scanning in 6th thread: 0.364 sec
> Finished cms space scanning in 0th thread: 0.364 sec
> Finished cms space scanning in 2th thread: 0.364 sec
> Finished cms space scanning in 7th thread: 0.364 sec
> Finished cms space scanning in 4th thread: 0.364 sec
> Finished cms space scanning in 13th thread: 0.364 sec
> Finished cms space scanning in 3th thread: 0.364 sec
> Finished cms space scanning in 11th thread: 0.364 sec
> Finished cms space scanning in 5th thread: 0.365 sec
> Finished cms space scanning in 12th thread: 0.368 sec
> Finished cms space scanning in 1th thread: 0.369 sec
> Finished cms space scanning in 10th thread: 0.392 sec
> Finished perm space scanning in 11th thread: 0.046 sec
> Finished perm space scanning in 10th thread: 0.018 sec
> Finished perm space scanning in 4th thread: 0.047 sec
> Finished perm space scanning in 12th thread: 0.042 sec
> Finished perm space scanning in 6th thread: 0.047 sec
> Finished perm space scanning in 5th thread: 0.046 sec
> Finished perm space scanning in 0th thread: 0.047 sec
> Finished perm space scanning in 3th thread: 0.047 sec
> Finished perm space scanning in 9th thread: 0.047 sec
> Finished perm space scanning in 7th thread: 0.047 sec
> Finished perm space scanning in 8th thread: 0.048 sec
> Finished perm space scanning in 1th thread: 0.051 sec
> Finished perm space scanning in 2th thread: 0.080 sec
> Finished perm space scanning in 13th thread: 0.168 sec
> Finished work stealing in 13th thread: 0.000 sec
> Finished work stealing in 11th thread: 0.121 sec
> Finished work stealing in 6th thread: 0.121 sec
> Finished work stealing in 8th thread: 0.120 sec
> Finished work stealing in 3th thread: 0.121 sec
> Finished work stealing in 0th thread: 0.121 sec
> Finished work stealing in 4th thread: 0.121 sec
> Finished work stealing in 2th thread: 0.088 sec
> Finished work stealing in 10th thread: 0.121 sec
> Finished work stealing in 5th thread: 0.121 sec
> Finished work stealing in 12th thread: 0.121 sec
> Finished work stealing in 1th thread: 0.112 sec
> Finished work stealing in 9th thread: 0.121 sec
> Finished work stealing in 7th thread: 0.121 sec
> 2012-09-28T09:09:48.040-0800: [CMS-concurrent-mark: 0.354/0.532 secs]
> (CMS-concurrent-mark yielded 3 times)
>   [Times: user=7.92 sys=0.24, real=0.53 secs]
>   (cardTable: 3342 cards, re-scanned 18695 cards, 2 iterations)
>
> This is by the way using -XX:+CMSScavengeBeforeRemark but I guess this
> is not affecting the behaviour here, right?
>
> Greetings
> Bernd
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use