Модераторы: LSD, AntonSaburov
  

Поиск:

Ответ в темуСоздание новой темы Создание опроса
> Проблема со сборкой мусора 
:(
    Опции темы
vdweller
Дата 2.9.2008, 19:37 (ссылка) | (нет голосов) Загрузка ... Загрузка ... Быстрая цитата Цитата


Новичок



Профиль
Группа: Участник
Сообщений: 35
Регистрация: 1.2.2008

Репутация: нет
Всего: нет
Есть серверное 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]


Думал может приложение переклинивает в этот момент времени, но судя по логам в приложении в момент когда сборщик сходит с ума не происходит никаких критических событий, обычная работа. Может кто нибудь глянет опытным взглядом на логи, в чем может быть проблема?
PM MAIL   Вверх
COVD
Дата 5.9.2008, 12:54 (ссылка) | (нет голосов) Загрузка ... Загрузка ... Быстрая цитата Цитата


Эксперт
***


Профиль
Группа: Завсегдатай
Сообщений: 1655
Регистрация: 26.7.2005

Репутация: 17
Всего: 43
Цитата

Может кто то сталкивался с таким поведением ява машины?


ну как, выяснили, кто виноват?
PM MAIL   Вверх
vdweller
Дата 5.9.2008, 15:29 (ссылка) | (нет голосов) Загрузка ... Загрузка ... Быстрая цитата Цитата


Новичок



Профиль
Группа: Участник
Сообщений: 35
Регистрация: 1.2.2008

Репутация: нет
Всего: нет
Цитата(COVD @ 5.9.2008,  12:54)
ну как, выяснили, кто виноват?

Увы, пока нет
Попробовал увеличить хип для молодого поколения (-XX:NewRatio=5) стабильное время работы увеличилось с часа до 10 часов, но потом все равно сборщик активизируется на всю. Мест выделения такого огромного количества объектов способных за 1 секунду заполнить все ~30 Мб выделенных для NewGen я не нашел в программе, так что пока расследование продолжается smile
PM MAIL   Вверх
Platon
Дата 5.9.2008, 15:40 (ссылка) | (нет голосов) Загрузка ... Загрузка ... Быстрая цитата Цитата


Эксперт
***


Профиль
Группа: Завсегдатай
Сообщений: 1801
Регистрация: 25.4.2006

Репутация: 16
Всего: 40
Не забываем о перекрестных ссылках...
для теста попробуйте попереопределять методы finalize некоторых объектов, в которых будет содержаться вывод на консоль, что объект завершает своё существование. Если вы переопределите в каком-то объекте этот метод, а в консоль от него не поступают сообщения, вот тут-то и собака зарыта.


--------------------
user posted image
Блог на винграде
Мой Блог о Java
For Java developers... only
PM MAIL ICQ   Вверх
COVD
Дата 5.9.2008, 16:03 (ссылка) | (нет голосов) Загрузка ... Загрузка ... Быстрая цитата Цитата


Эксперт
***


Профиль
Группа: Завсегдатай
Сообщений: 1655
Регистрация: 26.7.2005

Репутация: 17
Всего: 43
Можно было бы предположить, что "зацикливается" поток, работающий с селектором - распространенная ошибка при программировании nio. Но вы же используете  MINA, т.е. с этим потоком непосредственно не соприкасаетесь.
PM MAIL   Вверх
vdweller
Дата 7.9.2008, 18:29 (ссылка) | (нет голосов) Загрузка ... Загрузка ... Быстрая цитата Цитата


Новичок



Профиль
Группа: Участник
Сообщений: 35
Регистрация: 1.2.2008

Репутация: нет
Всего: нет
При определенных условиях зацикливался один из потоков работы с клиентами, который на каждой итерации создавал пачку ArrayList, всем спасибо, сам дурак smile
PM MAIL   Вверх
  
 Ответ в темуСоздание новой темы Создание опроса
Правила форума "Java"
LSD   AntonSaburov
powerOn   tux
javastic
  • Прежде, чем задать вопрос, прочтите это!
  • Книги по Java собираются здесь.
  • Документация и ресурсы по Java находятся здесь.
  • Используйте теги [code=java][/code] для подсветки кода. Используйтe чекбокс "транслит", если у Вас нет русских шрифтов.
  • Помечайте свой вопрос как решённый, если на него получен ответ. Ссылка "Пометить как решённый" находится над первым постом.
  • Действия модераторов можно обсудить здесь.
  • FAQ раздела лежит здесь.

Если Вам помогли, и атмосфера форума Вам понравилась, то заходите к нам чаще! С уважением, LSD, AntonSaburov, powerOn, tux, javastic.
 
0 Пользователей читают эту тему (0 Гостей и 0 Скрытых Пользователей)
0 Пользователей:
« Предыдущая тема | Java: Общие вопросы | Следующая тема »

Подписаться на тему | Подписка на этот форум | Скачать/Распечатать тему


 




[ Время генерации скрипта: 0.0448 ]   [ Использовано запросов: 22 ]   [ GZIP включён ]


Реклама на сайте     Информационное спонсорство

 
 По вопросам размещения рекламы пишите на vladimir(sobaka)vingrad.ru
Отказ от ответственности     Powered by Invision Power Board(R) 1.3 © 2003  IPS, Inc.