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

classic Classic list List threaded Threaded
14 messages Options
Sam Ottenhoff Sam Ottenhoff
Reply | Threaded
Open this post in threaded view
|

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

Hi Austin,

Eclipse MAT is showing you the retained heap locations at your snapshot time, but it's not accurate to say there is a leak in java.lang.ref.Finalizer. There is a lot of good info on Finalizer on the web. Here is one good resource:


Here are two important paragraphs from that doc:

Any instances of classes that implement the finalize() method are often called finalizable objects. They will not be immediately reclaimed by the Java garbage collector when they are no longer referenced. Instead, the Java garbage collector appends the objects to a special queue for the finalization process. Usually it's performed by a special thread called a "Reference Handler" on some Java Virtual Machines. During this finalization process, the "Finalizer" thread will execute each finalize() method of the objects. Only after successful completion of the finalize() method will an object be handed over for Java garbage collection to get its space reclaimed by "future" garbage collection. I did not say "current," which means at least two garbage collection cycles are required to reclaim the finalizable object. Sounds like it has some overhead? You got it. We need several shots to get the space recycled.

Finalizer threads are not given maximum priorities on systems. If a "Finalizer" thread cannot keep up with the rate at which higher priority threads cause finalizable objects to be queued, the finalizer queue will keep growing and cause the Java heap to fill up. Eventually the Java heap will get exhausted and a java.lang.OutOfMemoryError will be thrown.



On Wed, Feb 7, 2018 at 3:15 PM, Austin <[hidden email]> wrote:
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/.

--
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/.
Hendrik Steller Hendrik Steller
Reply | Threaded
Open this post in threaded view
|

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

----------  Forwarded Message  ----------
Subject: Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer
BaseAnnouncementService
Date: Donnerstag, 8. Februar 2018, 00:51:06 CET

On Mittwoch, 7. Februar 2018 21:15:09 CET Austin wrote:
> 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?

java.lang.Object has a method called finalize().
If a class overrides this (AFAIK empty by default) method, it makes garbage
collection more tricky.  Those objects can't be destroyed immediately when the
JVM thinks that they're ready to be garbage collected, because their
finalize()-method has to be called first.
To that end, they're stuffed into a queue and a rather low-priority
"finalizer"-thread walks by and pops elements off that queue and calls their  
finalize-method.

Potential Problem 1:
Objects can be queued faster than the low-priority thread removes them.
Potential Problem 2:
People can do stupid sh*t inside their finalize() method which might delay or
block the finalizer thread; think deadlocks, infinite loops, hanging
connections [1], ..

So there seem to be a couple of basic rules regarding overriding "finalize":
1. Don't do it
2. If you do it anyway, the implementation should return quickly and naturally
not hang, so it's probably a good idea to avoid expensive stuff, stuff that
needs locking or stuff that might have to wait for network connections or
other system.

.so I did a quick grep over the Sakai 11.4  source for "void finalize" [2]
and found that Sakai seems to do all of that:
Several classes override finalize and some seem to do stuff which looks rather
dangerous for doing it in a finalize.
For example, I still had the AssignmentService open in eclipse and tried  
following the calls in the finalize-implementations of one of the inner edit-
classes. This took me to
org.sakaiproject.util.BaseDbSingleStorage#cancelResource(Edit)

Without trying to really understand it or thinking it through, there seem to
be at least three things happening which would make me hesitate to call them
from an overridden  finalize():
* using synchronization (accessing a hashtable in this case)
* making database calls, likely across a  network in many cases
* doing something with locks; I didn't actually look if those edit locks being
released there are just some flags sakai sets in one of its own tables or if
there are "actual" db locks involved (like explicitly doing "lock table"s etc)


In case the problem occurs again,  it might be worth a try to deploy a button
which calls System.runFinalization() (or just copy a "secret"  JSP with a
scriplet into an existing webapp or the ROOT context and call that JSP) .
Because should the JVM start a separate finalizer thread for that call and
should the problem be that the original finalizer thread is blocked by a
single object e.g. waiting for a hanging connection and not some general
problem, then a potential second finalizer thread might be able to empty the
queue.

Regards,
  Hendrik

[1]
"Fun"  possibly relataed fact which I learned the hard way once:
by default, java.net.URLConnection uses an "infinite" read timeout,  i.e. if
you don't take special care, your program can end up waiting forever for a
ressource  which isn't available anymore.

[2]
If there's more than one match in one class file, it's likely because there
are inner classes overriding finalize() - for example, in case of the
AssignmentService, there seem to be several inner "AssignmentEdit"-classes

$> grep -r "void\s*finalize\s*(" | grep .java | grep -iv test
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BasePreferencesService.java:                
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BaseUserDirectoryService.java:              protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/alias/impl/
BaseAliasService.java:            
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/db/impl/
BasicSqlService.java:        
protected void finalize() {
kernel/kernel-impl/src/main/java/org/sakaiproject/event/impl/
BaseNotificationService.java:              
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:        
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:        
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/email/impl/
BaseDigestService.java:            
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:              
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:              
protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
chat/chat-tool/tool/src/java/org/sakaiproject/chat2/tool/
PresenceObserverHelper.java:  
protected void finalize()
providers/jldap/src/java/edu/amc/sakai/user/PooledLDAPConnection.java:  
protected void
finalize() throws LDAPException {
common/archive-api/src/main/java/org/sakaiproject/importer/api/
ResetOnCloseInputStream.java:    public void finalize() throws IOException{




--
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

Thanks Sam and Hendrik,

By coincidence (or stroke of bad luck), the same problem happened again today.  Actually, I believe we see these quite often, but usually it occurs at night so our users aren't impacted as much.  After taking a heap dump, Eclipse MAT showed the same issue with Finalizer and most of the first 20 or so objects listed had to do with Announcements again... and they looked like the exact same announcements as yesterday.  I'm sure the list of objects referenced with Finalizer is quite long, I can't say for certain that most of them have to do with announcement, but it sure is suspicious that the first bunch are announcements.

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

However, while clearing out the finalizer with a secret jsp, would be a great feature, I'd prefer to find the root cause.  l would like to know how our system is getting into that state.  Is a user doing something to suddenly trigger it?  Or is it an accumulation over time?  I suspect it's user triggered because usually it only happens on one server at a time (but not always), it doesn't happen every day, and we restart tomcat every morning, so anything accumulated would have been cleared in the morning.

On Wed, Feb 7, 2018 at 2:49 PM, Hendrik Steller <[hidden email]> wrote:
----------  Forwarded Message  ----------
Subject: Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer
BaseAnnouncementService
Date: Donnerstag, 8. Februar 2018, 00:51:06 CET

On Mittwoch, 7. Februar 2018 21:15:09 CET Austin wrote:
> 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?

java.lang.Object has a method called finalize().
If a class overrides this (AFAIK empty by default) method, it makes garbage
collection more tricky.  Those objects can't be destroyed immediately when the
JVM thinks that they're ready to be garbage collected, because their
finalize()-method has to be called first.
To that end, they're stuffed into a queue and a rather low-priority
"finalizer"-thread walks by and pops elements off that queue and calls their
finalize-method.

Potential Problem 1:
Objects can be queued faster than the low-priority thread removes them.
Potential Problem 2:
People can do stupid sh*t inside their finalize() method which might delay or
block the finalizer thread; think deadlocks, infinite loops, hanging
connections [1], ..

So there seem to be a couple of basic rules regarding overriding "finalize":
1. Don't do it
2. If you do it anyway, the implementation should return quickly and naturally
not hang, so it's probably a good idea to avoid expensive stuff, stuff that
needs locking or stuff that might have to wait for network connections or
other system.

.so I did a quick grep over the Sakai 11.4  source for "void finalize" [2]
and found that Sakai seems to do all of that:
Several classes override finalize and some seem to do stuff which looks rather
dangerous for doing it in a finalize.
For example, I still had the AssignmentService open in eclipse and tried
following the calls in the finalize-implementations of one of the inner edit-
classes. This took me to
org.sakaiproject.util.BaseDbSingleStorage#cancelResource(Edit)

Without trying to really understand it or thinking it through, there seem to
be at least three things happening which would make me hesitate to call them
from an overridden  finalize():
* using synchronization (accessing a hashtable in this case)
* making database calls, likely across a  network in many cases
* doing something with locks; I didn't actually look if those edit locks being
released there are just some flags sakai sets in one of its own tables or if
there are "actual" db locks involved (like explicitly doing "lock table"s etc)


In case the problem occurs again,  it might be worth a try to deploy a button
which calls System.runFinalization() (or just copy a "secret"  JSP with a
scriplet into an existing webapp or the ROOT context and call that JSP) .
Because should the JVM start a separate finalizer thread for that call and
should the problem be that the original finalizer thread is blocked by a
single object e.g. waiting for a hanging connection and not some general
problem, then a potential second finalizer thread might be able to empty the
queue.

Regards,
  Hendrik

[1]
"Fun"  possibly relataed fact which I learned the hard way once:
by default, java.net.URLConnection uses an "infinite" read timeout,  i.e. if
you don't take special care, your program can end up waiting forever for a
ressource  which isn't available anymore.

[2]
If there's more than one match in one class file, it's likely because there
are inner classes overriding finalize() - for example, in case of the
AssignmentService, there seem to be several inner "AssignmentEdit"-classes

$> grep -r "void\s*finalize\s*(" | grep .java | grep -iv test
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BasePreferencesService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BaseUserDirectoryService.java:              protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/alias/impl/
BaseAliasService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/db/impl/
BasicSqlService.java:
protected void finalize() {
kernel/kernel-impl/src/main/java/org/sakaiproject/event/impl/
BaseNotificationService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/email/impl/
BaseDigestService.java:
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:
protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
chat/chat-tool/tool/src/java/org/sakaiproject/chat2/tool/
PresenceObserverHelper.java:
protected void finalize()
providers/jldap/src/java/edu/amc/sakai/user/PooledLDAPConnection.java:
protected void
finalize() throws LDAPException {
common/archive-api/src/main/java/org/sakaiproject/importer/api/
ResetOnCloseInputStream.java:    public void finalize() throws IOException{





--
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/.
Sam Ottenhoff Sam Ottenhoff
Reply | Threaded
Open this post in threaded view
|

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

How many CPUs do you have allocated to this machine? A 10GB heap is large and will need lots of processing to cleanup. Why is CMSInitiatingOccupancyFraction set?

On Wed, Feb 7, 2018 at 8:04 PM, Austin <[hidden email]> wrote:
Thanks Sam and Hendrik,

By coincidence (or stroke of bad luck), the same problem happened again today.  Actually, I believe we see these quite often, but usually it occurs at night so our users aren't impacted as much.  After taking a heap dump, Eclipse MAT showed the same issue with Finalizer and most of the first 20 or so objects listed had to do with Announcements again... and they looked like the exact same announcements as yesterday.  I'm sure the list of objects referenced with Finalizer is quite long, I can't say for certain that most of them have to do with announcement, but it sure is suspicious that the first bunch are announcements.

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

However, while clearing out the finalizer with a secret jsp, would be a great feature, I'd prefer to find the root cause.  l would like to know how our system is getting into that state.  Is a user doing something to suddenly trigger it?  Or is it an accumulation over time?  I suspect it's user triggered because usually it only happens on one server at a time (but not always), it doesn't happen every day, and we restart tomcat every morning, so anything accumulated would have been cleared in the morning.

On Wed, Feb 7, 2018 at 2:49 PM, Hendrik Steller <[hidden email]> wrote:
----------  Forwarded Message  ----------
Subject: Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer
BaseAnnouncementService
Date: Donnerstag, 8. Februar 2018, 00:51:06 CET

On Mittwoch, 7. Februar 2018 21:15:09 CET Austin wrote:
> 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?

java.lang.Object has a method called finalize().
If a class overrides this (AFAIK empty by default) method, it makes garbage
collection more tricky.  Those objects can't be destroyed immediately when the
JVM thinks that they're ready to be garbage collected, because their
finalize()-method has to be called first.
To that end, they're stuffed into a queue and a rather low-priority
"finalizer"-thread walks by and pops elements off that queue and calls their
finalize-method.

Potential Problem 1:
Objects can be queued faster than the low-priority thread removes them.
Potential Problem 2:
People can do stupid sh*t inside their finalize() method which might delay or
block the finalizer thread; think deadlocks, infinite loops, hanging
connections [1], ..

So there seem to be a couple of basic rules regarding overriding "finalize":
1. Don't do it
2. If you do it anyway, the implementation should return quickly and naturally
not hang, so it's probably a good idea to avoid expensive stuff, stuff that
needs locking or stuff that might have to wait for network connections or
other system.

.so I did a quick grep over the Sakai 11.4  source for "void finalize" [2]
and found that Sakai seems to do all of that:
Several classes override finalize and some seem to do stuff which looks rather
dangerous for doing it in a finalize.
For example, I still had the AssignmentService open in eclipse and tried
following the calls in the finalize-implementations of one of the inner edit-
classes. This took me to
org.sakaiproject.util.BaseDbSingleStorage#cancelResource(Edit)

Without trying to really understand it or thinking it through, there seem to
be at least three things happening which would make me hesitate to call them
from an overridden  finalize():
* using synchronization (accessing a hashtable in this case)
* making database calls, likely across a  network in many cases
* doing something with locks; I didn't actually look if those edit locks being
released there are just some flags sakai sets in one of its own tables or if
there are "actual" db locks involved (like explicitly doing "lock table"s etc)


In case the problem occurs again,  it might be worth a try to deploy a button
which calls System.runFinalization() (or just copy a "secret"  JSP with a
scriplet into an existing webapp or the ROOT context and call that JSP) .
Because should the JVM start a separate finalizer thread for that call and
should the problem be that the original finalizer thread is blocked by a
single object e.g. waiting for a hanging connection and not some general
problem, then a potential second finalizer thread might be able to empty the
queue.

Regards,
  Hendrik

[1]
"Fun"  possibly relataed fact which I learned the hard way once:
by default, java.net.URLConnection uses an "infinite" read timeout,  i.e. if
you don't take special care, your program can end up waiting forever for a
ressource  which isn't available anymore.

[2]
If there's more than one match in one class file, it's likely because there
are inner classes overriding finalize() - for example, in case of the
AssignmentService, there seem to be several inner "AssignmentEdit"-classes

$> grep -r "void\s*finalize\s*(" | grep .java | grep -iv test
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BasePreferencesService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BaseUserDirectoryService.java:              protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/alias/impl/
BaseAliasService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/db/impl/
BasicSqlService.java:
protected void finalize() {
kernel/kernel-impl/src/main/java/org/sakaiproject/event/impl/
BaseNotificationService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/email/impl/
BaseDigestService.java:
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:
protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
chat/chat-tool/tool/src/java/org/sakaiproject/chat2/tool/
PresenceObserverHelper.java:
protected void finalize()
providers/jldap/src/java/edu/amc/sakai/user/PooledLDAPConnection.java:
protected void
finalize() throws LDAPException {
common/archive-api/src/main/java/org/sakaiproject/importer/api/
ResetOnCloseInputStream.java:    public void finalize() throws IOException{





--
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/.

--
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

Hello Sam,

Each of our 6 user facing servers has:

6 vCPUs / 16G RAM

we copied CMSInitiatingOccupancyFraction the setting from:  https://confluence.sakaiproject.org/display/PROD/Rutgers+performance+tuning+experience

On Wed, Feb 7, 2018 at 3:08 PM, Sam Ottenhoff <[hidden email]> wrote:
How many CPUs do you have allocated to this machine? A 10GB heap is large and will need lots of processing to cleanup. Why is CMSInitiatingOccupancyFraction set?

On Wed, Feb 7, 2018 at 8:04 PM, Austin <[hidden email]> wrote:
Thanks Sam and Hendrik,

By coincidence (or stroke of bad luck), the same problem happened again today.  Actually, I believe we see these quite often, but usually it occurs at night so our users aren't impacted as much.  After taking a heap dump, Eclipse MAT showed the same issue with Finalizer and most of the first 20 or so objects listed had to do with Announcements again... and they looked like the exact same announcements as yesterday.  I'm sure the list of objects referenced with Finalizer is quite long, I can't say for certain that most of them have to do with announcement, but it sure is suspicious that the first bunch are announcements.

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

However, while clearing out the finalizer with a secret jsp, would be a great feature, I'd prefer to find the root cause.  l would like to know how our system is getting into that state.  Is a user doing something to suddenly trigger it?  Or is it an accumulation over time?  I suspect it's user triggered because usually it only happens on one server at a time (but not always), it doesn't happen every day, and we restart tomcat every morning, so anything accumulated would have been cleared in the morning.

On Wed, Feb 7, 2018 at 2:49 PM, Hendrik Steller <[hidden email]> wrote:
----------  Forwarded Message  ----------
Subject: Re: [sakai-dev] GC memory leak with java.lang.ref.Finalizer
BaseAnnouncementService
Date: Donnerstag, 8. Februar 2018, 00:51:06 CET

On Mittwoch, 7. Februar 2018 21:15:09 CET Austin wrote:
> 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?

java.lang.Object has a method called finalize().
If a class overrides this (AFAIK empty by default) method, it makes garbage
collection more tricky.  Those objects can't be destroyed immediately when the
JVM thinks that they're ready to be garbage collected, because their
finalize()-method has to be called first.
To that end, they're stuffed into a queue and a rather low-priority
"finalizer"-thread walks by and pops elements off that queue and calls their
finalize-method.

Potential Problem 1:
Objects can be queued faster than the low-priority thread removes them.
Potential Problem 2:
People can do stupid sh*t inside their finalize() method which might delay or
block the finalizer thread; think deadlocks, infinite loops, hanging
connections [1], ..

So there seem to be a couple of basic rules regarding overriding "finalize":
1. Don't do it
2. If you do it anyway, the implementation should return quickly and naturally
not hang, so it's probably a good idea to avoid expensive stuff, stuff that
needs locking or stuff that might have to wait for network connections or
other system.

.so I did a quick grep over the Sakai 11.4  source for "void finalize" [2]
and found that Sakai seems to do all of that:
Several classes override finalize and some seem to do stuff which looks rather
dangerous for doing it in a finalize.
For example, I still had the AssignmentService open in eclipse and tried
following the calls in the finalize-implementations of one of the inner edit-
classes. This took me to
org.sakaiproject.util.BaseDbSingleStorage#cancelResource(Edit)

Without trying to really understand it or thinking it through, there seem to
be at least three things happening which would make me hesitate to call them
from an overridden  finalize():
* using synchronization (accessing a hashtable in this case)
* making database calls, likely across a  network in many cases
* doing something with locks; I didn't actually look if those edit locks being
released there are just some flags sakai sets in one of its own tables or if
there are "actual" db locks involved (like explicitly doing "lock table"s etc)


In case the problem occurs again,  it might be worth a try to deploy a button
which calls System.runFinalization() (or just copy a "secret"  JSP with a
scriplet into an existing webapp or the ROOT context and call that JSP) .
Because should the JVM start a separate finalizer thread for that call and
should the problem be that the original finalizer thread is blocked by a
single object e.g. waiting for a hanging connection and not some general
problem, then a potential second finalizer thread might be able to empty the
queue.

Regards,
  Hendrik

[1]
"Fun"  possibly relataed fact which I learned the hard way once:
by default, java.net.URLConnection uses an "infinite" read timeout,  i.e. if
you don't take special care, your program can end up waiting forever for a
ressource  which isn't available anymore.

[2]
If there's more than one match in one class file, it's likely because there
are inner classes overriding finalize() - for example, in case of the
AssignmentService, there seem to be several inner "AssignmentEdit"-classes

$> grep -r "void\s*finalize\s*(" | grep .java | grep -iv test
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BasePreferencesService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/user/impl/
BaseUserDirectoryService.java:              protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/alias/impl/
BaseAliasService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/db/impl/
BasicSqlService.java:
protected void finalize() {
kernel/kernel-impl/src/main/java/org/sakaiproject/event/impl/
BaseNotificationService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/content/impl/
BaseContentService.java:
protected void finalize()
kernel/kernel-impl/src/main/java/org/sakaiproject/email/impl/
BaseDigestService.java:
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:
protected void finalize()
message/message-util/util/src/java/org/sakaiproject/message/util/
BaseMessage.java:
protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
assignment/assignment-impl/impl/src/java/org/sakaiproject/assignment/impl/
BaseAssignmentService.java:           protected void finalize()
chat/chat-tool/tool/src/java/org/sakaiproject/chat2/tool/
PresenceObserverHelper.java:
protected void finalize()
providers/jldap/src/java/edu/amc/sakai/user/PooledLDAPConnection.java:
protected void
finalize() throws LDAPException {
common/archive-api/src/main/java/org/sakaiproject/importer/api/
ResetOnCloseInputStream.java:    public void finalize() throws IOException{





--
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/.


--
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/.
Hendrik Steller Hendrik Steller
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
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/.

finalize.jsp (1K) Download Attachment
Matthew Buckett-2 Matthew Buckett-2
Reply | Threaded
Open this post in threaded view
|

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

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/.
Matthew Jones-2 Matthew Jones-2
Reply | Threaded
Open this post in threaded view
|

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

Can you expand the window there with the classnames? What's the inner class there in org.sakaiproject.announcement.impl.BaseAnnouncementService$Base  ???

On Thu, Feb 8, 2018 at 2:36 PM Austin <[hidden email]> wrote:
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/.

--
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

The inner classes are:  java.lang.String, BaseAnnouncementMessageHeaderEdit, BaseResourcePropertiesEdit

The 2nd class in Finalizer has something to do with TikainputStream?  I saw a few instances of that, but the majority the objects had to do with Announcements.

Thanks for helping us look into this!

- Austin

On Thu, Feb 8, 2018 at 10:08 AM, Matthew Jones <[hidden email]> wrote:
Can you expand the window there with the classnames? What's the inner class there in org.sakaiproject.announcement.impl.BaseAnnouncementService$Base  ???

On Thu, Feb 8, 2018 at 2:36 PM Austin <[hidden email]> wrote:
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/.

--
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/.

BaseAnnouncementMessageHeaderEdit.png (689K) 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

also the message_date on that announcement object is quite old, 2014-04-14 11:18:34.  I also asked the user if he was doing anything with their site / announcements, but he did not.  So it's pretty strange that such an old announcement is getting loaded up and an 'edit' object is created for it.

On Thu, Feb 8, 2018 at 10:21 AM, Austin <[hidden email]> wrote:
The inner classes are:  java.lang.String, BaseAnnouncementMessageHeaderEdit, BaseResourcePropertiesEdit

The 2nd class in Finalizer has something to do with TikainputStream?  I saw a few instances of that, but the majority the objects had to do with Announcements.

Thanks for helping us look into this!

- Austin

On Thu, Feb 8, 2018 at 10:08 AM, Matthew Jones <[hidden email]> wrote:
Can you expand the window there with the classnames? What's the inner class there in org.sakaiproject.announcement.impl.BaseAnnouncementService$Base  ???

On Thu, Feb 8, 2018 at 2:36 PM Austin <[hidden email]> wrote:
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/.


--
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

Another thing I was wondering is if Announcements get loaded into memory whenever a user is added into memory?  The reason I ask is because, we have a site that has 30,000 users, which includes a ton of "old" users.  (which I've also been suspicious of in the past causing problems)  And since some of the Announcements I inspected were also 'old'... this is kind of a leap, but is there any chance that even though these old users are not actually logging in, but they are somehow getting loaded into memory (suspect that if one person logs in and views that 30K site, every user from that site will also be loaded into mem.), are announcements they would have been seeing also getting loaded into memory?

On Thu, Feb 8, 2018 at 10:27 AM, Austin <[hidden email]> wrote:
also the message_date on that announcement object is quite old, 2014-04-14 11:18:34.  I also asked the user if he was doing anything with their site / announcements, but he did not.  So it's pretty strange that such an old announcement is getting loaded up and an 'edit' object is created for it.

On Thu, Feb 8, 2018 at 10:21 AM, Austin <[hidden email]> wrote:
The inner classes are:  java.lang.String, BaseAnnouncementMessageHeaderEdit, BaseResourcePropertiesEdit

The 2nd class in Finalizer has something to do with TikainputStream?  I saw a few instances of that, but the majority the objects had to do with Announcements.

Thanks for helping us look into this!

- Austin

On Thu, Feb 8, 2018 at 10:08 AM, Matthew Jones <[hidden email]> wrote:
Can you expand the window there with the classnames? What's the inner class there in org.sakaiproject.announcement.impl.BaseAnnouncementService$Base  ???

On Thu, Feb 8, 2018 at 2:36 PM Austin <[hidden email]> wrote:
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/.



--
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/.
Hendrik Steller Hendrik Steller
Reply | Threaded
Open this post in threaded view
|

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

On Freitag, 9. Februar 2018 20:28:04 CET Austin wrote:

> Another thing I was wondering is if Announcements get loaded into memory

> whenever a user is added into memory? The reason I ask is because, we have

> a site that has 30,000 users, which includes a ton of "old" users. (which

> I've also been suspicious of in the past causing problems) And since some

> of the Announcements I inspected were also 'old'... this is kind of a leap,

> but is there any chance that even though these old users are not actually

> logging in, but they are somehow getting loaded into memory (suspect that

> if one person logs in and views that 30K site, every user from that site

> will also be loaded into mem.), are announcements they would have been

> seeing also getting loaded into memory?

 

I don't think so; sounds rather unlikely.

Also, I just had a look by enabling the mysql general query log for my local development sakai instance and then:

started the server,

logged in with an admin account,

clicked a bit around the announcements tool in my Home site,

went to a course site,

looked at the announcements,

edited one until "preview,

canceled the preview,

logged out of sakai without canceling the edit and

shut down the server again.

 

Only a few queries were made which included "%announcement%" and nothing of that looked like what you were suspecting (see queries below) ; then again, your setup, tools, customizations etc are going to be different.

 

I also didn't find what I was suspecting (or not really suspecting because I hadn't found any evidence of it happening in the code) and actually looking for:

In your screenshots, those were "edit"-objects which were waiting for finalization. That seems like there's more happening than e.g. a user or a search engine's crawler opening and reading an old announcement.

I found ~160 four abandoned records which never got cleaned up in my sakai_locks table with the oldest ones from February 2014.

 

That made me wonder if something could be loading all entries from that locks table and create "ancient" edit objects for those records that way, e.g. for prefilling a local cache or something cleanup-related.

But according to the query log, this doesn't happen; at least not on my one-tomcat-no-distributed-caching notebook without any quartz jobs.

 

 

If I were really interested in where those old announcement edits are originating from, I would go into the announcement service where those edit objects for announcements are being created and then add something like

 

if (switchToEnableThis && "thatOldAnnouncementsId".equals(announcementId)) {

dumpRequestAndSessionInfo();

throwAndCatchSomeDummyExceptionAndLogItsStacktrace();

notifyMe();

}

 

Regards

Hendrik

 

 

-------

Query log:

 

MariaDB [sakai11]> select argument from mysql.general_log where argument like '%announcement%' and argument not like '%mysql.general_log%' and command_type!= 'Prepare';

| CREATE TABLE ANNOUNCEMENT_CHANNEL ( CHANNEL_ID VARCHAR (255) NOT NULL, NEXT_ID INT, XML LONGTEXT )                                                                                                                                                                                                                                                             |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/!site/motd' )                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_MESSAGE where (CHANNEL_ID = '/announcement/channel/!site/motd' and DRAFT = '0') order by MESSAGE_DATE desc                                                                                                                                  |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/~hsteller/main' )                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_MESSAGE  where (CHANNEL_ID = '/announcement/channel/~hsteller/main' )order by MESSAGE_DATE asc                                                                                                                                              |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                                           
| select XML from ANNOUNCEMENT_MESSAGE  where (CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )order by MESSAGE_DATE asc                                     
| select SAKAI_ALIAS.ALIAS_ID,SAKAI_ALIAS.TARGET,SAKAI_ALIAS.CREATEDBY,SAKAI_ALIAS.MODIFIEDBY,SAKAI_ALIAS.CREATEDON,SAKAI_ALIAS.MODIFIEDON from SAKAI_ALIAS where TARGET = '/announcement/ann
ouncement/30f49e34-5224-49aa-9099-9f11fa490654' order by SAKAI_ALIAS.ALIAS_ID                                                                                                                                                                                                                                                                                     |
| select SAKAI_ALIAS.ALIAS_ID,SAKAI_ALIAS.TARGET,SAKAI_ALIAS.CREATEDBY,SAKAI_ALIAS.MODIFIEDBY,SAKAI_ALIAS.CREATEDON,SAKAI_ALIAS.MODIFIEDON from SAKAI_ALIAS where TARGET = '/announcement/ann
ouncement/30f49e34-5224-49aa-9099-9f11fa490654' order by SAKAI_ALIAS.ALIAS_ID                                                                                                                                                                                                                                                                                      |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                              
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_MESSAGE  where (CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )order by MESSAGE_DATE asc                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_MESSAGE  where (CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )order by MESSAGE_DATE asc                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_MESSAGE where (CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' ) and ( MESSAGE_ID = 'f419dcea-72ef-4e8b-8f63-3a98b969628a' )   
                                                                                                                                                                      |
| select XML from ANNOUNCEMENT_MESSAGE where (CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' ) and ( MESSAGE_ID = 'f419dcea-72ef-4e8b-8f63-3a98b969628a' )   
                                                                                                                                                                      |
| insert into SAKAI_LOCKS (TABLE_NAME,RECORD_ID,LOCK_TIME,USAGE_SESSION_ID) values ('ANNOUNCEMENT_MESSAGE', '1275768022 - /announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main/f41
9dcea-72ef-4e8b-8f63-3a98b969628a', TIMESTAMP'2018-02-09 21:29:56.459000', 'd78979c3-f937-48a9-8edc-bcad916955f6')                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                       |
| select count(1) from SAKAI_REALM_RL_FN,SAKAI_REALM force index (AK_SAKAI_REALM_ID) where SAKAI_REALM_RL_FN.REALM_KEY = SAKAI_REALM.REALM_KEY and  SAKAI_REALM.REALM_ID IN ('/announcement/c
hannel/30f49e34-5224-49aa-9099-9f11fa490654/main','/site/30f49e34-5224-49aa-9099-9f11fa490654','!site.helper') and FUNCTION_KEY in (select FUNCTION_KEY from SAKAI_REALM_FUNCTION where FUNCT
ION_NAME = 'annc.read')  and (ROLE_KEY in (select ROLE_KEY from SAKAI_REALM_RL_GR where ACTIVE = '1' and USER_ID = NULL  and REALM_KEY in (select REALM_KEY from SAKAI_REALM where  SAKAI_REA
LM.REALM_ID IN ('/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main','/site/30f49e34-5224-49aa-9099-9f11fa490654','!site.helper')))  or ROLE_KEY in (1) ) |


| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                       |
| select XML from ANNOUNCEMENT_CHANNEL where ( CHANNEL_ID = '/announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main' )                                                                                                                                                                       |
| delete from SAKAI_LOCKS where TABLE_NAME = 'ANNOUNCEMENT_MESSAGE' and RECORD_ID = '1275768022 - /announcement/channel/30f49e34-5224-49aa-9099-9f11fa490654/main/f419dcea-72ef-4e8b-8f63-3a9
8b969628a'

--
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 Jones-2 Matthew Jones-2
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
It's possible whenever a user logs in via the Announcement Synoptic Widget. By default it only shows for the last 10 days but since the data is stored in XML I could imagine that it actually has to read through the database records and make objects just to display the tool for every case. I wouldn't know without research.

You could try to remove that tool registration from the system. (Removing the xml from webapps/sakai-announcement-tool/WEB-INF/tools/sakai.synoptic.announcement.xml) and restarting should make it not load up anymore.

On Fri, Feb 9, 2018 at 2:28 PM Austin <[hidden email]> wrote:
Another thing I was wondering is if Announcements get loaded into memory whenever a user is added into memory?  The reason I ask is because, we have a site that has 30,000 users, which includes a ton of "old" users.  (which I've also been suspicious of in the past causing problems)  And since some of the Announcements I inspected were also 'old'... this is kind of a leap, but is there any chance that even though these old users are not actually logging in, but they are somehow getting loaded into memory (suspect that if one person logs in and views that 30K site, every user from that site will also be loaded into mem.), are announcements they would have been seeing also getting loaded into memory?

On Thu, Feb 8, 2018 at 10:27 AM, Austin <[hidden email]> wrote:
also the message_date on that announcement object is quite old, 2014-04-14 11:18:34.  I also asked the user if he was doing anything with their site / announcements, but he did not.  So it's pretty strange that such an old announcement is getting loaded up and an 'edit' object is created for it.

On Thu, Feb 8, 2018 at 10:21 AM, Austin <[hidden email]> wrote:
The inner classes are:  java.lang.String, BaseAnnouncementMessageHeaderEdit, BaseResourcePropertiesEdit

The 2nd class in Finalizer has something to do with TikainputStream?  I saw a few instances of that, but the majority the objects had to do with Announcements.

Thanks for helping us look into this!

- Austin

On Thu, Feb 8, 2018 at 10:08 AM, Matthew Jones <[hidden email]> wrote:
Can you expand the window there with the classnames? What's the inner class there in org.sakaiproject.announcement.impl.BaseAnnouncementService$Base  ???

On Thu, Feb 8, 2018 at 2:36 PM Austin <[hidden email]> wrote:
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/.



--
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

Ashley Willis mentioned, "I think you might be on to something with the Base 64 image stuff"

I checked some old heap dumps from last semester (when we were on Sakai 10.7) when we experienced similar [CMS-concurrent...] looping.  And while I did not see the BaseAnnoncementMessageEdit leaks, I was seeing tons of instances of 

org.apache.jasper.runtime.BodyContentImpl
org.apache.jasper.runtime.PageContextImpl
org.apache.jasper.runtime.BodyContentImpl[]

and inspecting them, the content seemed to have a embedded e.g. "...ppt/slides/_rels/slide28.xml.rels...", or other encoded data.  And in particular, they had to do with the Forums tool, perhaps large ppt attachments of over 100MB?  Anyway, I didn't see this Forums error in my recent heap dumps from Sakai 11.4... maybe whatever forums issue that caused it in 10.7 is now fixed in Sakai 11.4 or perhaps fixed after we upgraded to MySql 5.6, but in any case, I thought it was a weird coincidence that back then as well as now, we're seeing stuck objects that include embedded data: images, ppt, etc...

On Fri, Feb 9, 2018 at 1:41 PM, Matthew Jones <[hidden email]> wrote:
It's possible whenever a user logs in via the Announcement Synoptic Widget. By default it only shows for the last 10 days but since the data is stored in XML I could imagine that it actually has to read through the database records and make objects just to display the tool for every case. I wouldn't know without research.

You could try to remove that tool registration from the system. (Removing the xml from webapps/sakai-announcement-tool/WEB-INF/tools/sakai.synoptic.announcement.xml) and restarting should make it not load up anymore.

On Fri, Feb 9, 2018 at 2:28 PM Austin <[hidden email]> wrote:
Another thing I was wondering is if Announcements get loaded into memory whenever a user is added into memory?  The reason I ask is because, we have a site that has 30,000 users, which includes a ton of "old" users.  (which I've also been suspicious of in the past causing problems)  And since some of the Announcements I inspected were also 'old'... this is kind of a leap, but is there any chance that even though these old users are not actually logging in, but they are somehow getting loaded into memory (suspect that if one person logs in and views that 30K site, every user from that site will also be loaded into mem.), are announcements they would have been seeing also getting loaded into memory?

On Thu, Feb 8, 2018 at 10:27 AM, Austin <[hidden email]> wrote:
also the message_date on that announcement object is quite old, 2014-04-14 11:18:34.  I also asked the user if he was doing anything with their site / announcements, but he did not.  So it's pretty strange that such an old announcement is getting loaded up and an 'edit' object is created for it.

On Thu, Feb 8, 2018 at 10:21 AM, Austin <[hidden email]> wrote:
The inner classes are:  java.lang.String, BaseAnnouncementMessageHeaderEdit, BaseResourcePropertiesEdit

The 2nd class in Finalizer has something to do with TikainputStream?  I saw a few instances of that, but the majority the objects had to do with Announcements.

Thanks for helping us look into this!

- Austin

On Thu, Feb 8, 2018 at 10:08 AM, Matthew Jones <[hidden email]> wrote:
Can you expand the window there with the classnames? What's the inner class there in org.sakaiproject.announcement.impl.BaseAnnouncementService$Base  ???

On Thu, Feb 8, 2018 at 2:36 PM Austin <[hidden email]> wrote:
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/.




--
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/.