[sakai-dev] GC memory leak with java.lang.ref.Finalizer / BaseAnnouncementService

classic Classic list List threaded Threaded
4 messages Options
Austin Nakasone Austin Nakasone
Reply | Threaded
Open this post in threaded view
|

[sakai-dev] GC memory leak with java.lang.ref.Finalizer / BaseAnnouncementService

Hello Sakai Devs,

Yesterday we experienced an issue where GC was looping over and over causing some performance issues on one of our servers.

We're running:

Sakai 11.4
Tomcat 8.0.47
Java 1.8.0_151
MySQL 5.6
RHEL 7

with these Java opts (these aren't all of them, but the ones that are mem. related):

-Xmx10280m 
-Xms10280m 
-XX:MaxMetaspaceSize=1024m 
-Xmn2500m 
-XX:+UseConcMarkSweepGC 
-XX:+UseParNewGC 
-XX:CMSInitiatingOccupancyFraction=80 
-XX:+DisableExplicitGC 
-XX:+DoEscapeAnalysis 
-verbose:gc 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 

The error in the logs that keep looping over and over are:

47863.032: [CMS-concurrent-preclean: 5.037/5.037 secs] [Times: user=5.35 sys=0.04, real=5.04 secs] 
47863.032: [CMS-concurrent-abortable-preclean-start]
47863.032: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
47863.033: [GC (CMS Final Remark) [YG occupancy: 1542954 K (2304000 K)]47863.033: [Rescan (parallel) , 0.3890201 secs]47863.423: [weak refs processing, 0.0000592 secs]47863.423: [class unloading, 0.2006707 secs]47863.623: [scrub symbol table, 0.0485713 secs]47863.672: [scrub string table, 0.0086044 secs][1 CMS-remark: 7966719K(7966720K)] 9509674K(10270720K), 0.6472521 secs] [Times: user=2.06 sys=0.02, real=0.65 secs] 
47863.682: [CMS-concurrent-sweep-start]
47865.226: [CMS-concurrent-sweep: 1.544/1.544 secs] [Times: user=1.58 sys=0.01, real=1.54 secs] 
47865.226: [CMS-concurrent-reset-start]
47865.241: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
06-Feb-2018 16:40:56.125 DEBUG [ajp-bio-8009-exec-309] edu.gatech.sakai.user.impl.GaTechUserDirectoryServiceImpl.authorizeUserLogin authorizeUserLogin; user.eid; gasconm; user.email: [hidden email]
47867.243: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7966695K(7966720K)] 9965851K(10270720K), 0.3508320 secs] [Times: user=0.93 sys=0.00, real=0.35 secs] 
47867.594: [CMS-concurrent-mark-start]
47871.695: [CMS-concurrent-mark: 4.099/4.101 secs] [Times: user=8.48 sys=0.03, real=4.10 secs] 
47871.695: [CMS-concurrent-preclean-start]
47871.739: [CMS-concurrent-preclean: 0.041/0.044 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
47871.739: [CMS-concurrent-abortable-preclean-start]
47871.739: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
47871.740: [GC (CMS Final Remark) [YG occupancy: 2083498 K (2304000 K)]47871.741: [Rescan (parallel) , 0.5782041 secs]47872.319: [weak refs processing, 0.0000354 secs]47872.319: [class unloading, 0.1000239 secs]47872.419: [scrub symbol table, 0.0407029 secs]47872.460: [scrub string table, 0.0067250 secs][1 CMS-remark: 7966695K(7966720K)] 10050194K(10270720K), 0.7260444 secs] [Times: user=2.95 sys=0.01, real=0.72 secs] 

While the problem was happening I took a heap dump with jmap and upon analyzing it with Eclipse Memory Analyzer, it said that there was a leak with

java.lang.ref.Finalizer

and it was taking up 61% of the heap.  Digging a little deeper, the first 10 or 20 of those objects (out of 8million?) were coming from

BaseAnnouncementService

and of those 10 or 20 they all seemed to coming from the same site, which appeared to have an announcement that included an <img> tag(s) with base64 image data.  I'm not sure if the content of the announcement had anything to do with it or if the instructor did something specific and the content is irrelevant. 

Has anyone seen anything like this?  Is it a memory leak in the Announcement tool?  Or do we need to tune our Memory settings to improve the GC?

Thanks,

Austin

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

memory_leak1.png (131K) Download Attachment
memory_leak2.png (211K) Download Attachment
memory_leak3.png (536K) Download Attachment
Austin Nakasone Austin Nakasone
Reply | Threaded
Open this post in threaded view
|

Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer / BaseAnnouncementService

Thanks Hendrik!

On Wed, Feb 7, 2018 at 4:01 PM, Hendrik Steller <[hidden email]> wrote:
On Donnerstag, 8. Februar 2018 02:04:16 CET Austin wrote:

> Creating a "secret JSP" that runs System.runFinalization() sounds
> interesting, but I might need a little help getting started with that.

1. Copy the code below into a file with a top secret name of your choice
ending in ".jsp"  (e.g.  "thats_totally_secure.jsp")

2. Copy that file into the root folder of a webapp of your choice (e.g.
tomcat/webapps/foobar)

Now  you (well, and everyone else..) can call the JSP directly by opening the
URL http://server/foobar/thats_totally_secure.jsp
Or, if you copy the file into tomcat/webapps/ROOT, you can call it via
http://server/thats_totally_secure.jsp

(3.)
Delete the file again / move it out of the webapp's folder once you don't need
it anymore.

Hendrik

Code (also attached):


<%@page import="java.util.Date"%>
<%@ page language="java" contentType="text/html; charset=UTF-8"
pageEncoding="UTF-8"%>
<%!
        private static Date lastFinalize;
        private static Date lastGC;
%>
<%
        if ("post".equalsIgnoreCase(request.getMethod())) {
                final String action = request.getParameter("whatdo");
                if ("finalize".equals(action)) {
                        lastFinalize = new Date();
                        System.runFinalization();
                }
                else if ("gc".equals(action)) {
                        lastGC = new Date();
                        System.gc();
                }
        }
%>
<html>
        <head><title>Top secret JSP</title></head>
        <body>
                <div>
                        <form action="" method="POST">
                                <span>Last manual finalize run: <%=lastFinalize != null ?
lastFinalize : "never"%></span> <input type="submit"
                                        value="Run finalize"> <input type="hidden" name="whatdo"
value="finalize">
                        </form>
                </div>
                <div>
                        <form action="" method="POST">
                                <span>Last manual garbage collection: <%=lastGC != null ? lastGC :
"never"%></span> <input type="submit" value="Force GC">
                                <input type="hidden" name="whatdo" value="gc">
                        </form>
                </div>
        </body>
</html>

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.
Austin Nakasone Austin Nakasone
Reply | Threaded
Open this post in threaded view
|

Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer / BaseAnnouncementService

Does anyone know which comes first (or how I can find out) ... 

if the heap fills up with Finalizer objects, then the [CMS-concurrent-reset-start] is unable to process them causing it to keep looping?

Or...

does the [CMS-concurrent-reset-start] fail first (for some other reason), making the heap fill up with Finalizer objects?

On Wed, Feb 7, 2018 at 4:15 PM, Austin <[hidden email]> wrote:
Thanks Hendrik!

On Wed, Feb 7, 2018 at 4:01 PM, Hendrik Steller <[hidden email]> wrote:
On Donnerstag, 8. Februar 2018 02:04:16 CET Austin wrote:

> Creating a "secret JSP" that runs System.runFinalization() sounds
> interesting, but I might need a little help getting started with that.

1. Copy the code below into a file with a top secret name of your choice
ending in ".jsp"  (e.g.  "thats_totally_secure.jsp")

2. Copy that file into the root folder of a webapp of your choice (e.g.
tomcat/webapps/foobar)

Now  you (well, and everyone else..) can call the JSP directly by opening the
URL http://server/foobar/thats_totally_secure.jsp
Or, if you copy the file into tomcat/webapps/ROOT, you can call it via
http://server/thats_totally_secure.jsp

(3.)
Delete the file again / move it out of the webapp's folder once you don't need
it anymore.

Hendrik

Code (also attached):


<%@page import="java.util.Date"%>
<%@ page language="java" contentType="text/html; charset=UTF-8"
pageEncoding="UTF-8"%>
<%!
        private static Date lastFinalize;
        private static Date lastGC;
%>
<%
        if ("post".equalsIgnoreCase(request.getMethod())) {
                final String action = request.getParameter("whatdo");
                if ("finalize".equals(action)) {
                        lastFinalize = new Date();
                        System.runFinalization();
                }
                else if ("gc".equals(action)) {
                        lastGC = new Date();
                        System.gc();
                }
        }
%>
<html>
        <head><title>Top secret JSP</title></head>
        <body>
                <div>
                        <form action="" method="POST">
                                <span>Last manual finalize run: <%=lastFinalize != null ?
lastFinalize : "never"%></span> <input type="submit"
                                        value="Run finalize"> <input type="hidden" name="whatdo"
value="finalize">
                        </form>
                </div>
                <div>
                        <form action="" method="POST">
                                <span>Last manual garbage collection: <%=lastGC != null ? lastGC :
"never"%></span> <input type="submit" value="Force GC">
                                <input type="hidden" name="whatdo" value="gc">
                        </form>
                </div>
        </body>
</html>


--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.
Austin Nakasone Austin Nakasone
Reply | Threaded
Open this post in threaded view
|

Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer / BaseAnnouncementService

In reply to this post by Austin Nakasone
Hello Matthew,

Sorry, I'm new to MAT.  I'm not sure if I'm looking in the right place...

The Finalizer thread stats show:

Type|Name       |Value
-----------------------------------------------------------
ref |lock       |java.lang.Object @ 0x5e0e9aad0
ref |unfinalized|java.lang.ref.Finalizer @ 0x55ab72458
ref |queue      |java.lang.ref.ReferenceQueue @ 0x5d9c07f90
-----------------------------------------------------------

Also the thread details says that the thread name is NULL.  I'm not sure if that's expected?

Thanks,

Austin


On Thu, Feb 8, 2018 at 9:05 AM, Matthew Buckett <[hidden email]> wrote:
Are you able to look at a thread dump and see the state of the finalizer thread(s), it sounds like they may have become stuck and although the the announcement objects are in the queue are they the ones currently being processed?

As Hendrik mentioned Sakai does lots of scary stuff in finalizers (like making database calls) so this could well be where it's got stuck.

On 8 February 2018 at 18:20, Austin <[hidden email]> wrote:
Does anyone know which comes first (or how I can find out) ... 

if the heap fills up with Finalizer objects, then the [CMS-concurrent-reset-start] is unable to process them causing it to keep looping?

Or...

does the [CMS-concurrent-reset-start] fail first (for some other reason), making the heap fill up with Finalizer objects?

On Wed, Feb 7, 2018 at 4:15 PM, Austin <[hidden email]> wrote:
Thanks Hendrik!

On Wed, Feb 7, 2018 at 4:01 PM, Hendrik Steller <[hidden email]> wrote:
On Donnerstag, 8. Februar 2018 02:04:16 CET Austin wrote:

> Creating a "secret JSP" that runs System.runFinalization() sounds
> interesting, but I might need a little help getting started with that.

1. Copy the code below into a file with a top secret name of your choice
ending in ".jsp"  (e.g.  "thats_totally_secure.jsp")

2. Copy that file into the root folder of a webapp of your choice (e.g.
tomcat/webapps/foobar)

Now  you (well, and everyone else..) can call the JSP directly by opening the
URL http://server/foobar/thats_totally_secure.jsp
Or, if you copy the file into tomcat/webapps/ROOT, you can call it via
http://server/thats_totally_secure.jsp

(3.)
Delete the file again / move it out of the webapp's folder once you don't need
it anymore.

Hendrik

Code (also attached):


<%@page import="java.util.Date"%>
<%@ page language="java" contentType="text/html; charset=UTF-8"
pageEncoding="UTF-8"%>
<%!
        private static Date lastFinalize;
        private static Date lastGC;
%>
<%
        if ("post".equalsIgnoreCase(request.getMethod())) {
                final String action = request.getParameter("whatdo");
                if ("finalize".equals(action)) {
                        lastFinalize = new Date();
                        System.runFinalization();
                }
                else if ("gc".equals(action)) {
                        lastGC = new Date();
                        System.gc();
                }
        }
%>
<html>
        <head><title>Top secret JSP</title></head>
        <body>
                <div>
                        <form action="" method="POST">
                                <span>Last manual finalize run: <%=lastFinalize != null ?
lastFinalize : "never"%></span> <input type="submit"
                                        value="Run finalize"> <input type="hidden" name="whatdo"
value="finalize">
                        </form>
                </div>
                <div>
                        <form action="" method="POST">
                                <span>Last manual garbage collection: <%=lastGC != null ? lastGC :
"never"%></span> <input type="submit" value="Force GC">
                                <input type="hidden" name="whatdo" value="gc">
                        </form>
                </div>
        </body>
</html>


--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.



--
  Matthew Buckett, Senior VLE Developer

  Systems and Applications, Technology Enhanced Learning
  IT Services, University of Oxford
  13 Banbury Road, OX2 6NN
  Tel: 01865 283349

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

thread detail.png (113K) Download Attachment
thread stats.png (269K) Download Attachment