Why is this a problem? CPU load and log file size.
The CPU load reported by top increases from it's normal 0-1% resting state to
25-50% continually, and higher when searching, indexing, etc.
With 6.1.0 we just got a huge GC log file. With 6.4.1 the GC log is now cycled
before it grows too large, but it does mean that they are quickly cycled (every
3 hours).
Operations seem much slower in this state but I haven't collected figures for
this.
When Solr gets into this state it stays like it until it's restarted.
Thanks,
Leon Stringer
>
> On 14 February 2017 at 05:45 Erick Erickson <erickerick...@gmail.com>
> wrote:
>
>
> 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
>
