WeakReference processing: long times during G1 remark

[Yu Zhang]

Hi, Simone,

Sorry for the very late response.  I am posting my understanding how 
references are processed in G1.  I might misunderstand it, I am hoping 
others can correct me if I am wrong.

G1 has 2 reference processors: stop the world (_ref_processor_stw) and 
concurrent_marking (_ref_processor_cm). _ref_processor_stw is used 
during STW pauses(young/mixed/full gc) ; _ref_processor_cm is used 
during concurrent marking.  These 2 both span the heap.

During a STW pause, _ref_processor_cm discovery is temporally disabled. 
  _ref_processor_stw handles the reference object discovery and 
processing.  At the end of the evacuation, _ref_processor_stw process 
the discovered references and en queue the rest.  _ref_processor_cm 
discovery is restored.

ref_processor_cm handles reference object discovery and processing 
during the concurrent marking cycle.  The discovery is enabled during 
initial-marking.  The reference is processed during remark.

It is strange that if your weak reference allocation is 2.5M per hour, 
but 3M in 39s during remark.

>Am I right in assuming that a young GC processes the weak refs from
the young generation, while a remark processes the weak refs that have
been found during marking (and therefore those that are in old
generation) ?

The references during young gc are discovered during young gc pause.  While the references processed during remark are discovered during marking cycle.

> Another thing I noticed is that the weak refs processed during the
mixed GC do not sum up to the 3M processed during remark: at most few
thousands vs 3M. Not sure they should, I just wanted to report this
information in case it matters.

They are not related.

Thanks,
Jenny

On 2/10/2015 10:34 AM, Simone Bordet wrote:
> Hi,
>
> I just want to double check with the experts whether what I see is
> normal or needs more investigation.
>
> The application uses one ThreadLocal, which eventually generates
> WeakReferences, lots of them.
> Below you can find 2 G1 remark GC log lines that are 39s apart.
> -XX:+ParallelRefProcEnabled is on, JDK 8u25.
>
> What I am interested in is understanding if ~35s of CPU time is
> considered normal to process 3M of weak references, since seems a lot
> of time (about 12 micros each).
>
> Also, the weak refs number reported in the GC log line is the number
> of weak refs that have been GC marked, or the number of weak refs that
> have been enqueued (their referent is weakly reachable) ?
> I ask because we have instrumented WeakReference allocation, and the
> numbers shows an allocation of about 2.5M weak refs per hour, while
> here seems 3M in 39s.
> Furthermore, we have no evidence that 3M weak refs survive for a long
> period of time, and we see a big difference in the number of weak refs
> processed during a young GC (at most around 1K, more often in the tens
> or hundreds), and the 3M processed during remark.
>
> Am I right in assuming that a young GC processes the weak refs from
> the young generation, while a remark processes the weak refs that have
> been found during marking (and therefore those that are in old
> generation) ?
>
> Another thing I noticed is that the weak refs processed during the
> mixed GC do not sum up to the 3M processed during remark: at most few
> thousands vs 3M. Not sure they should, I just wanted to report this
> information in case it matters.
>
> Is there any known issue about ref processing during the remark phase ?
>
> Thanks !
>
>
> 2015-02-09T12:07:00.327-0800: 31671.525: [GC remark 31671.530: [GC
> ref-proc31671.530: [SoftReference, 2 refs, 0.0052296 secs]31671.535:
> [WeakReference, 3264308 refs, 2.0524238 secs]31673.588:
> [FinalReference, 215 refs, 0.0028225 secs]31673.591:
> [PhantomReference, 1787 refs, 0.0050046 secs]31673.596: [JNI Weak
> Reference, 0.0007776 secs], 2.0932150 secs], 2.1138048 secs]
>   [Times: user=36.39 sys=0.68, real=2.11 secs]
>
> 2015-02-09T12:07:39.210-0800: 31710.408: [GC remark 31710.413: [GC
> ref-proc31710.413: [SoftReference, 3 refs, 0.0064721 secs]31710.420:
> [WeakReference, 3168257 refs, 1.7807508 secs]31712.201:
> [FinalReference, 268 refs, 0.0025569 secs]31712.203:
> [PhantomReference, 1702 refs, 0.0038438 secs]31712.207: [JNI Weak
> Reference, 0.0007997 secs], 1.8847662 secs], 1.9052513 secs]
>   [Times: user=34.54 sys=0.63, real=1.90 secs]
>