Hi, This is normal behavior as metrics are built up to come to a size decision that will balance overheads with pause time. It’s based on the premise that smaller space will be quicker to collect… and the weak generational hypothesis suggests that this is a false premise. Another factor is allocation rates. The number of regions allocated to young will rise and fall as allocation rates rise and fall. This can lead to some interesting pathologies.
Kind regards, Kirk > On Jun 2, 2017, at 8:39 PM, Alexandr Nikitin <[email protected]> > wrote: > > Hi all, > > I encountered a strange behavior of JVM G1 GC. After a couple of hours of > normal work it shrinks the number of regions by 10 times. That causes a lot > of copying and promotions, GC times jump dramatically. After a dozen of those > unsuccessful collections it brings the number of regions back to the previous > normal number. Please help me understand its motivation. > > The full GC log: > https://gist.githubusercontent.com/alexandrnikitin/6e214dff1ba0f9c4930400c00ecfbdf9/raw/da7c941799e9a359c8ae3f612b503f8afae2dff0/full-strange-gc.log > > <https://gist.githubusercontent.com/alexandrnikitin/6e214dff1ba0f9c4930400c00ecfbdf9/raw/da7c941799e9a359c8ae3f612b503f8afae2dff0/full-strange-gc.log> > The hiccup and healing part only: > https://gist.githubusercontent.com/alexandrnikitin/6e214dff1ba0f9c4930400c00ecfbdf9/raw/da7c941799e9a359c8ae3f612b503f8afae2dff0/strange-gc.log > > <https://gist.githubusercontent.com/alexandrnikitin/6e214dff1ba0f9c4930400c00ecfbdf9/raw/da7c941799e9a359c8ae3f612b503f8afae2dff0/strange-gc.log> > > Here's the transition part only. As you can see the first collection went > almost as usual - 180ms (usually 40-50ms) Then G1 decides to reduce number > of regions from 3762 to 310. GC took 1.80 secs after that. > 2017-06-02T18:46:56.010+0200: 10178.264: [GC pause (G1 Evacuation Pause) > (young) > Desired survivor size 7902068736 bytes, new threshold 15 (max 15) > - age 1: 3862296 bytes, 3862296 total > - age 2: 459784 bytes, 4322080 total > - age 3: 587472 bytes, 4909552 total > - age 4: 383864 bytes, 5293416 total > - age 5: 399064 bytes, 5692480 total > - age 6: 363896 bytes, 6056376 total > - age 7: 323632 bytes, 6380008 total > - age 8: 357584 bytes, 6737592 total > - age 9: 323312 bytes, 7060904 total > - age 10: 328672 bytes, 7389576 total > - age 11: 986184 bytes, 8375760 total > - age 12: 222176 bytes, 8597936 total > - age 13: 188536 bytes, 8786472 total > - age 14: 207232 bytes, 8993704 total > - age 15: 120168 bytes, 9113872 total > 10178.275: [G1Ergonomics (CSet Construction) start choosing CSet, > _pending_cards: 834913, predicted base time: 89.27 ms, remaining time: 110.73 > ms, target pause time: 200.00 ms] > 10178.275: [G1Ergonomics (CSet Construction) add young regions to CSet, > eden: 3762 regions, survivors: 1 regions, predicted young region time: 8.28 > ms] > 10178.275: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: > 3762 regions, survivors: 1 regions, old: 0 regions, predicted pause time: > 97.55 ms, target pause time: 200.00 ms] > 2017-06-02T18:46:56.121+0200: 10178.375: [SoftReference, 0 refs, 0.0011474 > secs]2017-06-02T18:46:56.122+0200: 10178.376: [WeakReference, 62 refs, > 0.0005960 secs]2017-06-02T18:46:56.123+0200: 10178.377: [FinalReference, 536 > refs, 0.0023264 secs]2017-06-02T18:46:56.125+0200: 10178.379: > [PhantomReference, 0 refs, 0 refs, 0.0014977 > secs]2017-06-02T18:46:56.127+0200: 10178.381: [JNI Weak Reference, 0.0000471 > secs], 0.1337364 secs] > [Parallel Time: 97.7 ms, GC Workers: 28] > [GC Worker Start (ms): Min: 10178276.8, Avg: 10178277.6, Max: > 10178278.2, Diff: 1.4] > [Ext Root Scanning (ms): Min: 0.0, Avg: 0.8, Max: 6.4, Diff: 6.4, Sum: > 23.4] > [Update RS (ms): Min: 86.6, Avg: 91.4, Max: 91.7, Diff: 5.2, Sum: > 2559.4] > [Processed Buffers: Min: 104, Avg: 118.4, Max: 143, Diff: 39, Sum: > 3315] > [Scan RS (ms): Min: 0.7, Avg: 1.0, Max: 1.1, Diff: 0.3, Sum: 26.9] > [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: > 0.7] > [Object Copy (ms): Min: 2.3, Avg: 2.5, Max: 3.0, Diff: 0.6, Sum: 71.2] > [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 12.1] > [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 28] > [GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: > 7.6] > [GC Worker Total (ms): Min: 95.7, Avg: 96.5, Max: 97.3, Diff: 1.6, Sum: > 2701.4] > [GC Worker End (ms): Min: 10178373.9, Avg: 10178374.1, Max: 10178374.3, > Diff: 0.4] > [Code Root Fixup: 0.1 ms] > [Code Root Purge: 0.0 ms] > [Clear CT: 9.0 ms] > [Other: 26.9 ms] > [Choose CSet: 0.0 ms] > [Ref Proc: 6.1 ms] > [Ref Enq: 0.2 ms] > [Redirty Cards: 0.3 ms] > [Humongous Register: 1.7 ms] > [Humongous Reclaim: 0.7 ms] > [Free CSet: 6.5 ms] > [Eden: 117.6G(117.6G)->0.0B(117.5G) Survivors: 32.0M->96.0M Heap: > 138.2G(196.0G)->20.6G(196.0G)] > [Times: user=2.99 sys=0.02, real=0.13 secs] > 2017-06-02T18:46:56.144+0200: 10178.398: Total time for which application > threads were stopped: 0.2457828 seconds, Stopping threads took: 0.1110667 > seconds > 2017-06-02T18:46:56.145+0200: 10178.399: Total time for which application > threads were stopped: 0.0006996 seconds, Stopping threads took: 0.0001565 > seconds > 2017-06-02T18:46:56.145+0200: 10178.399: Total time for which application > threads were stopped: 0.0003017 seconds, Stopping threads took: 0.0000817 > seconds > 2017-06-02T18:46:56.146+0200: 10178.400: Total time for which application > threads were stopped: 0.0002389 seconds, Stopping threads took: 0.0000372 > seconds > 2017-06-02T18:46:56.146+0200: 10178.400: Total time for which application > threads were stopped: 0.0002567 seconds, Stopping threads took: 0.0000476 > seconds > 2017-06-02T18:46:59.820+0200: 10182.074: Total time for which application > threads were stopped: 0.0006631 seconds, Stopping threads took: 0.0001533 > seconds > 2017-06-02T18:46:59.820+0200: 10182.074: Total time for which application > threads were stopped: 0.0002674 seconds, Stopping threads took: 0.0000527 > seconds > 2017-06-02T18:47:06.354+0200: 10188.608: [GC pause (G1 Evacuation Pause) > (young) > Desired survivor size 671088640 bytes, new threshold 15 (max 15) > - age 1: 49132824 bytes, 49132824 total > - age 2: 1745176 bytes, 50878000 total > - age 3: 417632 bytes, 51295632 total > - age 4: 411672 bytes, 51707304 total > - age 5: 371712 bytes, 52079016 total > - age 6: 377456 bytes, 52456472 total > - age 7: 344840 bytes, 52801312 total > - age 8: 317216 bytes, 53118528 total > - age 9: 331216 bytes, 53449744 total > - age 10: 302656 bytes, 53752400 total > - age 11: 282424 bytes, 54034824 total > - age 12: 733032 bytes, 54767856 total > - age 13: 221808 bytes, 54989664 total > - age 14: 170104 bytes, 55159768 total > - age 15: 179872 bytes, 55339640 total > 10188.608: [G1Ergonomics (CSet Construction) start choosing CSet, > _pending_cards: 898670, predicted base time: 105.76 ms, remaining time: 94.24 > ms, target pause time: 200.00 ms] > 10188.608: [G1Ergonomics (CSet Construction) add young regions to CSet, > eden: 310 regions, survivors: 3 regions, predicted young region time: 2434.15 > ms] > 10188.608: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 310 > regions, survivors: 3 regions, old: 0 regions, predicted pause time: 2539.91 > ms, target pause time: 200.00 ms] > 2017-06-02T18:47:08.146+0200: 10190.400: [SoftReference, 0 refs, 0.0010616 > secs]2017-06-02T18:47:08.147+0200: 10190.401: [WeakReference, 24 refs, > 0.0005880 secs]2017-06-02T18:47:08.148+0200: 10190.402: [FinalReference, 49 > refs, 0.0006509 secs]2017-06-02T18:47:08.149+0200: 10190.402: > [PhantomReference, 0 refs, 1 refs, 0.0010624 > secs]2017-06-02T18:47:08.150+0200: 10190.404: [JNI Weak Reference, 0.0000308 > secs], 1.8028711 secs] > [Parallel Time: 1790.9 ms, GC Workers: 28] > [GC Worker Start (ms): Min: 10188608.9, Avg: 10188609.3, Max: > 10188609.6, Diff: 0.7] > [Ext Root Scanning (ms): Min: 0.3, Avg: 0.7, Max: 2.6, Diff: 2.3, Sum: > 19.7] > [Update RS (ms): Min: 127.3, Avg: 128.9, Max: 129.7, Diff: 2.4, Sum: > 3608.7] > [Processed Buffers: Min: 89, Avg: 127.7, Max: 180, Diff: 91, Sum: > 3576] > [Scan RS (ms): Min: 582.3, Avg: 582.9, Max: 583.1, Diff: 0.9, Sum: > 16322.1] > [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.4, Diff: 0.4, Sum: > 0.5] > [Object Copy (ms): Min: 1073.9, Avg: 1074.5, Max: 1077.6, Diff: 3.7, > Sum: 30085.2] > [Termination (ms): Min: 0.0, Avg: 3.2, Max: 3.7, Diff: 3.7, Sum: 90.0] > [Termination Attempts: Min: 1, Avg: 780.6, Max: 959, Diff: 958, Sum: > 21856] > [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: > 2.6] > [GC Worker Total (ms): Min: 1789.9, Avg: 1790.3, Max: 1790.7, Diff: > 0.7, Sum: 50128.8] > [GC Worker End (ms): Min: 10190399.5, Avg: 10190399.6, Max: 10190399.7, > Diff: 0.2] > [Code Root Fixup: 0.1 ms] > [Code Root Purge: 0.0 ms] > [Clear CT: 0.7 ms] > [Other: 11.2 ms] > [Choose CSet: 0.0 ms] > [Ref Proc: 3.7 ms] > [Ref Enq: 0.2 ms] > [Redirty Cards: 4.2 ms] > [Humongous Register: 0.4 ms] > [Humongous Reclaim: 0.1 ms] > [Free CSet: 0.8 ms] > [Eden: 9920.0M(9920.0M)->0.0B(8736.0M) Survivors: 96.0M->1280.0M Heap: > 33.2G(196.0G)->24.9G(196.0G)] > [Times: user=35.11 sys=3.42, real=1.80 secs] > > > Thank you! > > -- > You received this message because you are subscribed to the Google Groups > "mechanical-sympathy" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected] > <mailto:[email protected]>. > For more options, visit https://groups.google.com/d/optout > <https://groups.google.com/d/optout>. -- You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. For more options, visit https://groups.google.com/d/optout.
