Jean FRANCOIS blog [Weblogic / Java EE / SOA]: Stuck Thread

Affichage des articles dont le libellé est Stuck Thread. Afficher tous les articles

vendredi 28 janvier 2011

WLDF : Stuck Treads & Log Notification

08:00 |

Publié par Jean FRANCOIS |

Modifier l'article

OBJECTIF

L’objectif et de mettre en place une remonté d’alerte sur la présence de threads en blocage sur la plateforme Weblogic/OSB. Pour cela on peut utiliser le module WLDF de Weblogic en remontant l’information par mail.

La procédure consiste à paramétrer Weblogic pour dire au bout de combien de temps on considère qu’un thread est en blocage pour pouvoir remonter l’information dans le log Weblogic (Message ID=BEA-320068). Cette information sera ensuite capturée par une configuration WLDF pour remonter l’information via Mail ou JMS.

L’avantage de cette méthode est que l’on n’est pas obligé de monitorer l’ensemble des WorkManager pour détecter les StuckThreads car quelque soit l’application responsable elle lèvera une notification dans le log Weblogic. L’inconvenant c’est que l’on n’aura pas la finesse de l’information sur la provenance du StuckThread.

STUCK THREAD

http://j-francois.blogspot.com/2010/04/stuckthreadmaxtime.html

Un thread est considéré en blocage s’il prend du temps à s’exécuter (en attente ou en exécution). Il faut donc préciser un temps au bout duquel on considère que le thread en activité est en blocage.

Pour cela, il faut préciser à Weblogic le TIMEOUT au bout duquel on marque le thread en STUCK, ainsi que la fréquence de recherche de threads en STUCK.

Pour le paramétrage du TIMEOUT, il faut se connecter à la console d’administration du domaine et de paramétrer chaque instance de la façon suivante :

http://${ip}:${port}/console

${domaine}àEnvironmentàServersà${instance}àConfigurationàTuning

Stuck Thread Max Time	Le temps au bout duquel on considère que le thread est bloqué
Stuck Thread Timer Interval	La fréquence de contrôle

Changer la valeur de Stuck Thread Max Time en diminuant la valeur par défaut (si besoin) qui est de 10 minutes.

Si des Threads sont en blocage, Weblogic les remonte dans son log et le notifier dans le MBean associé au Workmanager de la ressource. Pour le log Weblogic, on a l’entrée suivante :

Exemple d’un log Weblogic sur un StuckThread

####<23 juil. 2009 03 h 14 VET>

<[ACTIVE] ExecuteThread: '72' for queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <> <1248335056672> <[STUCK] ExecuteThread: '64' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "44" seconds working on the request "weblogic.servlet.internal.ServletRequestImpl@b5839e[

GET /TestFreez/Freez.jsp HTTP/1.1

Accept: */*

Referer: http://localhost:7001/console/console.portal?_nfpb=true&_pageLabel=WebAppApplicationTestingPage&handle=

com.bea.console.handles.AppDeploymentHandle%28%22com.bea%3AName%3DTestFreez%2CType

%3DAppDeployment%22%29

Accept-Language: fr

Accept-Encoding: gzip, deflate

User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.30; .NET CLR 3.0.04506.648)

Connection: Keep-Alive

]", which is more than the configured time (StuckThreadMaxTime) of "30" seconds. Stack trace:

Thread-79 "[STUCK] ExecuteThread: '64' for queue: 'weblogic.kernel.Default (self-tuning)'" {

java.lang.Thread.sleep(Thread.java:???)

jsp_servlet.__freez._jspService(__freez.java:61)

weblogic.servlet.jsp.JspBase.service(JspBase.java:34)

weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:224)

weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:108)

weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:198)

weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:175)

weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run

(WebAppServletContext.java:3468)

weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:308)

weblogic.security.service.SecurityManager.runAs(Unknown Source)

weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2116)

weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2038)

weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1372)

weblogic.work.ExecuteThread.execute(ExecuteThread.java:198)

weblogic.work.ExecuteThread.run(ExecuteThread.java:165)

}

WLDF

Création d’un module WLDF pour la remontée d’alerte. Il faut pour cela :

Créer un module WLDF pour y créer des ressources associées au monitoring.
Créer des sources de Notifications pour pouvoir remonter les informations (Mail, JMS, etc …)
Créer des règles de remontées d’alerte (Watchs) à associer aux sources de Notification.

Il faudra paramétrer la sévérité d’observation pour remonter les problèmes.

WLDF MODULE

La création d’un module est nécessaire pour la suite. Elle ne sert qu’a organiser et rassembler les ressources que l’on va créer par la suite.

Lock & Edit

${domaine}àEnvironmentàDiagnosticsàDiagnostic ModulesàNew

Name : Module

Description : Module de Monitoring

Activate Changes

Penser à le targer sur l’instance.

CREATION DES NOTIFICATIONS

Plusieurs sources de notifications sont possibles :

SMTP Via une session mail
JMS Sur une file de messages
Diagnostique Image Dans un fichier de diagnostic
SNMP Via une remontée SNMP

PREREQUIS

Pour une notification mail, il faut d’abord créer une Session Mail.

${domaine}àServicesàMail SessionsàDiagnostic ModulesàNew

Pour une notification JMS, il faudra créer une file de messages

${domaine}àServicesàMessagingàJMS Modulesà${module}à${queue}/${factory}

Pour une notification par trap SNMP, il faut activer l’agent dans Weblogic et paramétrer l’outil externe pour récupérer la notification.

${domaine}àDiagnosticsàSNMPàAgentsà${nom de domaine}àEnabled

CREATION DE LA SOURCE DE NOTIFICATION

Lock & Edit

Aller sous le module

${domaine}àDiagnosticsàDiagnostic Modulesà${module}àConfigurationàWatches and NotificationàNotificationsàNew

Donner un nom logique au service et son type :

Renseigner les informations associées à la source (le destinataire et le contenu du mail)

Finish

Activate Changes

CREATION DE L’ALERTE

On définit ici la règle qui déclenche l’alerte, ainsi que la source pour la remonter.

CREATION DE L’ALERTE

Lock & Edit

${domaine}àEnvironmentàDiagnosticsàDiagnostic Modulesà${module}àConfigurationàWatches and NotificationàWatchesàNew

Préciser un nom logique de la notification.

Watch Name Nom logique

Watch Type Server Log

Définition de la règle d’activation de l’alerte sur l’entrée dans le log par rapport à un Message ID particulier.

Add Expressions

Finish

ASSOCIATION DE L’ALERTE A LA DESTINATION

Se repositionner dans l’alerte définie pour lui associer une destination (Mail)

Notitication

Sélectionner la notification créée précédemment

Activate Changes

FREQUENCE DE VERIFICATION

Penser à régler la sévérité pour pouvoir remonter l’information correctement

Libellés : LOG, MONITORING, Stuck Thread, TROUBLESHOOTING, WLDF |

0 commentaires

jeudi 8 avril 2010

StuckThreadMaxTime

12:11 |

Publié par Jean FRANCOIS |

Modifier l'article

Pour détecter des contentions de Threads on peut utiliser l’option Weblogic StuckThreadMaxTime. Cette option permet de définir un temps au bout duquel on considère qu’un thread a pris trop de temps pour s’exécuter.

Un thread peut prendre du temps pour deux raisons :

ü Soit, il exécute un code trop long (boucle, etc … ) consommateur de CPU.

ü Soit, il attend une réponse d’un composant externe au thread (un lock d’un autre thread ou une ressource distante).

La seule façon d’investiguer sur ces problèmes est d’en être informé et d’avoir des informations à analyser.

PARAMETRAGE

Le paramétrage se fait via la console Weblogic ou un scripte WLST sur chaque instance.

Consoleà${domaine}àEnvironmentàServersà${instance}àConfigurationàTuning

Stuck Thread Max Time	Le temps au bout duquel on considère que le thread prend trop de temps.
Stuck Thread Timer Interval	L’intervalle de temps pour vérifier que les threads n’ont pas dépassé le temps indiqué dans le 1er paramétré.

Le paramétrage par défaut est de 10 minutes. Pour fixer le temps au bout duquel on considère qu’une requête prend trop de temps, on peut prendre le scénario le plus long et doubler ce temps comme seuil d’alerte.

ALERTE

Pour être alerté sur des Stuck, on pourra monitorer les MBean des WorkManager des applications pour relever le nombre de thread en blocage.

WorkManagerRuntime : com.bea:ServerRuntime=${server},Name=${name},ApplicationRuntime=${ressource name},Type=WorkManagerRuntime

Attribut : StuckThreadCount

ANALYSE

Weblogic détecte les Thread Stuck et le notifie dans son log en indiquant le temps de blocage, l’URL responsable et le code JAVA en cours d’exécution. L’analyse étant de décrypter la stack JAVA.

Exemple d’un log Weblogic sur un StuckThread

####<23 juil. 2009 03 h 14 VET>

GET /TestFreez/Freez.jsp HTTP/1.1

Accept: */*

Referer: http://localhost:7001/console/console.portal?_nfpb=true&_pageLabel=WebAppApplicationTestingPage&handle=com.bea.console.handles.AppDeploymentHandle%28%22com.bea%3AName%3DTestFreez%2CType%3DAppDeployment%22%29

Accept-Language: fr

Accept-Encoding: gzip, deflate

User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.30; .NET CLR 3.0.04506.648)

Connection: Keep-Alive

]", which is more than the configured time (StuckThreadMaxTime) of "30" seconds. Stack trace:

Thread-79 "[STUCK] ExecuteThread: '64' for queue: 'weblogic.kernel.Default (self-tuning)'" {

java.lang.Thread.sleep(Thread.java:???)

jsp_servlet.__freez._jspService(__freez.java:61)

weblogic.servlet.jsp.JspBase.service(JspBase.java:34)

weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:224)

weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:108)

weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:198)

weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:175)

weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3468)

weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:308)

weblogic.security.service.SecurityManager.runAs(Unknown Source)

weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2116)

weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2038)

weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1372)

weblogic.work.ExecuteThread.execute(ExecuteThread.java:198)

weblogic.work.ExecuteThread.run(ExecuteThread.java:165)

}

CORRECTION

On ne peut pas libérer le thread en blocage (interdit par la JVM et le serveur d’applications). La seule solution et de supprimer la cause du blocage ou d’établir un timeout avec retour d’exception en aval. La raison du blocage peut-être :

ü Une contention de la ressource externe (un lock de base, une ressource distante en difficulté).

ü Une défaillance du code.

Libellés : Stuck Thread, TROUBLESHOOTING, WEBLOGIC |

0 commentaires

mercredi 7 avril 2010

WEBLOGIC StuckThreads

05:38 |

Publié par Jean FRANCOIS |

Modifier l'article

Le thread permet d’exécuter le code JAVA sur la CPU comme les processus sur le serveur (unité d’exécution). Le serveur d’applications permet de fournir un certain nombre de thread pour traiter les requêtes utilisateur (à une URL correspond un code JAVA spécifié par les descripteurs J2EE). Ces threads peuvent prendre du temps ou être mises en contention due au code qui s’exécute. Deux cas de contention peuvent se présenter :

ü Attente d’une ressource externe (attente sur une table en lock, lock du code JAVA).

ü Exécution de façon anormalement longue (boucle, appels multiples)

Pour détecter qu’un thread est long ou en contention, plusieurs méthodes peuvent être mises en œuvre à différents niveaux. L’instance Weblogic reçoit les requêtes utilisateur ‹ via le réseauŒ, le pool de threads et le Workmanager exécuter ces requêtes en déclenchant le code applicatifŽ.

Cinq points de mesure peuvent donc être mise en place :

ü Temps de réponse client ‹

ü Temps des requêtes Œ

ü Temps des threads

ü Temps des méthodes Ž

ü Temps des requêtes sur le backend.

Concernant les requêtes, nous pouvons utiliser les access log, pour les threads nous pouvons observer les comportements via les MBean du pool de thread et des WorkManager. Pour l’application, il faudra passer par du profiling JAVA. Pour la partie client, ou pourra utiliser des outils sur le navigateur type http Watch ou IE Watch.

L’objectif étant de fractionner le temps global en temps intermédiaires associés à chaque tiers traversé, afin de définir les responsabilités sur des dégradations de temps de réponse sachant que l’architecture est une composée d’éléments hétérogènes.

CLIENT

Les temps constatés sont dans un premier temps relevés du côté client avec une objectivité toute relative. Il faut donc un outil impartial pour notifier ces temps et observer les requêtes HTTP les plus couteuses.

Dans le cas d’un client Web on pourra utiliser un outil type HTTP Watch ou IE Watch afin de récupérer ces temps par URL et d’investiguer sur les trames retour.

Pour un client JAVA lourd, il faudra passer par les temps d’exécution du processus où instrumenter le code client pour obtenir ces informations.

Dans le cas d’un test de charge, c’est l’outil d’injection qui se charge de relever les temps unitaire et moyen.

REQUETES

Les requêtes utilisateur peuvent être monitoré côté client, mais également côté serveur. Sur la partie serveur, ce sont les access log qui peuvent donner l’information. Il faut pour cela les paramétrer en rajoutant un champ associé au temps de réponse (temps de traitement du serveur JEE)

Pour ajouter ce temps de requêtage, il suffit de se positionner via la console Weblogic :

EnvironnementàServersà${le serveur}àLoggingàHTTP

Format : Extended

Extended Logging Format Fields : date time cs-method cs-uri sc-status time-taken

Extraction de la documentation

time-taken

Time taken for transaction to complete in seconds, field has type , as defined in the W3C specification.

Exemple sans le champs time-taken

127.0.0.1 - - [30/juil./2009:11:45:12 -0430] "GET /em/images/EM_Loginarea_Background.png HTTP/1.1" 200 3610

Avec le mode extened log et le time-taken

#Version: 1.0

#Fields: date time cs-method cs-uri sc-status time-taken

#Software: WebLogic

#Start-Date: 2009-10-09 04:35:08

2009-10-09 04:35:08 GET /TestSession/ 200 0.172

2009-10-09 04:35:09 GET /TestSession/ 200 0.015

2009-10-09 04:35:09 GET /TestSession/ 200 0.0

2009-10-09 04:35:17 GET /TestSession/ 200 0.0

2009-10-09 04:35:18 GET /TestSession/ 200 0.0

2009-10-09 04:35:19 GET /TestSession/ 200 0.0

2009-10-09 04:35:19 GET /TestSession/ 200 0.016

Vous pouvez utiliser ce log avec l’outil WLSAccessLogReport.ou effectuer une macro Excel.

Vue Excel de l’outil WLSAccessLogReport.

THREADS

Côté serveur d’applications, c’est le temps d’exécution des threads qui peut nous informer sur les temps passés dans les requêtes. Concernant les temps dégradés, on pourra activer des options de Weblogic afin d’être notifié et d’agir sur cet événement.

Trois possibilités nous sont offertes pour observer les contentions :

ü Œ Le pool de thread avec un monitoring.

ü Le WorkManager nécessitant un paramétrage spécifique.

ü Ž La notification via le log Weblogic.

POOL THREADS

Le pool de thread est géré automatiquement sur les besoins d’allocation de cette ressource. Quand il n’y a plus de threads pour desservir la charge, il en créer de supplémentaire (jusqu'à une certaine limite).

Weblogic analyse les temps passés dans les threads pour décider d’en allouer d’autre. Les threads non occupés depuis un certain temps sont mis dans un état Standy et les threads qui statistiquement ont une durée d’exécution plus longue que la moyenne sont mis en état Hogging. C’est ce paramètre qui permet de nous alerter sur un début de contention.

Il suffit donc de monitorer celui-ci pour avoir une vue sur les threads de durée de vie anormalement longue (normale ou non). Il n’y a pour cette métrique aucun paramètre possible pour fixer le seuil au bout duquel on considère qu’un thread est en contention. C’est le pool qui le renseigne par rapport au temps moyen.

${instance}àRuntimeServiceMBeanàServerRuntimeàThreadPoolRuntimeMBean

Métriques

CompletedRequestCount	Nombre de requêtage réalise depuis le démarrage de l’instance (prendre la valeur d’avant pour calculer le throughtput)	141415
ExecuteThreadIdleCount	Nombre de threads inoccupé (libre)	0
ExecuteThreadTotalCount	Nombre total de threads dans le pool	15
HoggingThreadCount	Nombre de thread utilisé par des requêtes trop lente	5
MinThreadsConstraintsCompleted		14126
MinThreadsConstraintsPending		0
PendingUserRequestCount	Nombre de requête utilisateur en attente sur le pool de thread du serveur	0
QueueLength	File d’attente des requêtes en utilisateur	0
SharedCapacityForWorkManagers		65536
StandbyThreadCount	Nombre de threads plus utilisé et mise en attente (réserve pour éviter une trop grande activité de création de threads)	9
Throughput		3.5

Le nombre de actif = nombre de inoccupé + nombre de threads occupé

WORKMANAGER

Le WorkManager est un composant d’infrastructure qui prend en charge les besoins de ressource CPU pour les composants déployés sur le serveur d’applications. Il embarque une intelligence et une possibilité de paramétrage afin de gérer dynamiquement les besoins selon l’évolution de la charge. Il se place donc entre le pool de threads et la ressource desservie.

Ce composant peut nous renseigner sur les blocages de thread associé à la ressource. Il permet également d’agir sur les contentions via les mécanismes l’Overload Protections.

Le paramétrage des Stuck Thread décrit dans le chapitre suivant sur la partie log, permet de notifier le paramètre MBean StuckThreadCount sur les thread en contention spécifique sur la ressource associé. Cette métrique peut être remontée via un outil de monitoring avec possibilité de remontée d’alerte.

${instance}àRuntimeServiceMBeanàServerRuntimeà${instance}àApplicationRuntimesà${application}àWorkManagerRuntimesà${nom du workmanager}

Activité de chaque workmanager

ApplicationName	String	TestFreez
CompletedRequests	Long	0
ModuleName	String	null
PendingRequests	Integer	0
StuckThreadCount	Integer	0

Via les mécanismes d’Overload Protection, on pourra définir sur quelle condition de blocage de la ressource Threads on déclare l’instance défaillante.

Globalement via la console Weblogic.

EnvironnementàServersàConfigurationàOverload

Spécifiquement en créant un WorkManager et en ajoutant dans les descripteurs JEE cette partie.

weblogic.xml

LOG

Modifier le paramétrage Weblogic sur le StuckThreadMaxTime qui permet à Weblogic de remonter les Threads en contention via les logs Weblogic (également via les WorkManager). Il faut modifier les paramètres suivants pour changer la valeur par défaut de 10 minutes à 1 minute.

EnvironnementàServersàConfigurationàTuning

Stuck Thread Max Time : 600 à 60

Stuck Thread Timer Intervel : 60

Exemple d’un log Weblogic sur un StuckThread

####<23 juil. 2009 03 h 14 VET>

GET /TestFreez/Freez.jsp HTTP/1.1

Accept: */*

Accept-Language: fr

Accept-Encoding: gzip, deflate

User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.30; .NET CLR 3.0.04506.648)

Connection: Keep-Alive

]", which is more than the configured time (StuckThreadMaxTime) of "30" seconds. Stack trace:

Thread-79 "[STUCK] ExecuteThread: '64' for queue: 'weblogic.kernel.Default (self-tuning)'" {

java.lang.Thread.sleep(Thread.java:???)

jsp_servlet.__freez._jspService(__freez.java:61)

weblogic.servlet.jsp.JspBase.service(JspBase.java:34)