Initial mark times

[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