There are several issues when reporting concurrent marking time:
1. Bengt.Rutisson noticed when -XX:+G1SummarizeConcMark is used,
I stumbled on this comment in ConcurrentMarkThread::run():
// Update the total virtual time before doing this, since it will try
// to measure it to get the vtime for this marking. We purposely
// neglect the presumably-short "completeCleanup" phase here.
_vtime_accum = (end_time - _vtime_start);
After we have updated the _vtime_accum we go on to do the cleanup work. This work is now split up into a stopped phase and a concurrent phase. Both these phases should probably be included in the _vtime_accum value since we use it to log the total time spent in concurrent cycles at the end of a run.
When I look at the nosql logs that we got from Jenny the presumably-short "completeCleanup" phase is really not that short. They are 300-500 ms. We actually log this value in the summary too. Under the name "cleanups". But the concurrent cleanup time is not logged anywhere as far as I can tell.
So this summary at the end of the nosql log:
Concurrent marking:
0 init marks: total time = 0.00 s (avg = 0.00 ms).
75 remarks: total time = 4.65 s (avg = 61.93 ms).
[std. dev = 11.14 ms, max = 100.41 ms]
75 final marks: total time = 0.17 s (avg = 2.24 ms).
[std. dev = 0.43 ms, max = 3.83 ms]
75 weak refs: total time = 4.48 s (avg = 59.69 ms).
[std. dev = 10.97 ms, max = 96.58 ms]
75 cleanups: total time = 27.55 s (avg = 367.32 ms).
[std. dev = 37.75 ms, max = 513.21 ms]
Final counting total time = 0.06 s (avg = 0.82 ms).
RS scrub total time = 26.83 s (avg = 357.74 ms).
Total stop_world time = 32.19 s.
Total concurrent time = 4649.85 s ( 4642.63 s marking).
...isn't really accurate. The _vtime_accum is reported as the last line, the " Total concurrent time". As you can see the "cleanups" have taken 27 seconds and they are not included in the 4659 seconds that are reported.
2. There is also a bug in the reporting of initial marks. We don't update the data source that is printed for the "init marks" line. The field logged for that line is called _init_times but is never assigned to.
3. with -XX:+G1SummarizeConcMark enabled:
75 remarks: total time = 4.65 s (avg = 61.93 ms).
[std. dev = 11.14 ms, max = 100.41 ms]
75 final marks: total time = 0.17 s (avg = 2.24 ms).
[std. dev = 0.43 ms, max = 3.83 ms]
75 weak refs: total time = 4.48 s (avg = 59.69 ms).
[std. dev = 10.97 ms, max = 96.58 ms]
The 'weak refs' time is weakRefsWork(bool clear_all_soft_refs) time, which includes 'Unloading'. The finer gc details has something like:
"4784.322: [GC remark 4784.322: [Finalize Marking, 0.0018464 secs] 4784.324: [GC ref-proc4784.324: [SoftReference, 0 refs, 0.0002438 secs]4784.324: [WeakReference, 114 refs, 0.0002219 secs]4784.324: [FinalReference, 3 refs, 0.0001556 secs]4784.324: [PhantomReference, 0 refs, 0.0001459 secs]4784.324: [JNI Weak Reference, 0.0000089 secs], 0.0008123 secs] 4784.324: [Unloading, 0.0031693 secs], 0.0591604 secs]"
It is confusing to me, that in summary, weak refs is 59.69ms, but in details, it is 0.2219ms.
4. In the finer gc details listed above, the remark time is 59.1604ms, but only 2 ms (for finalize marking and refproc) + 3ms (for unloading) are listed.
1. Bengt.Rutisson noticed when -XX:+G1SummarizeConcMark is used,
I stumbled on this comment in ConcurrentMarkThread::run():
// Update the total virtual time before doing this, since it will try
// to measure it to get the vtime for this marking. We purposely
// neglect the presumably-short "completeCleanup" phase here.
_vtime_accum = (end_time - _vtime_start);
After we have updated the _vtime_accum we go on to do the cleanup work. This work is now split up into a stopped phase and a concurrent phase. Both these phases should probably be included in the _vtime_accum value since we use it to log the total time spent in concurrent cycles at the end of a run.
When I look at the nosql logs that we got from Jenny the presumably-short "completeCleanup" phase is really not that short. They are 300-500 ms. We actually log this value in the summary too. Under the name "cleanups". But the concurrent cleanup time is not logged anywhere as far as I can tell.
So this summary at the end of the nosql log:
Concurrent marking:
0 init marks: total time = 0.00 s (avg = 0.00 ms).
75 remarks: total time = 4.65 s (avg = 61.93 ms).
[std. dev = 11.14 ms, max = 100.41 ms]
75 final marks: total time = 0.17 s (avg = 2.24 ms).
[std. dev = 0.43 ms, max = 3.83 ms]
75 weak refs: total time = 4.48 s (avg = 59.69 ms).
[std. dev = 10.97 ms, max = 96.58 ms]
75 cleanups: total time = 27.55 s (avg = 367.32 ms).
[std. dev = 37.75 ms, max = 513.21 ms]
Final counting total time = 0.06 s (avg = 0.82 ms).
RS scrub total time = 26.83 s (avg = 357.74 ms).
Total stop_world time = 32.19 s.
Total concurrent time = 4649.85 s ( 4642.63 s marking).
...isn't really accurate. The _vtime_accum is reported as the last line, the " Total concurrent time". As you can see the "cleanups" have taken 27 seconds and they are not included in the 4659 seconds that are reported.
2. There is also a bug in the reporting of initial marks. We don't update the data source that is printed for the "init marks" line. The field logged for that line is called _init_times but is never assigned to.
3. with -XX:+G1SummarizeConcMark enabled:
75 remarks: total time = 4.65 s (avg = 61.93 ms).
[std. dev = 11.14 ms, max = 100.41 ms]
75 final marks: total time = 0.17 s (avg = 2.24 ms).
[std. dev = 0.43 ms, max = 3.83 ms]
75 weak refs: total time = 4.48 s (avg = 59.69 ms).
[std. dev = 10.97 ms, max = 96.58 ms]
The 'weak refs' time is weakRefsWork(bool clear_all_soft_refs) time, which includes 'Unloading'. The finer gc details has something like:
"4784.322: [GC remark 4784.322: [Finalize Marking, 0.0018464 secs] 4784.324: [GC ref-proc4784.324: [SoftReference, 0 refs, 0.0002438 secs]4784.324: [WeakReference, 114 refs, 0.0002219 secs]4784.324: [FinalReference, 3 refs, 0.0001556 secs]4784.324: [PhantomReference, 0 refs, 0.0001459 secs]4784.324: [JNI Weak Reference, 0.0000089 secs], 0.0008123 secs] 4784.324: [Unloading, 0.0031693 secs], 0.0591604 secs]"
It is confusing to me, that in summary, weak refs is 59.69ms, but in details, it is 0.2219ms.
4. In the finer gc details listed above, the remark time is 59.1604ms, but only 2 ms (for finalize marking and refproc) + 3ms (for unloading) are listed.
- relates to
-
JDK-8153770 Move G1 concurrent time report into separate class
-
- Open
-