[spip-dev] debug++

Dev
1

Bonjour,

Dans la V209 le var_mode=debug permet de finement
connaitre les temps de calculs des boucles
et inclusions spip, lors du calcul d'un squelette.
C'est fort utile... mais devant la profusion d'information
se pose la question "à quoi je m'attaque pour commencer ?",
car d'une part il y a moultes données dans un fichier squelette
d'autre part il y a moultes fichier squelette...

Et surtout, si une inclusion est pénible et lourde,
mais qu'avec un bon cache le calcul n'est fait que très rarement,
il y aura probablement mieux à faire que de passer du temps dessus...

Or, avec les jeux d'inclusions il est difficile de calculer à coup sur
les temps globalisés d'exécution d'un morceau de code...
ou en tout cas, il serait appréciable de pouvoir vérifier !

A ma connaissance, il n'y a pas d'outil pour connaître
les temps de calculs réels et globalisés dans le temps
des différents éléments du squelette.
C'est à dire en tenant compte des caches des différentes noisettes,
des mode d'#inclusions ou d'<inclusions> etc
c'est à dire en fait le réel comptabilisé sur l'ensemble du site
et sur une durée donnée
(top initialisation, top relevé des compteurs un jour ou une semaine après).

Une telle connaissance permettrait clairement de savoir
à quoi s'attaquer prioritairement dans l'optimisation d'un site...

JLuc

2

Salut,

?var_profile=1 peut être ?

3

bruno bergot a écrit :

Salut,

?var_profile=1 peut être ?

En faisant ?var_mode=calcul&var_profile=1
on a vraiment un max d'info pointues pour optimiser tout azimut,
mais c'est toujours un instantanné correspondant à la page appelée.

Pour accéder à des valeurs réelles globales au site,
il faudrait un mode debug_permanent - le temps du test start stop-
et probablement une table supplémentaire
pour y additionner les temps de calcul par élément spip.

JL

4

Même au niveau de PHP, les profileurs que je connais (Zend, Xdebug) sont toujours des profileurs sur un hit.
Faire du profilage en conditions reelles supposerait donc de loger tous les calculs de squelette (nom du squelette calculé, page appelante, et temps de calcul) dans un format à définir pour pouvoir les exploiter ensuite par un outil de dépouillement.

Le plus gros travail consiste à mon avis à faire une étude des formats standardisés ou non pour ce type de profilage, et des outils de dépouillements existants (SPIP n'ayant pas vocation à réinventer la roue).
Produire les log dans le bon format est assez trivial, il me semble.

Une fois cette information disponible off line, il est assez facile de faire ressortir les squelettes les plus calculés, puis de les optimiser à la main avec le var_profile=1 notamment.

Cela dit, et sans vouloir réduire l'intérêt d'un tel outil, il me semble que 80% du résultat est atteignable en regardant les urls les plus demandées dans tout bon outil de statistiques du site, et d'optimiser le calcul de ces pages avec var_profile=1.

Il y a certes des centaines de requêtes à chaque page, mais celles qui sont vraiment lourdes se comptent en général sur les doigts des mains, et se concentrer sur l'optimisation de ces requêtes suffit en général à transformer un site escargot en site rapide ...

Dans les divers cas où j'ai eu a opitmiser des sites lents, c'est la démarche que j'ai appliquée et qui a été largement satisfaisante, au point que je n'ai jamais ressenti le besoin d'un outil comme tu le décris.

Mais n'hésite pas à faire le bench des formats et outils et poser à la spec, le reste ira vite je pense.

Cédric

5

cedric.morin@yterium.com a répondu.

Je ne connais pas les profileurs dont tu parles,
mais je comprend ta réponse.

Le plus gros travail consiste à mon avis à faire une étude des formats standardisés ou non pour ce type de profilage,

Il me semble qu'une liste de paires
  (référence de l'élément spip, durée cumulée des appels)
suffirait pour répondre au besoin.
(pas besoin de logs détaillés avec heure d'exec,...)

Une fois cette information disponible off line, il est assez facile de faire ressortir les squelettes les plus calculés, puis de les optimiser à la main avec le var_profile=1 notamment.

Pour être sur : l'intéressant est de faire ressortir les squelettes
dont le calcul sur une durée (compil n fois + exécution xxx fois en une journée)
est le plus long.

Cela dit, et sans vouloir réduire l'intérêt d'un tel outil, il me semble que 80% du résultat est atteignable en regardant les urls les plus demandées dans tout bon outil de statistiques du site, et d'optimiser le calcul de ces pages avec var_profile=1.
Il y a certes des centaines de requêtes à chaque page, mais celles qui sont vraiment lourdes se comptent en général sur les doigts des mains, et se concentrer sur l'optimisation de ces requêtes suffit en général à transformer un site escargot en site rapide ...

C'est vrai, et cela peut suffire car il y a souvent des rapports 10 ou plus
entre les quelques plus lourdes et les suivantes.

Cependant, en ce qui me concerne, il sais très bien multiplier par 10
la durée d'un cache, mais je ne sais que très embryonnairement
analyser le comportement de SQL sur une boucle pour l'optimiser,
même en disposant de toutes les infos techniques pour le faire !!!-

Il me reste donc actuellement une incertitude avec les caches,
les caches emboités et les inclusions dynamiques ou statiques,
dont il est difficile de vérifier qu'ils sont bien appliqués
comme on le croit, comme on le veut, comme on pense le demander.

Les caches élémentaires peuvent donc être, en alternative,
une source d'information utile pour l'optimisation d'un site :
indiquer leur fréquence d'invalidation,
ou le nombre de fois qu'ils le sont dans la durée de test.
Cette information, combinée avec celles déjà fournies assurerait
la convoitée vision globale du réel,
mais son calcul supposerait aussi des logs sur une durée

JLuc

6

Des kilomètres de log ne donneront jamais aucun résultat tangible si on a pas un outil qui permette une exploitation statistique derrière, comme pour les visites d’un site.
Lis-tu couramment les logs apache ou utilise-tu un outil qui les dépouille et les présente sous une forme humainement lisible ?

D’ou ma réponse :
il faut commencer par trouver des outils d’analyse de logs de profilage qui reposent sur des formats standardisés ou ouverts, et retenir le format de log qui nous parait le plus adapté pour notre usage.
Ce en quoi tu peux certainement contribuer.

Cédric

7

cedric.morin@yterium.com a écrit :

Cette information, combinée avec celles déjà fournies assurerait
la convoitée vision globale du réel,
mais son calcul supposerait aussi des logs sur une durée

Des kilomètres de log ne donneront jamais aucun résultat tangible si on a pas un outil qui permette une exploitation statistique derrière, comme pour les visites d'un site. Lis-tu couramment les logs apache ou utilise-tu un outil qui les dépouille et les présente sous une forme humainement lisible ?

Je parlais de log sans nécessairement penser "fichier de log".
J'envisageais spontanément à une solution "base de donnée"
comme il est fait pour les stats de visite :
un UPDATE ou INSERT à chaque hit je crois.

D'ou ma réponse : il faut commencer par trouver des outils d'analyse de logs de profilage qui reposent sur des formats standardisés ou ouverts, et retenir le format de log qui nous parait le plus adapté pour notre usage.
Ce en quoi tu peux certainement contribuer.

J'ai du mal à penser qu'on gagnera à se servir
d'un "format standard de profilage"
pour un format de donnée aussi élémentaire.

Car si c'est un fichier de logs temporels, une liste de paires suffit :
...(référence_interne_de_lelement_spip, durée_d_exec)...
pour maintenir les temps de calculs cumulés par noisette.

Et dans la solution où on vise à publier le nombre réel
de recalcul de chaque cache, il suffit d'une liste plate de singletons :
(référence_interne_de_lelement_spip_caché)
c'est à dire une liste d'entiers les uns à la suite des autres.

JLuc

8

cedric.morin@yterium.com a écrit :

Des kilomètres de log ne donneront jamais aucun résultat tangible si on a pas un outil qui permette une exploitation statistique derrière, comme pour les visites d'un site.

Les informations calculées pourraient être visualisées
- du moins lorsqu'elles existeraient, c'est à dire celles du dernier test pendant 1h/1jour) -
en infos complémentaires dans les encarts du var_mode debug et du var_profile=1
en regard de chaque noisette ou élément de code concerné.

J'arrête là je pense avoir exprimé la vue.
JLuc

9

Le but c'est de ne pas réinventer la roue. Pour profiler réellement un site, il faut un vrai outil analysant automatiquement les statistiques enregistrées, et présentant un rapport ayant du sens.

Coder tout ce travail doit *prendre du temps*, alors qu'il existe peut-être déjà des outils de profilage libres, et utilisant un format de donnée ouvert (c'est-à-dire clairement défini et utilisable par tous).

Ce que veut dire Cédric, c'est qu'il est donc plus intéressant de chercher si ce genre de format exsite, puis d'en choisir un bien. Il n'y aura alors plus qu'à utiliser un outil existant, donc *rien à coder* mis à part la génération des enregistrements de stats !

Demander à ce que des choses soient codées en plus dans SPIP, fait que tu ne peux pas aider.
En revanche, la solution de Cédric d'utiliser un format standard, fait que *TU* peux contribuer puisqu'il s'agit de faire des recherches sur Internet.

Merci d'avance pour ta contribution, donc.

10

oui, donc tu proposes que l'on re-développe une interface de visualisation et depouillement de toutes ces statistiques.
très peu pour moi, dans ce cas.

Si ça intéresse quelqu'un de réinventer la roue, qu'il ne se prive pas.
Cédric

11

On se calme, JLuc exprimait au départ le fait avéré que les temps de calcul affichés par le débusqueur ne sont pas d'une grande utilité car n'incluant pas le gain fourni par le cache. Que ses propositions techniques ne soient pas nécessairement les meilleures ne disqualifie pas sa remarque initiale.

Je ne sais plus qui avait signalé que l'interpolation PHP dans un squelette due à une balise dynamique (le formulaire de recherche il me semble) aggravait lourdement le temps de réponse. Il faudrait savoir si cette aggravation se constate pour toutes les interpolations (notamment le <INCLURE..>), et ça ce n'est pas une simple analyse des URL les plus vues, ni même des squelettes les plus demandés qui peut permettre de le déterminer.

On retombe sur le même constat: le langage de squelettes est devenu un langage de programmation à part entière, et du coup nécessite les outils dédiés qu'on trouve ailleurs: débusqueur, profileur, éditeur dirigé par la syntaxe etc. Que ceci doit se faire avec un minimum de développement, pour ma part j'en suis convaincu, mais la discussion sur la réforme de la syntaxe pour profiter des outils existants montre que cette recommandation se heurte parfois à d'autres impératifs. Le débat n'est donc pas si simple.

Committo,Ergo:Sum

12

* Committo,Ergo:sum tapuscrivait, le 17/09/2009 17:06:

Je ne sais plus qui avait signalé que l'interpolation PHP dans un squelette due à une balise dynamique (le formulaire de recherche il me semble) aggravait lourdement le temps de réponse.

http://monsitespip.com/spip.php?article29

13

JLuc a écrit :

Dans la V209 le var_mode=debug permet de finement
connaitre les temps de calculs des boucles
et inclusions spip, lors du calcul d'un squelette.

J'ai besoin d'une petite précision sur l'interprétation de la durée renvoyée par var_mode=debug pour un squelette donné

Il s'agit bien du temps de compilation du squelette en question seul ? Pas de tout l'arbre d'inclusion ?

Parce que j'ai des chiffres étranges, oscillant entre 1s et 17s suivant les appels à contexte constant, et mon squelette sommaire.html fait juste ça :

#CACHE{12*3600}

[(#ENV{ville} |!={''} |?{ [(#SET{mavar,[(#EVAL{setcookie('ville_preferee', '[(#ENV{ville})]', (time() + 3600*24*365));})] })] })]

#SET{ville,#ENV{ville} |sinon{#EVAL{$_COOKIE["ville_preferee"]}}}

[(#INCLURE{fond=inclus/inc_sommaire}{lang}{ville=#GET{ville}})]

Si la durée indique le temps de compilation / calcul de la totalité de l'arbre d'inclusion, je comprends ces chiffres, ça peut venir d'une charge sur le serveur ou d'une mauvaise optimisation de certaines de mes requêtes.
Si par contre ça ne prend en compte que ce squelette, il va falloir que je me penche dans la config de mon serveur...

(Je précise : je parle de cet exemple parce qu'il est flagrant, mais j'ai les mêmes chiffres aberrants et aléatoires sur presque toutes les pages)

A bientôt
    Simon

14

Le vocabulaire standard considère que "le temps de compilation" est le temps que met le compilateur à traduire le langage-source (ici le langage des squelettes) dans le langage-cible (ici PHP) et il est de peu d'intérêt ici puisque la compilation intervient rarement en production: une fois compilé, c'est le code PHP qui est exécuté. Le temps intéresant à afficher est le temps d'exécution du code PHP compilé, et c'est ce que veut faire SPIP en mesurant le temps au niveau de la fonction inc_parametrer et non ailleurs.

Malheureusement, le temps qu'il affiche est biaisé de plusieurs manières:

1. par définition, le mode debug recompile tous les squelettes pour être certain d'avoir la dernière version; résultat: le temps d'exécution d'un squelette incluant va être plombé par le temps de compilation des squelettes inclus, bien qu'il ne compte pas son propre temps de compilation.

2. on se sert de la fonction time(), qui donne seulement l'heure qu'il est, autrement dit on mesure la charge globale du serveur, pas le temps CPU spécifique au code PHP exécuté.

3. si un squelette est inclus dans une boucle, le temps affiché par le débusqueur est celui du dernier passage dans la boucle,
non pas le temps cumulé de tous les passages (ça c'est un choix arbitraire qui pourrait être différent, mais il faut en être conscient).

JLuc a donc raison quand il dit qu'il manque un outil précis de mesure des performances spécifique à SPIP. Ca fait partie des améliorations encore à apporter au débusqueur. Je rappelle que inc_parametrer est une fonction surchargeable, les améliorations sont donc relativement faciles à expérimenter.

Committo,Ergo:Sum