Desacelerações intermitentes do Tomcat, sem resposta, trava

Question

Estou tentando rastrear a causa de lentidão intermitente do nosso servidor Tomcat. Recebemos lentidão várias vezes por semana, onde o Tomcat para de responder ou leva vários minutos para processar solicitações, e as cargas da CPU na caixa (Linux), como mostrado pelo tempo de atividade, aumentam de 1 a 30 para 30. as coisas gradualmente se resolvem e tudo volta ao normal depois de uns 10 minutos.

Estamos usando o Apache como front-end e o Postgres para nosso banco de dados. Eu tenho cavado os logs para tentar descobrir o que pode estar causando o problema. Eu não notei nenhum aumento óbvio na demanda nos tempos da desaceleração.

O que eu descobri é que, em várias ocasiões, pouco antes da desaceleração, o Tomcat parece apenas adormecer por cerca de três minutos e meio. Não há entradas em seus logs durante esse período nem consultas do Tomcat no banco de dados. Depois de seu pequeno cochilo, o Tomcat vai acordar e começar a processar todas as coisas que já foram copiadas, levando a um pesado banco de dados e carregamento de CPU e tempos de resposta lentos.

Para tentar descobrir o que o Tomcat está fazendo durante seu tempo de sesta, eu configurei um script para monitorar seu log e enviar um sinal de kill-3 para obter um dump de thread se não houver atividade no log para três minutos. Infelizmente, o sinal não ativa o Tomcat, portanto, o despejo de thread não ocorre até que ele tenha acordado por conta própria e tenha retomado o processamento.

Apache e Postgres aparentemente ainda estão acordados e ativos durante os intervalos de três minutos e meio - seus registros mostram que as atividades não relacionadas ao Tomcat continuam durante esses períodos.

Nossa versão do Tomcat é a 5.0.28.

Pensamentos, sugestões? Eu sou muito novo em trabalhar com o Tomcat, então, por favor, não assuma muito conhecimento.

Depois de ativar a coleta de lixo detalhada por sugestão de Alex, capturei algumas ocorrências do problema e descobri que um GC completo era responsável, levando mais de 200 segundos em ambos os casos, por exemplo:

04:21:55.648491500 [GC 1035796K->933637K(1041984K), 0.3407580 secs]
04:21:56.012832500 [Full GC[Unloading class sun.reflect.GeneratedMethodAccessor633]
04:22:38.003920500 [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor39]
04:22:38.004051500 [Unloading class sun.reflect.GeneratedConstructorAccessor102]
04:22:38.004392500 [Unloading class sun.reflect.GeneratedConstructorAccessor98]
04:22:38.004533500 [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor40]
04:22:38.004716500 [Unloading class sun.reflect.GeneratedMethodAccessor634]
04:22:38.004808500 [Unloading class sun.reflect.GeneratedConstructorAccessor90]
04:22:38.004889500 [Unloading class sun.reflect.GeneratedConstructorAccessor95]
04:22:38.005044500 [Unloading class sun.reflect.GeneratedMethodAccessor632]
04:25:18.688916500  933637K->154281K(1041984K), 202.6760940 secs]

Agora só preciso descobrir como ajustar as coisas para evitar isso. (Sugestões bem-vindas.)

Obrigado pela ajuda Alex e Mainguy.

    

Answer 1

O primeiro passo, conforme mencionado acima, é alterar o script de início do tomcat para adicionar o
-verbose: gc -XX: + PrintGCTimeStamps -XX: + PrintGCDetails

Quando você tiver sua lentidão, procure por coisas em catalina.out como "FullGC" ou muitos GCs ...

Eu observaria que, se você ainda não fez isso, aumente o tamanho do heap do tomcat para algo em torno de 1/2 a 3/4 da memória disponível, assumindo que esta caixa JUST executa o tomcat. Por exemplo, para definir o heap máximo como 768 megabytes, você adicionaria: -Xmx768M para JAVA_OPTS

Se você estiver usando o Ubuntu 10.04, essas configurações geralmente estarão localizadas em / etc / default / tomcat6.

    

Answer 2

Isso aconteceu quando um bom pedaço da memória na geração "tenured" do heap Java foi trocado para o disco porque é lixo e não é usado há algum tempo. Quando uma coleção completa é necessária, essa memória deve ser trocada de volta.

Nesse caso, sua resposta é um tanto contraintuitiva: REDUZE o tamanho do heap Java ou descubra que outras coisas estão usando a RAM que está causando a troca. No nosso caso, algumas tarefas em lote noturnas usavam um monte de RAM, fazendo com que a geração antiga fosse trocada para o disco. Então, o primeiro Full GC necessário na manhã seguinte levou FOREVER (mais de 180 segundos, como você está vendo).

Você também pode tentar o coletor de varredura de marca simultânea, o que reduz os tempos do Full GC fazendo a maior parte do trabalho em paralelo. Esta é a melhor documentação que já vi; Há também alguns bons blogs da Sun sobre o assunto: link

    

Answer 3

Tente ativar a coleta de lixo detalhada e veja se é uma pausa na coleta de lixo. Eu acho que um monte enorme, muita alocação de objetos e troca pode causar uma longa pausa, mas esse tempo soa bastante incomum.