Why is this a problem? Are you seeing unacceptable slowness?
It's fairly common for Java to frequently do GC, the problem happens
when it uses stop-the-world GC. So unless you're seeing visibly
slow performance I'd say ignore it.
Curiously, increasing the Java heap a little bit sometimes helps
as I've seen situations where the GC recovers so little memory that
another GC cycle immediately occurs. That said I don't see evidence
of this in what you showed.
GCViewer is a nifty tool for visualizing the GC activity BTW.
Best,
Erick
On Mon, Feb 13, 2017 at 8:36 AM, Leon STRINGER
<leon.strin...@ntlworld.com> wrote:
> Hi,
>
> I get an issue where, when I'm deleting and adding Solr cores, it appears to
> go
> into a loop increasing CPU load and continually (every 2 seconds) logging to
> the
> garbage collection log.
>
> I had this problem with 6.1.0 so we've just upgraded to 6.4.1 and the issue
> still occurs. The entries being logged every 2 seconds are below (hope it's
> not
> too verbose). Obviously this means the log gets big quickly.
>
> We can work around the issue by restarting Solr but presumably something has
> gone wrong. Can anyone suggest if we're doing something incorrectly to cause
> this, or if it's an issue we can troubleshoot.
>
> Any advice gratefully received.
>
> On CentOS 7 with OpenJDK 1.8.0_91-b14.
>
> solr_gc.log.0.current logs the following every 2 seconds:
>
> 2017-02-13T16:19:11.230+0000: 5092.640: [GC (CMS Initial Mark) [1
> CMS-initial-mark: 225270K(393216K)] 225280K(502464K), 0.0030517 secs] [Times:
> user=0.01 sys=0.00, real=0.01 secs]
> 2017-02-13T16:19:11.234+0000: 5092.643: Total time for which application
> threads
> were stopped: 0.0033800 seconds, Stopping threads took: 0.0000473 seconds
> 2017-02-13T16:19:11.234+0000: 5092.643: [CMS-concurrent-mark-start]
> 2017-02-13T16:19:11.359+0000: 5092.769: [CMS-concurrent-mark: 0.125/0.125
> secs]
> [Times: user=0.50 sys=0.00, real=0.12 secs]
> 2017-02-13T16:19:11.359+0000: 5092.769: [CMS-concurrent-preclean-start]
> 2017-02-13T16:19:11.361+0000: 5092.771: [CMS-concurrent-preclean: 0.002/0.002
> secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
> 2017-02-13T16:19:11.362+0000: 5092.771: [GC (CMS Final Remark) [YG occupancy:
> 10
> K (109248 K)]{Heap before GC invocations=3236 (full 1150):
> par new generation total 109248K, used 10K [0x00000000e0000000,
> 0x00000000e8000000, 0x00000000e8000000)
> eden space 87424K, 0% used [0x00000000e0000000, 0x00000000e0001020,
> 0x00000000e5560000)
> from space 21824K, 0% used [0x00000000e6ab0000, 0x00000000e6ab1830,
> 0x00000000e8000000)
> to space 21824K, 0% used [0x00000000e5560000, 0x00000000e5560000,
> 0x00000000e6ab0000)
> concurrent mark-sweep generation total 393216K, used 225270K
> [0x00000000e8000000, 0x0000000100000000, 0x0000000100000000)
> Metaspace used 176850K, capacity 179580K, committed 181092K, reserved 1210368K
> class space used 18794K, capacity 19506K, committed 19836K, reserved 1048576K
> 2017-02-13T16:19:11.362+0000: 5092.771: [GC (CMS Final Remark)
> 2017-02-13T16:19:11.362+0000: 5092.771: [ParNew
> Desired survivor size 20112992 bytes, new threshold 8 (max 8)
> - age 2: 160 bytes, 160 total
> - age 4: 32 bytes, 192 total
> : 10K->6K(109248K), 0.0041872 secs] 225280K->225276K(502464K), 0.0042455 secs]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> Heap after GC invocations=3237 (full 1150):
> par new generation total 109248K, used 6K [0x00000000e0000000,
> 0x00000000e8000000, 0x00000000e8000000)
> eden space 87424K, 0% used [0x00000000e0000000, 0x00000000e0000000,
> 0x00000000e5560000)
> from space 21824K, 0% used [0x00000000e5560000, 0x00000000e5561830,
> 0x00000000e6ab0000)
> to space 21824K, 0% used [0x00000000e6ab0000, 0x00000000e6ab0000,
> 0x00000000e8000000)
> concurrent mark-sweep generation total 393216K, used 225270K
> [0x00000000e8000000, 0x0000000100000000, 0x0000000100000000)
> Metaspace used 176850K, capacity 179580K, committed 181092K, reserved 1210368K
> class space used 18794K, capacity 19506K, committed 19836K, reserved 1048576K
> }
> 2017-02-13T16:19:11.366+0000: 5092.775: [Rescan (parallel) , 0.0018980
> secs]2017-02-13T16:19:11.368+0000: 5092.777: [weak refs processing, 0.0004940
> secs]2017-02-13T16:19:11.368+0000: 5092.778: [class unloading, 0.0580950
> secs]2017-02-13T16:19:11.426+0000: 5092.836: [scrub symbol table, 0.0110875
> secs]2017-02-13T16:19:11.438+0000: 5092.847: [scrub string table, 0.0019072
> secs][1 CMS-remark: 225270K(393216K)] 225276K(502464K), 0.0780250 secs]
> [Times:
> user=0.09 sys=0.00, real=0.08 secs]
> 2017-02-13T16:19:11.440+0000: 5092.849: Total time for which application
> threads
> were stopped: 0.0782677 seconds, Stopping threads took: 0.0000411 seconds
> 2017-02-13T16:19:11.440+0000: 5092.849: [CMS-concurrent-sweep-start]
> 2017-02-13T16:19:11.546+0000: 5092.955: [CMS-concurrent-sweep: 0.106/0.106
> secs]
> [Times: user=0.11 sys=0.00, real=0.11 secs]
> 2017-02-13T16:19:11.546+0000: 5092.955: [CMS-concurrent-reset-start]
> 2017-02-13T16:19:11.546+0000: 5092.956: [CMS-concurrent-reset: 0.001/0.001
> secs]
> [Times: user=0.00 sys=0.00, real=0.00 secs]
>
> Regards,
>
> Leon Stringer
