This discussion is archived
1 Reply Latest reply: Feb 20, 2012 8:14 AM by JohnHendrikx RSS

DefNew GC panicing with SoftReferences?

JohnHendrikx Pro
Currently Being Moderated
I'm experiencing an odd problem of late. My (small) program (max heap 256 MB) uses a lot of large (JavaFX) Images, which are being kept track of in an ImageCache class that uses SoftReferences. After about two dozen of these images have been loaded however, the GC starts going crazy doing lots of small cleans. This shows itself as:

- Lots of GC printing in the log
- One core maxed out
- This continues for a few seconds initially, but with more pics loaded can run minutes(!) at a time

The images however are not being cleaned up at all -- VisualVM reports the heap hovering near its max the whole time. A FUll GC cleans this up... but... the behaviour above continues when the next image is loaded, despite having a heap that isn't even 50% used.

I'm not doing much special in my opinion, it is just a hobby project that I would certainly not expect to run into any kind of GC-type trouble. If anyone can explain this behaviour, I'd be interested. Tested on 32-bit Windows 7, JDK 1.7u2 and 1.7u4 (dev preview).

See below the logs to illustrate this problem (I cut out some of the large GC loops):

0.533: [GC 0.533: [DefNew: 4416K->512K(4928K), 0.0039006 secs] 4416K->517K(15872K), 0.0039602 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.799: [GC 0.799: [DefNew: 4928K->512K(4928K), 0.0062266 secs] 4933K->1165K(15872K), 0.0062645 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.058: [GC 1.058: [DefNew: 4928K->512K(4928K), 0.0073100 secs] 5581K->1690K(15872K), 0.0073504 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1.256: [GC 1.256: [DefNew: 4928K->512K(4928K), 0.0069235 secs] 6106K->2515K(15872K), 0.0069609 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
1.418: [GC 1.418: [DefNew: 4926K->512K(4928K), 0.0051198 secs] 6930K->2793K(15872K), 0.0052875 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.553: [GC 1.553: [DefNew: 4926K->512K(4928K), 0.0044132 secs] 7207K->3321K(15872K), 0.0044506 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
1.627: [GC 1.627: [DefNew: 4928K->512K(4928K), 0.0039100 secs] 7737K->3708K(15872K), 0.0039692 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.697: [GC 1.697: [DefNew: 4928K->512K(4928K), 0.0041284 secs] 8124K->3844K(15872K), 0.0041961 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.833: [GC 1.833: [DefNew: 4928K->277K(4928K), 0.0034055 secs] 8260K->3781K(15872K), 0.0034434 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[FINE] ProgramController.registerService() - registering new service: hs.mediasystem.screens.SubtitleDownloadService@ae214c
[INFO] Navigator.navigateTo() - Destination('Home'; modal=false)
1.978: [GC 1.978: [DefNew: 4693K->512K(4928K), 0.0064901 secs] 8197K->4614K(15872K), 0.0065348 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[FINE] ProgramController.registerService() - registering new service: hs.mediasystem.screens.MessagePaneExecutorService$GroupWorker@c3f72c
2.306: [GC 2.306: [DefNew: 4928K->512K(4928K), 0.0056779 secs] 9030K->5162K(15872K), 0.0057234 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2.512: [GC 2.512: [DefNew: 4921K->472K(4928K), 0.0060734 secs] 9571K->5624K(15872K), 0.0061185 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
4.783: [GC 4.783: [DefNew: 4888K->330K(4928K), 0.0056426 secs] 10040K->5879K(15872K), 0.0056834 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[INFO] Navigator.navigateTo() - Destination('Movies'; modal=false)
[INFO] Navigator.navigateTo() - Destination('Movies'; modal=false)
5.476: [GC 5.476: [DefNew: 4746K->255K(4928K), 0.0050245 secs] 10295K->6108K(15872K), 0.0050653 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
5.535: [GC 5.536: [DefNew: 4671K->512K(4928K), 0.0049691 secs] 10524K->6456K(15872K), 0.0050100 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
5.693: [GC 5.693: [DefNew: 4928K->512K(4928K), 0.0085990 secs] 10872K->7455K(15872K), 0.0086437 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
5.873: [GC 5.874: [DefNew: 4928K->512K(4928K), 0.0131007 secs] 11871K->9422K(15872K), 0.0131450 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
6.036: [GC 6.036: [DefNew: 4928K->512K(4928K), 0.0094798 secs] 13838K->10399K(15872K), 0.0095228 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0112281)
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt1190080)
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt1461312)
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0080339)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt1190080
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0112281
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt1461312
6.378: [GC 6.378: [DefNew: 4928K->488K(4928K), 0.0084662 secs]6.386: [Tenured: 11579K->10280K(12252K), 0.0909118 secs] 14815K->10280K(17180K), [Perm : 15406K->15406K(15616K)], 0.0995113 secs] [Times: user=0.06 sys=0.00, real=0.10 secs]
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0429493)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0429493
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0080339
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0462200)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0462200
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=1)
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0090728)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0090728
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0096895)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0096895
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0286499)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0286499
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0088763)
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0384819)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0384819
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0088763
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt1043842)
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0118655)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt1043842
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0118655
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0066769)
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0163651)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0066769
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0163651
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0078748)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0078748
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt1014759)
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.identifyItem() - Cache Hit
[FINE] CachedItemEnricher.enrichItem() - Loading from Cache: (MOVIE;TMDB;tt0499549)
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt1014759
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0499549
[FINE] ItemsDao.getItem() - Selecting Item with type/provider/providerid = MOVIE/TMDB/tt0401233
6.757: [GC 6.757: [DefNew: 4579K->143K(7808K), 0.0028406 secs] 14859K->11675K(24944K), 0.0028785 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[FINE] ItemsDao.getImage() - Loading image POSTER(id=1)
6.884: [GC 6.884: [DefNew: 6289K->83K(7808K), 0.0079273 secs]6.892: [Tenured: 17606K->17687K(23212K), 0.0705893 secs] 17821K->17687K(31020K), [Perm : 15436K->15436K(15616K)], 0.0786506 secs] [Times: user=0.08 sys=0.00, real=0.08 secs]
7.627: [GC 7.627: [DefNew: 11840K->1472K(13312K), 0.0100919 secs] 29527K->24266K(42792K), 0.0101409 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
13.167: [GC 13.167: [DefNew: 13312K->732K(13312K), 0.0128674 secs] 36106K->24995K(42792K), 0.0129245 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=11)
17.311: [GC 17.311: [DefNew: 6573K->1472K(13312K), 0.0065557 secs] 30835K->25930K(42792K), 0.0066008 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[FINE] ItemsDao.getImage() - Loading image POSTER(id=11)
17.419: [GC 17.419: [DefNew: 9050K->488K(13312K), 0.0113187 secs]17.430: [Tenured: 32000K->31257K(35556K), 0.0812767 secs] 33509K->31257K(48868K), [Perm : 17105K->17105K(17152K)], 0.0927683 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=3)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=3)
18.313: [GC 18.313: [DefNew: 18001K->845K(23552K), 0.0109778 secs] 49259K->42572K(75648K), 0.0110272 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=10)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=10)
19.439: [GC 19.439: [DefNew: 21837K->1685K(23552K), 0.0167106 secs]19.456: [Tenured: 56599K->56776K(58172K), 0.1225932 secs] 63564K->56776K(81724K), [Perm : 17112K->17096K(17152K)], 0.1395690 secs] [Times: user=0.13 sys=0.02, real=0.14 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=4)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=4)
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=80)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=80)
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=12)
23.176: [GC 23.176: [DefNew: 37362K->4735K(42624K), 0.0218504 secs] 94139K->75888K(137252K), 0.0218968 secs] [Times: user=0.01 sys=0.02, real=0.02 secs]
[FINE] ItemsDao.getImage() - Loading image POSTER(id=12)
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=9)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=9)
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=422)
24.709: [GC 24.709: [DefNew: 41972K->1900K(42624K), 0.0278884 secs]24.737: [Tenured: 96754K->98653K(100700K), 0.0819731 secs] 113125K->98653K(143324K), [Perm : 17108K->17108K(17152K)], 0.1102289 secs] [Times: user=0.09 sys=0.01, real=0.11 secs]
[FINE] ItemsDao.getImage() - Loading image POSTER(id=422)
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=8)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=8)
25.721: [GC 25.721: [DefNew: 65899K->7250K(74112K), 0.0257604 secs] 164552K->119050K(238536K), 0.0258098 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=6)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=6)
26.700: [GC 26.700: [DefNew: 73161K->5097K(74112K), 0.0238588 secs] 184961K->130126K(238536K), 0.0239095 secs] [Times: user=0.02 sys=0.02, real=0.02 secs]
26.797: [GC 26.797: [DefNew: 71017K->108K(74112K), 0.0086658 secs] 196046K->130189K(238536K), 0.0087122 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
26.893: [GC 26.893: [DefNew: 66028K->241K(74112K), 0.0055600 secs] 196109K->130321K(238536K), 0.0056000 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=111)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=111)
28.006: [GC 28.006: [DefNew: 66161K->6107K(74112K), 0.0134340 secs] 196241K->142263K(238536K), 0.0134817 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
28.082: [GC 28.082: [DefNew: 72021K->115K(74112K), 0.0097897 secs] 208177K->142318K(238536K), 0.0098378 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
28.154: [GC 28.154: [DefNew: 66002K->175K(74112K), 0.0026793 secs] 208204K->142378K(238536K), 0.0027206 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
28.219: [GC 28.219: [DefNew: 66038K->245K(74112K), 0.0035120 secs] 208240K->142448K(238536K), 0.0035609 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.285: [GC 28.285: [DefNew: 66113K->273K(74112K), 0.0029352 secs] 208316K->142476K(238536K), 0.0029803 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.345: [GC 28.345: [DefNew: 66193K->299K(74112K), 0.0030522 secs] 208396K->142502K(238536K), 0.0030956 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.406: [GC 28.406: [DefNew: 66159K->331K(74112K), 0.0031608 secs] 208362K->142534K(238536K), 0.0032038 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.467: [GC 28.467: [DefNew: 66251K->367K(74112K), 0.0030995 secs] 208454K->142570K(238536K), 0.0031450 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
28.530: [GC 28.530: [DefNew: 66248K->394K(74112K), 0.0032489 secs] 208451K->142597K(238536K), 0.0032957 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.593: [GC 28.593: [DefNew: 66296K->421K(74112K), 0.0033157 secs] 208499K->142624K(238536K), 0.0033604 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=7)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=7)
29.787: [GC 29.787: [DefNew: 66270K->5694K(74112K), 0.0145336 secs] 208473K->153972K(238536K), 0.0145821 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
29.857: [GC 29.857: [DefNew: 71614K->115K(74112K), 0.0095751 secs] 219892K->154008K(238536K), 0.0096211 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
29.917: [GC 29.918: [DefNew: 65999K->155K(74112K), 0.0025814 secs] 219893K->154048K(238536K), 0.0026308 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
29.969: [GC 29.969: [DefNew: 66040K->224K(74112K), 0.0025861 secs] 219934K->154118K(238536K), 0.0026274 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
30.016: [GC 30.016: [DefNew: 66135K->252K(74112K), 0.0027219 secs] 220029K->154146K(238536K), 0.0027649 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

(... snip about 20 lines ...)

31.643: [GC 31.643: [DefNew: 66382K->459K(74112K), 0.0031689 secs] 220691K->154786K(238536K), 0.0032136 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.702: [GC 31.702: [DefNew: 66366K->453K(74112K), 0.0031310 secs] 220693K->154798K(238536K), 0.0031731 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.759: [GC 31.759: [DefNew: 66370K->447K(74112K), 0.0031629 secs] 220715K->154810K(238536K), 0.0032114 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.818: [GC 31.819: [DefNew: 66356K->441K(74112K), 0.0030518 secs] 220719K->154822K(238536K), 0.0030965 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
31.877: [GC 31.877: [DefNew: 66357K->436K(74112K), 0.0030531 secs] 220737K->154834K(238536K), 0.0030944 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.936: [GC 31.936: [DefNew: 66344K->435K(74112K), 0.0030037 secs] 220743K->154846K(238536K), 0.0030509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=15)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=15)
32.952: [GC 32.952: [DefNew: 66289K->5639K(74112K), 0.0138950 secs] 220700K->166137K(238536K), 0.0139427 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
33.010: [GC 33.010: [DefNew: 71495K->178K(74112K), 0.0091681 secs]33.019: [Tenured: 165972K->166150K(168820K), 0.0815990 secs] 231993K->166150K(242932K), [Perm : 17117K->17117K(17152K)], 0.0909297 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
33.150: [GC 33.151: [DefNew: 69873K->181K(78656K), 0.0023907 secs] 236024K->166332K(253440K), 0.0024277 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
33.207: [GC 33.207: [DefNew: 70076K->200K(78656K), 0.0025056 secs] 236227K->166351K(253440K), 0.0025490 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
33.267: [GC 33.267: [DefNew: 70061K->222K(78656K), 0.0027496 secs] 236212K->166373K(253440K), 0.0027955 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
33.319: [GC 33.319: [DefNew: 70098K->242K(78656K), 0.0025129 secs] 236249K->166393K(253440K), 0.0025520 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

(...many more of these lines...)

40.391: [GC 40.391: [DefNew: 70189K->368K(78656K), 0.0027960 secs] 237896K->168083K(253440K), 0.0028419 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
40.453: [GC 40.453: [DefNew: 70189K->368K(78656K), 0.0030837 secs] 237904K->168092K(253440K), 0.0031416 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
40.517: [GC 40.517: [DefNew: 70258K->439K(78656K), 0.0030203 secs] 237982K->168172K(253440K), 0.0030637 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
40.596: [GC 40.596: [DefNew: 70162K->581K(78656K), 0.0030880 secs] 237895K->168322K(253440K), 0.0031284 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
40.666: [GC 40.666: [DefNew: 70403K->581K(78656K), 0.0030961 secs] 238144K->168331K(253440K), 0.0031403 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=13)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=13)
42.161: [GC 42.161: [DefNew: 70294K->6140K(78656K), 0.0157502 secs] 238044K->179973K(253440K), 0.0158060 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
42.230: [GC 42.230: [DefNew: 75850K->75850K(78656K), 0.0000175 secs]42.230: [Tenured: 173833K->174734K(174784K), 0.1042122 secs] 249684K->179972K(253440K), [Perm : 17126K->17126K(17152K)], 0.1043190 secs] [Times: user=0.09 sys=0.00, real=0.11 secs]
42.379: [Full GC 42.379: [Tenured: 174734K->173476K(174784K), 0.1745277 secs] 253047K->178289K(253440K), [Perm : 17126K->17126K(17152K)], 0.1745924 secs] [Times: user=0.17 sys=0.00, real=0.18 secs]
42.597: [Full GC 42.597: [Tenured: 174556K->174556K(174784K), 0.0899911 secs] 253024K->179018K(253440K), [Perm : 17126K->17126K(17152K)], 0.0900558 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
42.737: [Full GC 42.737: [Tenured: 174556K->174556K(174784K), 0.0914405 secs] 253032K->179387K(253440K), [Perm : 17126K->17126K(17152K)], 0.0915065 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
42.870: [Full GC 42.870: [Tenured: 174556K->174556K(174784K), 0.0859870 secs] 253043K->179396K(253440K), [Perm : 17126K->17126K(17152K)], 0.0860500 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
42.998: [Full GC 42.998: [Tenured: 174556K->173476K(174784K), 0.0873824 secs] 253050K->178325K(253440K), [Perm : 17126K->17126K(17152K)], 0.0874467 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]

(... many more of these lines ...)

76.869: [Full GC 76.869: [Tenured: 174274K->174274K(174784K), 0.0912524 secs] 252500K->180573K(253440K), [Perm : 17121K->17121K(17152K)], 0.0913175 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
77.008: [Full GC 77.008: [Tenured: 174274K->174274K(174784K), 0.0930352 secs] 252503K->181117K(253440K), [Perm : 17121K->17121K(17152K)], 0.0930973 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
77.153: [Full GC 77.153: [Tenured: 174274K->174530K(174784K), 0.1806351 secs] 252506K->175070K(253440K), [Perm : 17121K->17121K(17152K)], 0.1806969 secs] [Times: user=0.19 sys=0.00, real=0.18 secs]
77.398: [Full GC 77.398: [Tenured: 174530K->167748K(174784K), 0.1809714 secs] 252974K->167748K(253440K), [Perm : 17121K->17121K(17152K)], 0.1810366 secs] [Times: user=0.17 sys=0.00, real=0.18 secs]
77.628: [GC 77.628: [DefNew: 69911K->545K(78656K), 0.0025767 secs] 237659K->168293K(253440K), 0.0026206 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77.679: [GC 77.679: [DefNew: 70310K->549K(78656K), 0.0027793 secs] 238058K->168297K(253440K), 0.0028211 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77.729: [GC 77.729: [DefNew: 70314K->553K(78656K), 0.0029654 secs] 238062K->168301K(253440K), 0.0030177 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
77.781: [GC 77.781: [DefNew: 70318K->556K(78656K), 0.0025699 secs] 238066K->168305K(253440K), 0.0026108 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77.831: [GC 77.831: [DefNew: 70319K->560K(78656K), 0.0028679 secs] 238068K->168308K(253440K), 0.0029113 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

(...many more of these lines...)

95.334: [GC 95.334: [DefNew: 70364K->596K(78656K), 0.0025857 secs] 239579K->169816K(253440K), 0.0026218 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
95.392: [GC 95.392: [DefNew: 70360K->596K(78656K), 0.0030850 secs] 239579K->169819K(253440K), 0.0031318 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
95.450: [GC 95.450: [DefNew: 70506K->597K(78656K), 0.0032519 secs] 239730K->169824K(253440K), 0.0032961 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
95.509: [GC 95.509: [DefNew: 70360K->597K(78656K), 0.0030607 secs] 239587K->169828K(253440K), 0.0031071 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
95.566: [GC 95.566: [DefNew: 70364K->597K(78656K), 0.0030067 secs] 239595K->169831K(253440K), 0.0030526 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
95.624: [GC 95.624: [DefNew: 70360K->597K(78656K), 0.0027606 secs] 239595K->169835K(253440K), 0.0027998 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
95.681: [GC 95.681: [DefNew: 70362K->597K(78656K), 0.0029466 secs] 239600K->169839K(253440K), 0.0029982 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
208.497: [GC 208.497: [DefNew: 70549K->926K(78656K), 0.0067911 secs] 239791K->170171K(253440K), 0.0068400 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
518.900: [GC 518.900: [DefNew: 70878K->1267K(78656K), 0.0090123 secs] 240123K->170517K(253440K), 0.0090715 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
540.704: [Full GC (System) 540.704: [Tenured: 169249K->35169K(174784K), 0.1363699 secs] 175870K->35169K(253440K), [Perm : 17122K->17122K(17152K)], 0.1364401 secs] [Times: user=0.13 sys=0.00, real=0.14 secs]

==== after full GC, loading one more image... ====

780.866: [GC 780.867: [DefNew: 69952K->221K(78656K), 0.0032540 secs] 105121K->35390K(253440K), 0.0033047 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[FINE] ImageCache.cleanReferenceQueue() - Removed 28/30 images.
[FINE] ItemsDao.getImage() - Loading image BACKGROUND(id=15)
[FINE] ItemsDao.getImage() - Loading image POSTER(id=15)
958.646: [GC 958.646: [DefNew: 69987K->6444K(78656K), 0.0133042 secs] 105156K->47688K(253440K), 0.0133587 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
958.706: [GC 958.706: [DefNew: 75927K->546K(78656K), 0.0095079 secs] 117171K->47689K(253440K), 0.0095594 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
958.757: [GC 958.757: [DefNew: 70465K->574K(78656K), 0.0020795 secs] 117608K->47717K(253440K), 0.0021204 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
958.798: [GC 958.798: [DefNew: 70232K->556K(78656K), 0.0020284 secs] 117375K->47699K(253440K), 0.0020778 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
958.845: [GC 958.845: [DefNew: 70418K->562K(78656K), 0.0020327 secs] 117561K->47704K(253440K), 0.0020787 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
958.887: [GC 958.887: [DefNew: 70360K->567K(78656K), 0.0022545 secs] 117503K->47710K(253440K), 0.0023004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
958.931: [GC 958.931: [DefNew: 70361K->572K(78656K), 0.0018790 secs] 117504K->47715K(253440K), 0.0019207 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
958.972: [GC 958.972: [DefNew: 70382K->577K(78656K), 0.0020676 secs] 117525K->47720K(253440K), 0.0021110 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
959.017: [GC 959.017: [DefNew: 70379K->582K(78656K), 0.0021859 secs] 117522K->47725K(253440K), 0.0022319 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

..... many more lines ending with....

1087.248: [GC 1087.248: [DefNew: 70550K->1240K(78656K), 0.0023677 secs] 125027K->55719K(253440K), 0.0024073 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1087.309: [GC 1087.309: [DefNew: 70547K->1241K(78656K), 0.0026623 secs] 125026K->55721K(253440K), 0.0027083 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1087.383: [GC 1087.383: [DefNew: 70550K->1240K(78656K), 0.0024384 secs] 125030K->55722K(253440K), 0.0024771 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1087.461: [GC 1087.461: [DefNew: 70933K->1600K(78656K), 0.0028441 secs] 125416K->56084K(253440K), 0.0028849 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points