Monitoring du temps de réponse des requêtes HTTP

Salut les devs,

Aujourd’hui j’aimerais aborder un sujet qui m’a fait passer des moments difficiles (j’en suis convaincu, celà a déjà dû être le cas d’un bon nombre d’entre-vous) “le bottleneck”.  C’est un sujet très vaste, cet article se concentrera sur l’identification des requêtes HTTP entrantes qui pourraient être à l’origine de problèmes de lenteur.  Je vous mettrai aussi à disposition un petit outil que j’ai développé pouvant aider à leur identification.

Nos logiciels deviennent de plus en plus complexes, traitent un grand nombre de requêtes provenant de différentes sources, il peut s’agir d'applications front-end ou de tiers applications back-end. Pour garantir des performances optimales, il est essentiel de disposer d'un système de log capable de prendre quelques mesures clés telles que le temps de réponse, le nombre de global référence et le nombre de lignes de code exécutées pour chaque réponse HTTP.  Dans le cadre de mon travail, je suis impliqué dans le développement d’un logiciel dossier patient informatisé ainsi que sur l’analyse des incidents. La charge utilisateur provient essentiellement de requêtes HTTP (API REST ou application CSP), la nécessité de disposer de ce type de mesure lorsque des problèmes de lenteur généralisée se produisent est devenu une évidence.

Mesure du temps de réponse

L'un des éléments les plus pertinents pour évaluer les performances d'une application est le temps de réponse. Chaque requête doit être traitée dans un délai raisonnable pour offrir une expérience utilisateur satisfaisante. En enregistrant le temps de réponse pour chaque requête, un système de log permet d'identifier les performances sous-optimales. Ces informations peuvent être utilisées pour identifier les API ou pages CSP qui sont lentes afin de les optimiser et ainsi augmenter les performances globales de l'application.

Le nombre global référence

Bien que le temps de réponse soit très important, il ne faut surtout pas négliger le nombre de global référence.  L'accès disque est souvent une opération coûteuse en termes de temps d'exécution et l’efficacité du cache de IRIS peut masquer des problèmes. C’est à dire que si l’on accède à un grand nombre de global référence en cache, le temps de réponse sera excellent, mais dès que l’on accède à des données en dehors du cache, les performances chutent considérablement.  Dans un système où de nombreuses requêtes sont effectuées en parallèle, une utilisation excessive de l'accès disque peut entraîner des ralentissements importants. Un système de log qui mesure les accès global référence pour chaque requête permet de détecter les requêtes HTTP qui sollicitent excessivement les ressources.  En identifiant ces problèmes, les développeurs peuvent apporter des modifications pour minimiser les accès (ajout d’index, optimisation de requêtes SQL,...).

Nombre de lignes de code exécutées

Cette mesure permet d'identifier les requêtes qui exécutent un grand nombre de lignes de code, ce qui peut indiquer des portions du code qui nécessitent une optimisation.  Le plus souvent, le problème est le nombre de global référence, mais dans le cas ou une partie de code complexe ne serait que de la manipulation de données mémoires avec peu d’accès en base de données, cette mesure permettra de la mettre en évidence (par exemple: un problème avec des boucles). 

Détection des anomalies

Un système de log peut également être utilisé pour détecter les anomalies dans les performances des réponses aux requêtes. En enregistrant ces mesures, il est possible d'identifier les requêtes qui sortent de l'ordinaire. Par exemple, si une requête qui normalement s'exécute rapidement commence soudainement à prendre plus de temps ou à accéder de manière excessive au disque, cela peut indiquer un problème potentiel qui nécessite une attention immédiate (ex : augmentation du temps de réponse après une mise à jour applicative). La détection précoce des anomalies permet de résoudre rapidement les problèmes de performance et d'assurer une bonne expérience utilisateur.

Package web-timing-logger

Récemment, j’ai développé un petit outil pour la communauté, disponible sur open exchange, qui permet d'enregistrer toutes les requêtes HTTP entrantes. Cet outil enregistre notamment les mesures clés expliquées dans cet article. Il enregistre également quelques informations sur l’appelant qui peuvent être utiles pour le débogage : 

• Date et heure.
• Utilisateur connecté.
• Adresse IP de l’appelant.
• URL.
• Namespace d’exécution.
• Application web.
• Nom de la page (si applicable).
• URL sans les paramètres.

 

En plus de cela, il offre la possibilité d'intégrer des métriques personnalisées avec SAM (/api/monitor), ce qui peut vous permettre de les intégrer dans Prometheus et faire un dashboard avec Grafana.  On y retrouve une série de données par application web, page ou route (s’il s’agit d’application REST) agrégée par jour ainsi que par quart d’heure :

• Total hit : Nombre de requêtes reçues.
• Total timing : temps de réponse cumulé pour toutes les requêtes.
• Max timing : temps de réponse le plus lent.
• Average timing : temps de réponse moyen.

Les mêmes métriques sont également disponibles pour les global références et les lignes de code exécutées.

                                                                                                    

Exemple avec les métriques activés sur les applications web /api/monitor/ et /csp/sys/exp/:

webmeasure_average_gloref{id="/api/monitor/"} 903.5227272727272727
webmeasure_average_gloref{id="/api/monitor/metrics"} 903.5227272727272727
webmeasure_average_gloref{id="/csp/sys/exp/"} 1853.6875
webmeasure_average_gloref{id="/csp/sys/exp/%CSP.Broker.cls"} 1242.933333333333333
webmeasure_average_gloref{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_average_gloref_current_quarter{id="/api/monitor/"} 903.5227272727272727
webmeasure_average_gloref_current_quarter{id="/api/monitor/metrics"} 903.5227272727272727
webmeasure_average_gloref_current_quarter{id="/csp/sys/exp/"} 1853.6875
webmeasure_average_gloref_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 1242.933333333333333
webmeasure_average_gloref_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_average_lines{id="/api/monitor/"} 29365.5
webmeasure_average_lines{id="/api/monitor/metrics"} 29365.5
webmeasure_average_lines{id="/csp/sys/exp/"} 19415.5
webmeasure_average_lines{id="/csp/sys/exp/%CSP.Broker.cls"} 11570.73333333333333
webmeasure_average_lines{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_average_lines_current_quarter{id="/api/monitor/"} 29365.5
webmeasure_average_lines_current_quarter{id="/api/monitor/metrics"} 29365.5
webmeasure_average_lines_current_quarter{id="/csp/sys/exp/"} 19415.5
webmeasure_average_lines_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 11570.73333333333333
webmeasure_average_lines_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_average_timing_in_ms{id="/api/monitor/"} 27.27256818181818182
webmeasure_average_timing_in_ms{id="/api/monitor/metrics"} 27.27256818181818182
webmeasure_average_timing_in_ms{id="/csp/sys/exp/"} 16.6
webmeasure_average_timing_in_ms{id="/csp/sys/exp/%CSP.Broker.cls"} 9.94633333333333333
webmeasure_average_timing_in_ms{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_average_timing_in_ms_current_quarter{id="/api/monitor/"} 27.27256818181818182
webmeasure_average_timing_in_ms_current_quarter{id="/api/monitor/metrics"} 27.27256818181818182
webmeasure_average_timing_in_ms_current_quarter{id="/csp/sys/exp/"} 16.6
webmeasure_average_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 9.94633333333333333
webmeasure_average_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_max_lines{id="/api/monitor/"} 29498
webmeasure_max_lines{id="/api/monitor/metrics"} 29498
webmeasure_max_lines{id="/csp/sys/exp/"} 137087
webmeasure_max_lines{id="/csp/sys/exp/%CSP.Broker.cls"} 45208
webmeasure_max_lines{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_max_lines_current_quarter{id="/api/monitor/"} 29498
webmeasure_max_lines_current_quarter{id="/api/monitor/metrics"} 29498
webmeasure_max_lines_current_quarter{id="/csp/sys/exp/"} 137087
webmeasure_max_lines_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 45208
webmeasure_max_lines_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_max_timing{id="/api/monitor/"} 40.783
webmeasure_max_timing{id="/api/monitor/metrics"} 40.783
webmeasure_max_timing{id="/csp/sys/exp/"} 116.405
webmeasure_max_timing{id="/csp/sys/exp/%CSP.Broker.cls"} 66.458
webmeasure_max_timing{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_max_timing_current_quarter{id="/api/monitor/"} 40.783
webmeasure_max_timing_current_quarter{id="/api/monitor/metrics"} 40.783
webmeasure_max_timing_current_quarter{id="/csp/sys/exp/"} 116.405
webmeasure_max_timing_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 66.458
webmeasure_max_timing_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_total_gloref{id="/api/monitor/"} 39755
webmeasure_total_gloref{id="/api/monitor/metrics"} 39755
webmeasure_total_gloref{id="/csp/sys/exp/"} 29659
webmeasure_total_gloref{id="/csp/sys/exp/%CSP.Broker.cls"} 18644
webmeasure_total_gloref{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_total_gloref_current_quarter{id="/api/monitor/"} 39755
webmeasure_total_gloref_current_quarter{id="/api/monitor/metrics"} 39755
webmeasure_total_gloref_current_quarter{id="/csp/sys/exp/"} 29659
webmeasure_total_gloref_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 18644
webmeasure_total_gloref_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 11015
webmeasure_total_hit{id="/api/monitor/"} 44
webmeasure_total_hit{id="/api/monitor/metrics"} 44
webmeasure_total_hit{id="/csp/sys/exp/"} 16
webmeasure_total_hit{id="/csp/sys/exp/%CSP.Broker.cls"} 15
webmeasure_total_hit{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 1
webmeasure_total_hit_current_quarter{id="/api/monitor/"} 44
webmeasure_total_hit_current_quarter{id="/api/monitor/metrics"} 44
webmeasure_total_hit_current_quarter{id="/csp/sys/exp/"} 16
webmeasure_total_hit_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 15
webmeasure_total_hit_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 1
webmeasure_total_lines{id="/api/monitor/"} 1292082
webmeasure_total_lines{id="/api/monitor/metrics"} 1292082
webmeasure_total_lines{id="/csp/sys/exp/"} 310648
webmeasure_total_lines{id="/csp/sys/exp/%CSP.Broker.cls"} 173561
webmeasure_total_lines{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_total_lines_current_quarter{id="/api/monitor/"} 1292082
webmeasure_total_lines_current_quarter{id="/api/monitor/metrics"} 1292082
webmeasure_total_lines_current_quarter{id="/csp/sys/exp/"} 310648
webmeasure_total_lines_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 173561
webmeasure_total_lines_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 137087
webmeasure_total_timing_in_ms{id="/api/monitor/"} 1199.993
webmeasure_total_timing_in_ms{id="/api/monitor/metrics"} 1199.993
webmeasure_total_timing_in_ms{id="/csp/sys/exp/"} 265.6
webmeasure_total_timing_in_ms{id="/csp/sys/exp/%CSP.Broker.cls"} 149.195
webmeasure_total_timing_in_ms{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405
webmeasure_total_timing_in_ms_current_quarter{id="/api/monitor/"} 1199.993
webmeasure_total_timing_in_ms_current_quarter{id="/api/monitor/metrics"} 1199.993
webmeasure_total_timing_in_ms_current_quarter{id="/csp/sys/exp/"} 265.6
webmeasure_total_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.Broker.cls"} 149.195
webmeasure_total_timing_in_ms_current_quarter{id="/csp/sys/exp/%CSP.UI.Portal.SQL.Home.zen"} 116.405

Vous constaterez que les métriques sont très génériques, je vous encourage à développer vos métriques personnalisées nécessaires au bon monitoring de vos applications.

Installation ZPM

Si vous souhaitez effectuer une installation de test et que vous êtes utilisateur de Docker, je vous recommande de consulter cette section à titre informatif et de passer à la suivante. Le build du conteneur est automatisé pour configurer automatiquement l'environnement.

L’installation s’effectue avec ZPM, dans un terminal IRIS faites simplement : 

zpm "install web-timing-logger”

Une fois installer vous devez initialiser les paramètres, exécuter simplement :

Do ##class(dc.webtiming.Config).Initialize()

Par défaut, le log des requêtes HTTP ainsi que les métriques ne sont pas actives, voici comment les activer :

Do ##class(dc.webtiming.Config).SetLogEnabled(1)

Do ##class(dc.webtiming.Config).SetMetricsEnabled(1)

Afin que SAM (/api/monitor) puisse exposer les métriques customisées, il faut ajouter un rôle à l’application web /api/monitor, mais aussi enregistrer une classe dans SYS.Monitor.SAM.Config.  

Exécuter simplement :

Do ##class(dc.webtiming.Config).ConfigureAPIMonitor()

Si vous souhaitez utiliser cet utilitaire dans plusieurs applications web qui s’exécutent dans différents namespaces, il est absolument nécessaire de mapper le package “dc.webtiming” ainsi que les globals “dc.webtiming*” dans “%ALL”. 

Afin d’éviter de faire cette action manuellement, vous pouvez utiliser cette méthode : 

Do ##class(dc.webtiming.Config).AddToPercentAllNS()

Toutes les actions ci-dessus peuvent être réalisées en une seule ligne avec la commande :

Do ##class(dc.webtiming.Config).DefaultSetup()

Installation Docker

Le démarrage avec docker est classique,  cloner le repository et démarrer le conteneur : 

git clone https://github.com/lscalese/iris-web-timing-logger.git
docker-compose up -d

Activation sur une application web

Maintenant que nous avons configuré le système, il reste encore un détail important à régler pour pouvoir enregistrer les mesures. Pour cela, il est nécessaire de comprendre comment fonctionne le système. Pour déclencher la prise de mesure et l'enregistrement, web-timing-logger utilise les évènements "OnStartRequest" et "OnEndRequest". Ces événements sont implémentés dans la classe "dc.webtiming.CSPSessionEvents", qui est une sous-classe de "%CSP.SessionEvents". Ainsi, chaque application web doit être configurée avec la classe d'événements "dc.webtiming.CSPSessionEvents".

 

Si votre application web utilise déjà une autre classe d'événements, il n'y a aucun problème. Il suffit d'ajouter les appels suivants à cette classe :

dans la méthode OnStartRequest : 

Do ##class(dc.webtiming.Events).OnStart()

dans la méthode OnEndRequest :

Do ##class(dc.webtiming.Events).OnEnd()

This will add measurement and recording functionality to your existing event class.

Cela permettra d'ajouter les fonctionnalités de prise de mesure et d'enregistrement à votre classe d'événements existante.

Effectuez cette configuration pour toutes les applications web que vous souhaitez mesurer.

Dans le cas où vous êtes sur un système vide et que vous souhaitez seulement faire quelques tests, vous pouvez faire la configuration sur l’application /api/monitor.  L’accès aux métriques se fait par un appel HTTP, on peut donc aussi les mesurer pour générer des logs.  Il suffit ensuite d’ouvrir un navigateur et accéder plusieurs fois à la page http://localhost:49165/api/monitor/metrics (adaptez avec votre numéro de port), vous remarquerez que les métriques “webmeasure” sont alimentées et que la table “dc_webtiming_log.Request“ est remplie avec les données des requêtes HTTP:

SELECT *
FROM dc_webtiming_log.Request

Web-timing-logger facilite l'identification des points d'entrée problématiques dans les applications web, mais il ne fournit pas d'informations précises sur les parties spécifiques du code qui posent problème. Une fois que le point d'entrée est identifié, il existe un autre outil qui permet d'effectuer une analyse approfondie du code exécuté : OEX ZProfile développé par Dmitry Maslennikov. Vous trouverez également un article dédié ici.

Voilà, c’est tout pour aujourd’hui.  Il y a bien sûr d’autres choses que nous pourrions aborder sur “web-timing-logger” tel que l’ajout de mesure lorsque nous sommes en cours de développement, le nettoyage des logs ou encore les requêtes sql intéressantes.  Peut-être que j’écrirai une suite s' il y a de l’intérêt.  J’espère que l’article vous aura plu et vous donnera des idées pour le monitoring de vos applications.

A bientôt!