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 The hiccup and healing part only: 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]. For more options, visit https://groups.google.com/d/optout.
