Discussion :

[magnus2005]

Bonjour,

c'est un problème que j'ai depuis au moins 2 mois sur une application sur TOMCAT. le serveur tourne et au bout d'un temps X (entre 10 minutes et 10 jours) l'accès à la base (Mysql 5.0) via Hibernate (3.2.6) est bloqué. Pas de log d'erreur.
Donc j'ai ajouté des loggers et j'ai finit par trouver que le code bloquait sur les fonction "list" et sur tout les accès vers la base en général.
En utilisant Your kit Profiler j'ai pus trouver la pile d'appel et surtout ou les accés bloquaient

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
http-0.0.0.0-80-7 [BLOCKED] CPU time: 0:00
ch.qos.logback.classic.Logger.callAppenders(LoggingEvent)
ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable)
ch.qos.logback.classic.Logger.filterAndLog(String, Marker, Level, String, Object[], Throwable)
ch.qos.logback.classic.Logger.log(Marker, String, int, String, Throwable)
org.apache.commons.logging.impl.SLF4JLocationAwareLog.debug(Object)
org.hibernate.jdbc.AbstractBatcher.logOpenPreparedStatement()
org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(String, boolean, ScrollMode)
org.hibernate.loader.Loader.prepareQueryStatement(QueryParameters, boolean, SessionImplementor)
org.hibernate.loader.Loader.doQuery(SessionImplementor, QueryParameters, boolean)
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(SessionImplementor, QueryParameters, boolean)
org.hibernate.loader.Loader.doList(SessionImplementor, QueryParameters)
org.hibernate.loader.Loader.listIgnoreQueryCache(SessionImplementor, QueryParameters)
org.hibernate.loader.Loader.list(SessionImplementor, QueryParameters, Set, Type[])
org.hibernate.loader.criteria.CriteriaLoader.list(SessionImplementor)
org.hibernate.impl.SessionImpl.list(CriteriaImpl)
org.hibernate.impl.CriteriaImpl.list()
...connector.hibernate.HibernateUtil.list(Criteria)
...connector.user.UserHibernateFactory.exist(String, String)
...manager.DomainUserManagerImpl.authenticateUser(String, String, String, boolean)
...domain.Authenticate.<init>(String, String, String, boolean)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse)
...servlet.filter.SetCharacterEncodingFilter.doFilter(ServletRequest, ServletResponse, FilterChain)
java.lang.Thread.run()

Voila c'est donc bloque sur ch.qos.logback.classic.Logger.callAppenders.
S'il vous plait, Quelqu'un a t'il une vague idée sur le sujet, je prend toutes les suggestions.
J'ai plusieurs piste mais rien jusque là n'a pus contrecarrer ce bug et je ne parviens pas à le provoquer.

[djsnipe]

Si les accès sont bloqués, donc en attente de la BDD, il devrait bien y avoir un timeout sur la gestion des transactions et donc un message d'erreur. Sinon, rien dans les logs MySQL ?

[tchize_]

visiblement, c'est ce ch.qos.logback qui foire, je sais pas ce que c'est que ce truc, mais je propose de le virer pour tester?

[magnus2005]

Merci beaucoup pour vos suggestions.
il a 3 jours J'ai téléchargé les sources de logback et supprimé le code contenu dans la méthode callAppender.

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

ch.qos.logback.classic.Logger.callAppenders

Malheureusement cela supprime la log d'hibernate.
J'ai trouvé un obscure bug de DEADLOCK sur multicore qui pouvait exister sur cette librairie. (pour info le BUG pour ma part c'est produit en utilisant la 0.9.8 et j'ai recodé la 0.9.9)
http://bugzilla.qos.ch/show_bug.cgi?id=112.
Le problème est que je ne suis pas parvenu a reproduire ce BUG. J'ai par contre "réussi" à trouver un autre BUG sur CriteriaLoader.list avec un BUG déjà plus connu sur C3P0 qui fait APPARENT DEADLOCK. Ceci dit ce bug n'est pas apparut lors de l'exploitation du serveur mais seulement dans les tests de stress système et il a disparu avec utilisant la config de ce lien http://www.mchange.com/projects/c3p0/index.html par contre en utilisant celle de la doc d'hibernate http://www.hibernate.org/214.html le deadlock ce produit.
Pour le moment, les modifications ont été effectué et le BUG n'est pas réapparu. pas de blocage de l'accès.
Pour l'instant je demeure dans les hypothèses.

J'étais tellement persuadé que le problème venait d'un code Java que j'ai même pas pensé à regarder la log de Mysql ce qui est un oubli grossier. Cependant les Accés à Mysql (Via Mysql Browser) fonctionnaient et fonctionne toujours très bien que l'accès Java soit bloqué.

Voila je ne suis pas sur à 100% d'avoir corrigé mon problème mais j'espère que ce message aidera quelqu'un d'autre à corriger les siens.

[fluff]

Une idée qui m'est venu comme ça :
Ça ne viendrait pas d'un problème d'espace mémoire....

[magnus2005]

Tu veux dire un problème de type "out of memory" ?
En tous cas il n y en pas de trace de ce type. Je me suis aussi posé la question sur le la limitation du nombre de Thread mais d'après YJP la mémoire utilisée est faible et le nombre de Thread est inférieure à 60. Ceci dit l'application a déjà plantée sans que j'ai une quelconque information via YJP (YourKit Java Profiler) ou via la log de base donc rien n'est à exclure.