Astronomical GC times

[Brad Wood]

This isn't a question about FR so much as it is a quick sanity check to see if any of the other experts here have seen the situation I'm currently looking into.  I'll keep it short.  

Ubuntu 64-bit

Tomcat/Railo 4.2

Java 8

G1 garbage collector -- all default settings

4 GB heap

Virtualized environment

If the site is "warmed up" and taking regular traffic, my GC times are acceptable.  Not great, but acceptable.  Let's say a sustained 15-20 requests a second to a simple page.

Scavenge (Minor collection): ~25 ms

Marksweep (major collection): ~1.5 seconds

The issue is when the site sits for a while with little or no traffic, the first garbage collection will be just absurd.  Usually a 2-6 MINUTE stop-the-world collection where the entire JVM (including FR) is unresponsive.  After that, the first few minor collections can take 600-900 ms and the major collections can take 4-5 seconds until the box settles down again to the numbers I posted above.

During a multi-minute collection, CPU is at 0% for most of it until the end when there is a flurry of activity right before it completes.  Usually no more than 1GB is freed, so we're not dealing with 50GB heaps or anything here.

• Has anyone else ever seen this behavior?
• Any troubleshooting ideas?
• My personal hunch is that it's related to the virtualization environment "borrowing" RAM from VMs that aren't using it and being reluctant to give it back.
• I don't know anything about the virtualization environment yet.  That's my next step to speak with the host.

Thanks!

~Brad

[Darren Pywell]

Hi Brad,

Have you seen this article? This may be some help:

http://blog.mgm-tp.com/2014/04/controlling-gc-pauses-with-g1-collector/

Cheers,

Darren

[Darren Pywell]

Also it may be worth looking into SecureRandom which can so often be a cause of huge waits in Linux systems. I'm not sure it's the cause here but SecureRandom has often turned up on very long pauses on systems:

e.g. http://stackoverflow.com/questions/2563135/weblogic-is-slow-to-start-11mins-under-vm-virtualbox-and-vmware

Cheers,

Darren

On Monday, December 15, 2014 10:33:44 PM UTC+1, Brad Wood wrote:

[Brad Wood]

On Mon, Dec 15, 2014 at 4:20 PM, Darren Pywell <dapy...@googlemail.com> wrote:

Have you seen this article? This may be some help:

http://blog.mgm-tp.com/2014/04/controlling-gc-pauses-with-g1-collector/

Yes, I actually read that very article this week, along with just about every other GC tuning article that's on the Internet :)  We actually were seeing this issue prior to our upgrade to Java 8 when using Java 7 and the CMS collector.  I don't think that article really has anything useful for me though.  First of all, they're dealing with 50GB heaps, not even close to my small little 4GB heap.  Secondly, they're dealing with getting GC times that are already sub-second and making them even smaller.  

I've Googled a fair amount and haven't found a single Internet article talking about a 5 minute garbage collection.  There just simply isn't any information that I can find that seems to address what I'm seeing.

Thanks!

~Brad

ColdBox Platform Evangelist

Ortus Solutions, Corp 

E-mail: br...@coldbox.org

ColdBox Platform: http://www.coldbox.org 

Blog: http://www.codersrevolution.com

[Brad Wood]

On Mon, Dec 15, 2014 at 4:39 PM, Darren Pywell <dapy...@googlemail.com> wrote:

SecureRandom has often turned up on very long pauses on systems:

e.g. http://stackoverflow.com/questions/2563135/weblogic-is-slow-to-start-11mins-under-vm-virtualbox-and-vmware

Hmm, that is an interesting one.  I'm not sure how to prove if the JVM is trying to get some random data though since it's impossible for me to even use FR or get a stack trace (that I know of) while it's locked up.  In fact, I have to use OS tools just to get the CPU usage.  Not FR's fault of course, it only gets to take samples when the JVM is responding.

[Charlie Arehart]

Brad, can you confirm for us what’s telling you there are the long GC times? Just curious, since you say you can’t get to FR. Is it a report in FR after it awakes? Or its logs? Or some other native Java logging or UI?

Since you say there’s no CPU use during the time, I’d be inclined to wonder if there was some other explanation for things, but I realize if some tool says clearly there’s a long GC time, you’ll be inclined to trust it as saying “this is the problem”. Even so, sometimes that’s more the symptom than the true root cause, believe it or not.

Indeed, when I saw your mention first off of a virtualized environment, my first thought was along the lines of one of your conclusions in your first note: it could be something may be amiss in the hypervisor’s allocation of resources. Whenever there’s something that can’t be otherwise explained, and virtualization is involved, I can’t help but point a flashlight of suspicion at that being the issue. Of course it can be difficult to prove it, but it’s worth giving attention to the possibility at least to rule it out.  (Worst case, one might have to see about backing up the system and restoring it–or recovering a VM snapshot--onto a real system, equivalently configured, to prove if it’s the VM or not.

One other (easier) thing along those lines; how many CPUs were allocated to the VM? I know you’re saying you don’t see CPU as an issue, but another problem I’ve seen with vm’s is that folks may allocate only a single CPU (perhaps powerful), when some GC algorithms (especially the default one CF specifies) are sensitive to that (work worse when there’s only one CPU). Of course the G1 algorithm being the newest, you’d think it would be the best. But I’ve just not yet heard of explored how it may fair in a single CPU setup. Just something to consider.

HTH.

 

/charlie

[Brad Wood]

Excellent questions Charlie.  I hope you'll understand, I didn't address a lot of those in my initial post just to keep things short since people's eyes tend to glaze over if you give to much detail right away :)  Since you asked though, I'll categorically address them now:

Brad, can you confirm for us what’s telling you there are the long GC times?

Three things:

1. FR's "Resources" > "Garbage Collection" graph will show me the duration of the collection  as soon as it is complete (at least for a minute-- see my other thread about how this sampling works after 1 minute has passed)
2. The JVM's GC logging confirms the duration of the collections that I have enabled via the following args:
   -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/opt/railo/tomcat/logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M
3. Empirical evidence.  I can observe the quite predictable behavior of letting the server sit for a while, clicking the "Garbage Collection" button in FR and then everything on that server that's running on the JVM ceases to respond for the next  5 minutes or so including web requests, Fusion Reactor stats, etc.  Even without forcing a major collection, I can be using the site and suddenly a page will take 20-30 seconds to load.  A quick look into FR will confirm every time that a 20-30 second minor collection just happened that perfectly coincides with my "long" request that had no other visible signs of why it would have taken that long (JDBC times, etc).
   
   

> Just curious, since you say you can’t get to FR

I opened all the FR graphs ahead of time while testing.  Even though they don't update during a collection, the spike shows up on the graph as soon as the collection finishes.

> Or some other native Java logging or UI?

Yes, the GC logs I mentioned above corroborate what the FR graphs show me.

> Since you say there’s no CPU use during the time, I’d be inclined to wonder if there was some other explanation for things, but I realize if some tool says clearly there’s a long GC time, you’ll be inclined to trust it as saying “this is the problem”. Even so, sometimes that’s more the symptom than the true root cause, believe it or no

Well, certainly.  I don't actually think it's taking 5 minutes to perform a marksweep collection on such a small heap.  People can easily tune a 50 GB heap to do full collections in under 200 ms.  It seems to me that Java is simply waiting on some sort of low level operation from the operating system that's being blocked.  In this instance, I think Java is simply asking to access the memory its been told belongs to it.  That's just difficult to prove since I can't pull a stack trace during a GC.

> VM snapshot--onto a real system, equivalently configured, to prove if it’s the VM or not.

Well, I haven't done exactly that, but I did construct a setup on my local Windows PC that is as close as I can get.  Everything but the OS is the same.  The GC times are my local machine are mucho faster in general and there are no "warm up" times even after sitting overnight.

> One other (easier) thing along those lines; how many CPUs were allocated to the VM?

 There are 6 CPUs assigned to the VM, so it's certainly not in want of power.  My local PC that saw magnitudes of better performance only has 4 CPUs.  Like I mentioned in the OP the first 99% of the collection time is reported by the "top" command as Java consuming zero CPU resources so the hangup is clearly not CPU-bound.  The Linux swap file is also not being used at all, so it's also not an issues of RAM being swapped to disk.  

Thanks again for the sanity checks, Charlie.  Let me know if you think of anything else.  

Thanks!

~Brad

ColdBox Platform Evangelist

Ortus Solutions, Corp 

E-mail: br...@coldbox.org

ColdBox Platform: http://www.coldbox.org 

Blog: http://www.codersrevolution.com

--

You received this message because you are subscribed to the Google Groups "FusionReactor" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fusionreacto...@googlegroups.com.
To post to this group, send email to fusion...@googlegroups.com.
Visit this group at http://groups.google.com/group/fusionreactor.
For more options, visit https://groups.google.com/d/optout.

[Charlie Arehart]

Thanks, Brad. So is your next stop to talk to someone involved in the hypervisor (or research more yourself if you’re “him”), to see if perhaps the VM is under-allocated, or if there may be any logging of metrics at the hypervisor level to point to that possibility?

BTW, here are some tools for monitoring/managing vm’s that may be helpful: http://www.cf411.com/vmmon

/charlie

 

From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com] On Behalf Of Brad Wood
Sent: Tuesday, December 16, 2014 12:46 AM
To: fusionreactor
Subject: Re: [fusionreactor] Re: Astronomical GC times

 

Excellent questions Charlie.  I hope you'll understand, I didn't address a lot of those in my initial post just to keep things short since people's eyes tend to glaze over if you give to much detail right away :)  Since you asked though, I'll categorically address them now:

 

Brad, can you confirm for us what’s telling you there are the long GC times?

 

Three things:

<snip>

[Brad Wood]

On Tue, Dec 16, 2014 at 3:28 PM, Charlie Arehart <charli...@carehart.org> wrote:

Subject: Re: [fusionreactor] Re: Astronomical GC times

Yes Charlie, I have begun the conversation with the host provider and I am waiting to hear back.  Thanks for the VM-related links.  Your resources are, as always, very helpful :)

[Neil Wightman]

Hi Brad.

We had a very bad problem with secure random and java processes.  Our servers running on VMs would pause for 30 seconds for what seemed like no reason.

Finally we tracked it down to secure random being used by a VM which had very low entropy.

You can view the entropy by typing:

cat /proc/sys/kernel/random/entropy_avail

Our systems were at around 100 - 150.

You can work around this by editing the java.security (in jre/lib/security).  You can change the line

securerandom.source=file:/dev/urandom

to

securerandom.source=file:/dev/./urandom

This seems strange, but this change makes java really use /dev/urandom for most random number generation.  urandom is still secure enough for most usages.  See http://development.adaptris.net/users/lchan/blog/2012/06/15/slow-java-crypto-performance-on-linux/ for more info.

If you dont want to change this property you could install something like haveged, which is what we have done on our VMs.   This made our VMs have around 2000 for entropy_avail and stopped our pauses.

http://www.issihosts.com/haveged/ - says "Haveged was created to remedy low-entropy conditions in the Linux random device that can occur under some workloads, especially on headless servers"

I hope this helps,

Regards,
Neil

p.s.  I tried to email this yesterday but it never appeared on the list.

--
You received this message because you are subscribed to the Google Groups "FusionReactor" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fusionreacto...@googlegroups.com.
To post to this group, send email to fusion...@googlegroups.com.
Visit this group at http://groups.google.com/group/fusionreactor.
For more options, visit https://groups.google.com/d/optout.

--

Neil Wightman Senior Software Engineer Email: neil_w...@intergral.com Company Web http://www.intergral.com

This e-mail and any files transmitted with it are confidential and may be protected by legal privilege. If you are not the intended recipient, please notify the sender and delete the e-mail from your system. This e-mail has been scanned for malicious content but the internet is inherently insecure and Intergral GmbH cannot accept any liability for the integrity of this message or its attachments.

[Brad Wood]

Hi Neil, thanks for the second mention of secure random.  I read through that blog entry and SO post a few days back when Darren mentioned it.  I don't like to change too many factors at once and we had been tweaking some heap sizes and GC settings just to see if it made a difference so I hadn't tried it yet.  I've applied the  "file:/dev/./urandom" trick today and I'll do some testing to see if it has any effect.

In other news, I  have been able to get some more information about my virtual environment.  Turns out these aren't standard hypervisor VMs such as VMWare (in which each VM is a full OS install, drivers, libs, etc ) but Virtuozzo containers in which each container is simply a process on a single host OS that shares resources with the other containers on the box.  

These container solutions are enticing to hosting companies because they can fit MANY more VMs on a single host machine due to their small footprint, shared resources, and "overselling" of RAM (which is fine as long as all the containers don't want their max RAM all at once)  What this means though is there is simply a shared pool of RAM that the containers pull from as needed based on availability and their upper limit.  

I'll keep following that trail as well and see what we find.  In the mean time, anyone who has experience hosting Java-based apps on Virtuozzo containers is welcome to chime in.

Thanks!

~Brad

ColdBox Platform Evangelist

Ortus Solutions, Corp 

E-mail: br...@coldbox.org

ColdBox Platform: http://www.coldbox.org 

Blog: http://www.codersrevolution.com

[Brad Wood]

Just a followup to this thread for anyone finding it in the future.  We  never were able to find a "smoking gun" per se as I prefer, but some testing with the hosting provider  showed that moving our CF containers to another Virtuozzo host with much fewer other containers reduced the longest GC pauses down to around 4-5 seconds.  While not stellar, a 5 second pause time is at least doable.  My conclusion is that budget VPS "containers"  like the ones that run on Virtuozzo are not optimal for Java-based applications with large heaps when on a host also servicing a large number of other containers.  In this case, most of the other containers were PHP sites-- each of which probably used much smaller amounts of RAM.  

The Zen servers with the same host (which is a true virtualized environment with dedicated hardware) performs very fast with full collection times of a few hundred milliseconds.  The decision will be to migrate away from the container-based hosting and onto Zen virtualized environments.

The good news is that Fusion Reactor's tools made it possible to easily measure this data in real time and share it with the hosting provider so they could see the issue we were experiencing :)

Thanks!

~Brad

[Charlie Arehart]

Thanks for sharing, Brad.

I’d wonder instead if it may be just that the first server/VM was over-allocated. I think this happens often on virtualized servers more often than people may realize, where the person in control of the hypervisor spreads the available host resources over several (if not dozens or hundreds of vms) and the vm’s “think” they have x GB of memory, for instance, but instead it’s dynamically allocated on demand from the hypervisor and if there are more VMs asking for more memory than the hypervisor really has, you experience odd slownesses on the VM.

Sadly, that’s about the only way “from within” the VM that you can suspect it’s happening. There’s no way to “know”, as far as I know.

Anyone have more specific experience on this matter?

/charlie

 

From: fusion...@googlegroups.com [mailto:fusion...@googlegroups.com] On Behalf Of Brad Wood
Sent: Tuesday, January 06, 2015 10:54 PM
To: fusion...@googlegroups.com
Subject: Re: [fusionreactor] Re: Astronomical GC times

 

Just a followup to this thread for anyone finding it in the future.  We  never were able to find a "smoking gun" per se as I prefer, but some testing with the hosting provider  showed that moving our CF containers to another Virtuozzo host with much fewer other containers reduced the longest GC pauses down to around 4-5 seconds.  While not stellar, a 5 second pause time is at least doable.  My conclusion is that budget VPS "containers"  like the ones that run on Virtuozzo are not optimal for Java-based applications with large heaps when on a host also servicing a large number of other containers.  In this case, most of the other containers were PHP sites-- each of which probably used much smaller amounts of RAM.  

--

[Brad Wood]

Charlie, I would bet money this host is "over allocated".  Perhaps it was harsh of me to say 'VPS "containers"  like the ones that run on Virtuozzo are not optimal for Java-based applications' but I guess I was operating on the assumption that any hosting provider using container-based "VM"s is going to be overbooking the RAM.  From that I've read, that is the main advantage to hosting providers-- the ability to put a very large amount of containers on the same host with the assumption that they won't all need their RAM at once.

Of course, when Java suddenly decides that it wants to inspect all 4 Gigs of a heap it hadn't been using until then, I can see how it may take a busy host a few minutes to scavenge enough RAM to satisfy that.  Understandable, but not really acceptable for a web-application.