Re: intermittent extremely slow GC

Matt Avery Sat, 09 Nov 2002 16:37:05 -0800

The only two memory leaks I know of in the JVM are in Swing. The indeterminate progress bar leaks memory like crazy by creating a zillion Insets and JDialogs can cause memory leaks because the "dispose" method isn't working and so it won't allow them to be garbage collected. Both of these are in the bug list somewhere.

Dave A King wrote:

i definitely think swap is my issue.  I'm kicking myself for not noticing
it...
What's odd is the only thing that has changed on these servers in many weeks
is the java code for our application.  We have a fixed heap size if 512MB.
Where is all this extra memory coming from?  1GB real memory and 700+MB swap
in use.  Does the jvm itself leak memory, even with a fixed heap size?

-d-
-----Original Message-----
From: Matt Avery [mailto:mavery@;einnovation.com]
Sent: Friday, November 08, 2002 9:51 AM
To: Dave A King
Cc: '[EMAIL PROTECTED]'
Subject: Re: intermittent extremely slow GC

If any memory has paged to swap, garbage collection through the swap will be excruciatingly slow. Is another app consuming memory, forcing the server to use the swap partition heavily?

Dave A King wrote:

I'm trying to troubleshoot some really bizarre behavior in
a recent build of
our application. We have changed our memory usage quite a
bit, utilizing
more caching, etc. Overall performance has unsurprisingly
improved and all
looked good during QA after we tackled some memory leaks
and unbounded
caches. In general, we spend 1% or less time in GC. Minor
collections
happen often but quickly, usually under 100ms. Major
collections happen
every couple hours, generally taking ~3 seconds. After each major
collection, the heap in use is reduced approximately the
same each time, so
apparently we are leak-free. Everything was looking good...

After running this for over a week in production under moderate load
(significantly less than we ran in QA scenarios), I started
noticing some
wild behavior. About 100 hours in to the application's
lifetime, major
collections started taking much longer then it had in the
days prior.  45+
seconds becomes the norm. And on top of that, some minor
collections take
several seconds, and in some cases as long as 45 seconds.

The boggling part is that the application itself isn't
doing anything
differently 100 hours in than it had in the first few hours
of its life.
Each app server handles several hundred client connections,
that have an
average session length of a few hours. Each client has the
same type of
functions. Why on earth would GC time change so
dramatically after the app
has been up for a few days? Why would it take so much
longer to clear the
heap of the same amount and type of data that it had done
in a tenth of the
time before?

Any input would be appreciated... Here is some example
output from verbose
GC...

Normal behavior:

13122: [GC 441755K->382806K(516800K), 0.0547972 secs]
13135: [GC 442710K->383552K(516800K), 0.0621738 secs]
13152: [GC 443456K->384087K(516800K), 0.0714369 secs]
13166: [GC 443991K->385705K(516800K), 0.0968161 secs]
13181: [GC 445609K->385720K(516800K), 0.1021833 secs]
13195: [GC 445622K->385748K(516800K), 0.0390663 secs]
13208: [GC 445648K->387175K(516800K), 0.0490246 secs]
13230: [GC 447075K->388661K(516800K), 0.0740566 secs]
13243: [GC 448787K->389577K(516800K), 0.0829134 secs]
13258: [Full GC 449481K->144520K(516800K), 3.1433411 secs]
13272: [GC 204424K->146891K(516800K), 0.0390291 secs]
13288: [GC 206795K->147522K(516800K), 0.0864487 secs]
13307: [GC 207762K->147822K(516800K), 0.0402269 secs]
13324: [GC 207725K->148218K(516800K), 0.0444241 secs]

Abnormal behavior:

617481: [GC 429003K->369069K(516800K), 0.0502329 secs]
617485: [GC 428973K->371054K(516800K), 0.0752230 secs]
617491: [GC 430956K->371764K(516800K), 0.4616861 secs]
617495: [GC 431667K->372278K(516800K), 0.2441826 secs]
617498: [GC 432182K->374942K(516800K), 0.8099241 secs]
617501: [GC 434846K->378277K(516800K), 0.3345280 secs]
617504: [GC 438181K->380583K(516800K), 0.7288399 secs]
617509: [GC 440486K->389948K(516800K), 1.2321482 secs]
617516: [Full GC 449849K->125578K(516800K), 111.9440899 secs] **
617631: [GC 185482K->134830K(516800K), 0.2384958 secs]
617635: [GC 194734K->138885K(516800K), 17.7584829 secs] **
617664: [GC 198789K->140709K(516800K), 1.1765528 secs]
617667: [GC 200613K->142999K(516800K), 1.1135330 secs]
617670: [GC 202903K->143896K(516800K), 0.1886063 secs]
617674: [GC 204399K->145748K(516800K), 0.0643682 secs]
617679: [GC 205651K->146747K(516800K), 0.2402821 secs]

and
619471: [GC 305211K->244553K(516800K), 0.0485077 secs]
619479: [GC 304566K->245821K(516800K), 0.0509443 secs]
619490: [GC 305722K->246337K(516800K), 42.9122648 secs]
619550: [GC 306238K->251121K(516800K), 0.6206665 secs]
619556: [GC 311023K->252685K(516800K), 1.2239046 secs]

History of Full GC's over life of application:

9.53674e-07: [Full GC 17737K->2084K(516800K), 0.1908865 secs]
541.745: [Full GC 35627K->28499K(516800K), 0.6089849 secs]
13258.4: [Full GC 449481K->144520K(516800K), 3.1433411 secs]
18632.4: [Full GC 449434K->117622K(516800K), 4.1499891 secs]
31353.9: [Full GC 449503K->138192K(516800K), 2.9364882 secs]
44821.5: [Full GC 449635K->128602K(516800K), 3.5222492 secs]
72966.8: [Full GC 450272K->109305K(516800K), 3.1930017 secs]
90394.6: [Full GC 449639K->101752K(516800K), 3.3126717 secs]
102110: [Full GC 449730K->140655K(516800K), 7.4890938 secs]
113514: [Full GC 450201K->144888K(516800K), 4.6597281 secs]
124882: [Full GC 449649K->140969K(516800K), 3.2997761 secs]
141718: [Full GC 449502K->86848K(516800K), 8.5978765 secs]
165566: [Full GC 450117K->129728K(516800K), 2.6545095 secs]
176843: [Full GC 449487K->153627K(516800K), 3.2301273 secs]
182390: [Full GC 449720K->152101K(516800K), 3.2152205 secs]
191575: [Full GC 449424K->133796K(516800K), 4.2745676 secs]
202382: [Full GC 450226K->160236K(516800K), 4.7137709 secs]
212753: [Full GC 449944K->153338K(516800K), 4.3132010 secs]
223311: [Full GC 497070K->104709K(516800K), 5.0850315 secs]
246687: [Full GC 451648K->97212K(516800K), 6.9727917 secs]
262569: [Full GC 450214K->155561K(516800K), 4.2221823 secs]
273356: [Full GC 449771K->153328K(516800K), 3.2641268 secs]
283529: [Full GC 449575K->164721K(516800K), 3.5498228 secs]
293382: [Full GC 449638K->143123K(516800K), 10.4868135 secs]
307243: [Full GC 451802K->107020K(516800K), 2.4665213 secs]
322742: [Full GC 449626K->117682K(516800K), 6.7076082 secs]
341488: [Full GC 450024K->154630K(516800K), 3.7152338 secs]
345520: [Full GC 477976K->147138K(516800K), 9.4872484 secs]
349874: [Full GC 449596K->135205K(516800K), 9.2359171 secs]
356443: [Full GC 449765K->165255K(516800K), 14.9900150 secs]
362505: [Full GC 454136K->155750K(516800K), 21.1489773 secs]
368815: [Full GC 449678K->129656K(516800K), 26.0207815 secs]
377050: [Full GC 450518K->151542K(516800K), 33.3608971 secs]
386499: [Full GC 449904K->153672K(516800K), 47.4906855 secs]
403552: [Full GC 449416K->122490K(516800K), 20.0693369 secs]
425372: [Full GC 469095K->146568K(516800K), 14.3897219 secs]
434638: [Full GC 449450K->170882K(516800K), 16.9534063 secs]
441793: [Full GC 450081K->133802K(516800K), 13.6909714 secs]
446045: [Full GC 449793K->148823K(516800K), 23.0089579 secs]
451246: [Full GC 449682K->116912K(516800K), 29.9259081 secs]
459237: [Full GC 449518K->135291K(516800K), 16.1384649 secs]
466896: [Full GC 449932K->137190K(516800K), 23.3646173 secs]
478689: [Full GC 449450K->133844K(516800K), 7.2507315 secs]
499931: [Full GC 449520K->88578K(516800K), 14.8080225 secs]
513809: [Full GC 451336K->136276K(516800K), 3.5035353 secs]
522625: [Full GC 450085K->139059K(516800K), 3.5231466 secs]
529708: [Full GC 449694K->140208K(516800K), 12.8583107 secs]
536856: [Full GC 449501K->125418K(516800K), 28.3593645 secs]
543172: [Full GC 450500K->146659K(516800K), 20.3863163 secs]
550093: [Full GC 450006K->134614K(516800K), 92.3609552 secs]
556824: [Full GC 449658K->135680K(516800K), 3.3427563 secs]
573339: [Full GC 449487K->99214K(516800K), 24.8992348 secs]
596442: [Full GC 449419K->132497K(516800K), 3.3868160 secs]
606060: [Full GC 450057K->139770K(516800K), 6.8727570 secs]
612311: [Full GC 449691K->154099K(516800K), 33.8717966 secs]
617516: [Full GC 449849K->125578K(516800K), 111.9440899 secs]
622570: [Full GC 450899K->151202K(516800K), 42.3750582 secs]
626392: [Full GC 449720K->150420K(516800K), 54.5360518 secs]
632741: [Full GC 449523K->149336K(516800K), 45.1601849 secs]
636051: [Full GC 453486K->152278K(516800K), 28.5334997 secs]
644020: [Full GC 449785K->148017K(516800K), 37.1372957 secs]
658880: [Full GC 449516K->131457K(516800K), 8.9688177 secs]
682204: [Full GC 449840K->132642K(516800K), 3.6540842 secs]
687821: [Full GC 449700K->129643K(516800K), 19.1214924 secs]
695634: [Full GC 449788K->152392K(516800K), 30.2079229 secs]
----------------------------------------------------------------------
To UNSUBSCRIBE, email to [EMAIL PROTECTED]
with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
--
Matthew Avery
Senior Developer
(513) 470-5316
http://www.einnovation.com/
eInnovation, Inc., located in the heart of the midwest, invents and promotes eBusiness software that moves business technology to open standards.
----------------------------------------------------------------------
To UNSUBSCRIBE, email to [EMAIL PROTECTED]
with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]

--
Matthew Avery
Senior Developer
(513) 470-5316
http://www.einnovation.com/
eInnovation, Inc., located in the heart of the midwest, invents and promotes eBusiness software that moves business technology to open standards.

----------------------------------------------------------------------
To UNSUBSCRIBE, email to [EMAIL PROTECTED]
with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]

Re: intermittent extremely slow GC

Reply via email to