Есть серверное J2SE приложение написанное на базе Apache Mina. При работе на боевом сервере под небольшой нагрузкой (около 10 клиентов и порядка 1 сообщения в секунду) после некоторого времени работы (порядка 1 часа) приложение начинает грузить процессор на 100% (loadaverages >=1, 1 процессор), причем даже при почти полном исчезании коннектов нагрузка остается. После небольших разборок выяснилось что активизируется сборщик мусора и количество сборок мусора начинает зашкаливать (по несколько сборок в секунду), при этом используемая память постоянно скачет с 3 мегабайт до 40 - 50 и обратно в течении 20-30 секунд. Но все дело в том что никаких крупных объектов не выделяется в это время, сетевые сообщения "весят" порядка 50-100 байт, даже с учетом накладных расходов получается совсем мало, никак не 40 Мб, которые успевают выделиться за это время, а кроме них никакие данные не обрабатываются, да и размер хипа выставлен как -Xms128M -Xmx128M. Может кто то сталкивался с таким поведением ява машины?
Система на сервере freebsd 6.3, java version "1.6.0_03-p4" (также пробовал diablo-jdk-1.6, изменений никаких)
Вот логи сборки мусора:
Сначала все идет нормально
| Код |
0.904: [Full GC (System) 0.904: [Tenured: 0K->577K(116544K), 0.0445170 secs] 5782K->577K(129664K), [Perm : 3064K->3064K(16384K)], 0.0446240 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
35.043: [GC 35.043: [DefNew: 11712K->437K(13120K), 0.0120930 secs] 12289K->1015K(129664K), 0.0122370 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
151.594: [GC 151.594: [DefNew: 12149K->456K(13120K), 0.0044850 secs] 12727K->1034K(129664K), 0.0046150 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
356.445: [GC 356.445: [DefNew: 12168K->358K(13120K), 0.0038040 secs] 12746K->936K(129664K), 0.0039290 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
...
3067.719: [GC 3067.720: [DefNew: 11943K->241K(13120K), 0.0024650 secs] 12791K->1092K(129664K), 0.0025920 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
3223.277: [GC 3223.277: [DefNew: 11953K->153K(13120K), 0.0024860 secs] 12804K->1060K(129664K), 0.0026190 secs] [Times: user=0.00 sys=0.01, real=0.00 secs]
3494.815: [GC 3494.815: [DefNew: 11865K->142K(13120K), 0.0022030 secs] 12772K->1059K(129664K), 0.0023330 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
3600.951: [Full GC (System) 3600.951: [Tenured: 917K->1006K(116544K), 0.0603570 secs] 6189K->1006K(129664K), [Perm : 5600K->5600K(16384K)], 0.0605030 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
|
потом ни с того ни с сего сборки начинают сыпаться по несколько в секунду
| Код |
4323.797: [GC 4323.797: [DefNew: 11809K->105K(13120K), 0.0016370 secs] 12816K->1112K(129664K), 0.0017620 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
4472.709: [GC 4472.709: [DefNew: 11817K->134K(13120K), 0.0023120 secs] 12824K->1141K(129664K), 0.0024460 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
4574.036: [GC 4574.036: [DefNew: 11846K->123K(13120K), 0.0017580 secs] 12853K->1130K(129664K), 0.0018900 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4655.637: [GC 4655.637: [DefNew: 11835K->164K(13120K), 0.0020120 secs] 12842K->1171K(129664K), 0.0021430 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4655.690: [GC 4655.690: [DefNew: 11876K->163K(13120K), 0.0018120 secs] 12883K->1170K(129664K), 0.0019280 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
4655.740: [GC 4655.740: [DefNew: 11875K->157K(13120K), 0.0018030 secs] 12882K->1164K(129664K), 0.0019220 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4655.789: [GC 4655.789: [DefNew: 11869K->156K(13120K), 0.0016580 secs] 12876K->1163K(129664K), 0.0017710 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4655.838: [GC 4655.838: [DefNew: 11868K->154K(13120K), 0.0016380 secs] 12875K->1161K(129664K), 0.0017520 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
4655.887: [GC 4655.887: [DefNew: 11866K->154K(13120K), 0.0017140 secs] 12873K->1161K(129664K), 0.0018270 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4655.937: [GC 4655.937: [DefNew: 11866K->153K(13120K), 0.0016330 secs] 12873K->1160K(129664K), 0.0017460 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
4655.986: [GC 4655.986: [DefNew: 11865K->152K(13120K), 0.0016170 secs] 12872K->1159K(129664K), 0.0017300 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
4656.035: [GC 4656.035: [DefNew: 11864K->151K(13120K), 0.0016250 secs] 12871K->1158K(129664K), 0.0017400 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4656.085: [GC 4656.085: [DefNew: 11863K->132K(13120K), 0.0017230 secs] 12870K->1158K(129664K), 0.0018360 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4656.134: [GC 4656.134: [DefNew: 11844K->125K(13120K), 0.0016540 secs] 12870K->1158K(129664K), 0.0017660 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
4656.190: [GC 4656.190: [DefNew: 11837K->116K(13120K), 0.0015670 secs] 12870K->1156K(129664K), 0.0016880 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
4656.241: [GC 4656.241: [DefNew: 11828K->108K(13120K), 0.0015640 secs] 12868K->1155K(129664K), 0.0016780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4656.290: [GC 4656.290: [DefNew: 11820K->73K(13120K), 0.0013990 secs] 12867K->1141K(129664K), 0.0015080 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
4656.339: [GC 4656.339: [DefNew: 11785K->62K(13120K), 0.0013280 secs] 12853K->1141K(129664K), 0.0014370 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
4656.387: [GC 4656.387: [DefNew: 11774K->0K(13120K), 0.0013620 secs] 12853K->1141K(129664K), 0.0014700 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4656.435: [GC 4656.436: [DefNew: 11712K->0K(13120K), 0.0009620 secs] 12853K->1141K(129664K), 0.0010850 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4656.484: [GC 4656.484: [DefNew: 11712K->0K(13120K), 0.0009190 secs] 12853K->1141K(129664K), 0.0010150 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
|
Думал может приложение переклинивает в этот момент времени, но судя по логам в приложении в момент когда сборщик сходит с ума не происходит никаких критических событий, обычная работа. Может кто нибудь глянет опытным взглядом на логи, в чем может быть проблема?
|
