Discussoes de Programacao e Tecnologia

[Resolvido]Log4J está travando o VRaptor

31 respostas
R
Rafael_Guerreiro

Pessoal, bom dia!

Eu coloquei o log4j.properties na minha aplicação e funcionou bonitinho… O problema é q depois de algumas requisições, ele trava tudo. E o último log dele é que está buscando conexões com o banco… mas fica nisso para sempre…

Alguma ideia do que pode ser?

Alura Sistemas operacionais: entenda seu conceito e suas funções Descubra o que são sistemas operacionais, suas funções e tipos. Aprenda tudo de forma clara e objetiva. Não perca tempo!

31 Respostas

P
pedruhenrik

não seria problema de conexões com o banco ?

qual o erro?

att,

L
Lucas_Cavalcanti

vc está fechando as conexões/sessions/entitymanagers?

R
Rafael_Guerreiro

Não tem erro… Simplesmente fica travado…

Eu as sessões são fechadas pelo próprio VRaptor com um método no meu Criador de Sessões anotado com @PreDestroy

L
Lucas_Cavalcanti

justamente, qdo vc usa todas as conexões ele fica travado esperando pegar uma nova…

coloca um log no seu método anotado com @PreDestroy e ve se tá passando por lá mesmo

R
Rafael_Guerreiro

Lucas, ele está passando e fechando todas… A princípio parecia q nao ia travar, mas travou… =/

L
Lucas_Cavalcanti

vc tá usando qual banco?

habilita as estatísticas do hibernate (algo como hibernate.generate-statistics = true no hibernate.cfg.xml)

e faz manda mostrar em algum lugar o sessionFactory.getStatistics().getOpenSessions() e getClosedSessions() ou algo do tipo…

assim vc consegue ver se esses números estão diferentes

R
RafaelViana

Lucas Cavalcanti:
vc tá usando qual banco?

habilita as estatísticas do hibernate (algo como hibernate.generate-statistics = true no hibernate.cfg.xml)

e faz manda mostrar em algum lugar o sessionFactory.getStatistics().getOpenSessions() e getClosedSessions() ou algo do tipo…

assim vc consegue ver se esses números estão diferentes

Para testar estas estatísticas gosto bastante do Hibernate Profiler ele tem uma interface visual bem agradável para visualizar estes dados.

M
marciavilaca

posta o o seu log4j.properties

R
Rafael_Guerreiro

Eu estou usando o MySql...

Eu fiz esse código toda vez antes de abrir uma sessão e o resultado foi:

-Edit-

Coloquei depois de abrir uma session e o resultado é o mesmo. Desta vez devia ter sempre uma aberta...

Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Sessions ABERTAS - 0-------------------------------------
Sessions FECHADAS - 0-------------------------------------
Meu log4j.properties: 
log4j.rootCategory=INFO, S

log4j.logger.com.dappit.Dapper.parser=ERROR
log4j.logger.org.w3c.tidy=FATAL
log4j.appender.S = org.apache.log4j.ConsoleAppender
log4j.appender.S.layout = org.apache.log4j.PatternLayout
log4j.appender.S.layout.ConversionPattern = %d{yyyy-MM-dd HH:mm:ss} %c{1} [%p] %m%n
log4j.appender.R = org.apache.log4j.DailyRollingFileAppender
log4j.appender.R.File = logs/bensApps.log
log4j.appender.R.Append = true
log4j.appender.R.DatePattern = '.'yyy-MM-dd
log4j.appender.R.layout = org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern = %d{yyyy-MM-dd HH:mm:ss} %c{1} [%p] %m%n
log4j.appender.H = org.apache.log4j.RollingFileAppender
log4j.appender.H.File = logs/bensApps.html
log4j.appender.H.MaxFileSize = 100KB
log4j.appender.H.Append = false
log4j.appender.H.layout = org.apache.log4j.HTMLLayout
L
Lucas_Cavalcanti

vc colocou a configuração para gerar estatísticas do hibernate?

R
Rafael_Guerreiro

Sim… Como você mostrou… Mas como sei se está funcionando?

L
Lucas_Cavalcanti

vc sabe se está funcionando se ele gera alguma estatística…

o que vc usou é essa?

<property name="hibernate.generate_statistics">true</property>
R
Rafael_Guerreiro

Eu uso a consiguração programática:

L
Lucas_Cavalcanti

não é -, é _

R
Rafael_Guerreiro

Excelente observação

Agora ele funciona…

Sessions ABERTAS - 0------------------------------------- Sessions FECHADAS - 0------------------------------------- // Abre sessão Sessions ABERTAS - 1------------------------------------- Sessions FECHADAS - 0------------------------------------- Sessions ABERTAS - 1------------------------------------- Sessions FECHADAS - 1------------------------------------- // Abre sessão Sessions ABERTAS - 2------------------------------------- Sessions FECHADAS - 1-------------------------------------

L
Lucas_Cavalcanti

coloca o cara que fica imprimindo isso separado das requests (num @applicationScoped, abrindo uma thread que imprime isso a cada 5s por exemplo) e vai acessando a aplicação até travar…

vc viu que a diferença entre abertas e fechadas já começou a aparecer?

R
Rafael_Guerreiro

Não consegui fazer isso:
(num @applicationScoped, abrindo uma thread que imprime isso a cada 5s por exemplo)

Ainda não tem diferença nas sessions…

L
Lucas_Cavalcanti

mesmo qdo trava?

R
Rafael_Guerreiro

mesmo…

L
Lucas_Cavalcanti

qual é o log onde ele para quando trava? posta o finalzinho dele aqui plz

R
Rafael_Guerreiro

2011-07-21 18:17:33 TableMetadata [INFO] foreign keys: [] 2011-07-21 18:17:33 TableMetadata [INFO] indexes: [primary] 2011-07-21 18:17:33 TableMetadata [INFO] table found: warriorsoft44.wsm_pais 2011-07-21 18:17:33 TableMetadata [INFO] columns: [nom_pais, cod_pais] 2011-07-21 18:17:33 TableMetadata [INFO] foreign keys: [] 2011-07-21 18:17:33 TableMetadata [INFO] indexes: [nom_pais, primary] 2011-07-21 18:17:33 SchemaUpdate [INFO] schema update complete Sessions ABERTAS - 28------------------------------------- Sessions FECHADAS - 27------------------------------------- Sessions ABERTAS - 29------------------------------------- Sessions FECHADAS - 27-------------------------------------

Agora ele não está fechando… até a 27 estava tudo ok

R
Rafael_Guerreiro
mudei o meu log4j.properties para:
### direct log messages to stdout ###  
log4j.appender.stdout=org.apache.log4j.ConsoleAppender  
log4j.appender.stdout.Target=System.out  
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout  
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n  
  
### direct messages to file hibernate.log ###  
#log4j.appender.file=org.apache.log4j.FileAppender  
#log4j.appender.file.File=hibernate.log  
#log4j.appender.file.layout=org.apache.log4j.PatternLayout  
#log4j.appender.file.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n  
  
### set log levels - for more verbose logging change 'info' to 'debug' ###  
  
log4j.rootLogger=warn, stdout  
  
#log4j.logger.org.hibernate=info  
log4j.logger.org.hibernate=debug  
  
### log HQL query parser activity  
#log4j.logger.org.hibernate.hql.ast.AST=debug  
  
### log just the SQL  
#log4j.logger.org.hibernate.SQL=debug  
  
### log JDBC bind parameters ###  
log4j.logger.org.hibernate.type=info  
#log4j.logger.org.hibernate.type=debug  
  
### log schema export/update ###  
log4j.logger.org.hibernate.tool.hbm2ddl=debug  
  
### log HQL parse trees  
#log4j.logger.org.hibernate.hql=debug  
  
### log cache activity ###  
#log4j.logger.org.hibernate.cache=debug  
  
### log transaction activity  
#log4j.logger.org.hibernate.transaction=debug  
  
### log JDBC resource acquisition  
#log4j.logger.org.hibernate.jdbc=debug  
  
### enable the following line if you want to track down connection ###  
### leakages when using DriverManagerConnectionProvider ###  
#log4j.logger.org.hibernate.connection.DriverManagerConnectionProvider=trace
e o último log foi:
Sessions ABERTAS - 32-------------------------------------
Sessions FECHADAS - 30-------------------------------------
18:36:43,599 DEBUG ConnectionManager:444 - opening JDBC connection
  18:36:43,599 DEBUG SessionImpl:257 - opened session at timestamp: [telefone removido]
  18:36:43,599 DEBUG JDBCTransaction:87 - current autocommit status: false
  18:36:43,604 DEBUG JDBCTransaction:82 - begin
  18:36:43,604 DEBUG ConnectionManager:444 - opening JDBC connection
  18:36:43,605 DEBUG JDBCTransaction:87 - current autocommit status: false
  18:36:43,655 DEBUG SessionImpl:257 - opened session at timestamp: [telefone removido]
  18:36:43,655 DEBUG JDBCTransaction:82 - begin
  18:36:43,656 DEBUG ConnectionManager:444 - opening JDBC connection
  18:36:43,660 DEBUG SessionImpl:257 - opened session at timestamp: [telefone removido]
  18:36:43,663 DEBUG JDBCTransaction:82 - begin
  18:36:43,663 DEBUG ConnectionManager:444 - opening JDBC connection
  18:36:43,669 DEBUG SessionImpl:257 - opened session at timestamp: [telefone removido]
  18:36:43,669 DEBUG JDBCTransaction:82 - begin
  18:36:43,669 DEBUG ConnectionManager:444 - opening JDBC connection
L
Lucas_Cavalcanti

tenta procurar algum lugar da sua aplicação que ele pode estar abrindo uma sessão e não está fechando…

coloca um int estático no seu CriadorDeSession e no construtor dele guarde o int e incremente o valor.

daí vc imprime o número no openSession e no session.close(), pra ver se algum deles não é fechado

L
Lucas_Cavalcanti

outra coisa: vc tá com o c3p0 configurado?

R
Rafael_Guerreiro

Estou com o c3p0 sim…

configuration.setProperty("hibernate.connection.provider_class", "org.hibernate.connection.C3P0ConnectionProvider"); configuration.setProperty("hibernate.c3p0.timeout", "30"); configuration.setProperty("hibernate.c3p0.min_size", "5"); configuration.setProperty("hibernate.c3p0.max_size", "20"); configuration.setProperty("hibernate.c3p0.max_statements", "50");

o último log mudou denovo…

18:56:05,399 DEBUG TwoPhaseLoad:131 - resolving associations for [br.com.wsacervoweb.vo.Midia#3] 18:56:05,400 DEBUG TwoPhaseLoad:239 - done materializing entity [br.com.wsacervoweb.vo.Midia#3] 18:56:05,400 DEBUG StatefulPersistenceContext:892 - initializing non-lazy collections 18:56:05,400 DEBUG ConnectionManager:464 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 18:56:05,400 DEBUG Loader:1946 - done entity load Quantidade de sessions fechadas - 33-------------------------------------- 18:56:05,407 DEBUG ConnectionManager:464 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] Quantidade de sessions fechadas - 33--------------------------------------

L
Lucas_Cavalcanti

conta qtos ConnectionManager:444 - opening JDBC connection aparecem, e qtos ConnectionManager:464 - releasing JDBC connection

R
Rafael_Guerreiro

É, Lucas… Acho que o problema está nas Sessions…

Houveram 25 ConnectionManager:444 - opening JDBC connection e 13 ConnectionManager:464 - releasing JDBC connection quando travou.

E travou em um ConnectionManager:444 - opening JDBC connection.

L
Lucas_Cavalcanti

vc precisa procurar, então, as sessões que não estão sendo fechadas.

vc está usando o sessionFactory diretamente em algum lugar, ou só no CriadorDeSession?

R
Rafael_Guerreiro

É! Acho que é esse o problema… Tem alguns lugares que eu entro direto la… Para que eu possa acessar outro banco…

L
Lucas_Cavalcanti

pois eh, vc precisa ver se vc tá fechando todas as sessions q vc abre por fora.

R
Rafael_Guerreiro

Consegui resolver o problema… Era isso mesmo, sessions que nao eram fechadas… E estava justamente em um interceptor que acontece o tempo todo…

Criado 21 de julho de 2011
Ultima resposta 22 de jul. de 2011
Respostas 31
Participantes 5

Topicos relacionados

Como lidar com esse tipo de problema programadores: 31 respostas Código de Barras? 11 respostas O Eclipse não está identificando meu projeto como Java 5 respostas Efetuar soma no iReport 4.0.2 7 respostas Selecionando data em um datepicker 3 respostas
Fiap Graduacao em Tecnologia — FIAP Analise e Desenvolvimento de Sistemas, Engenharia de Software e mais
Casa do Codigo Casa do Codigo — Livros de tecnologia Livros de programacao, infraestrutura e inovacao