[spip-dev] profilage de include_spip() sur contrib

fil · Juin 22, 2008, 5:10

Je viens de tester sur spip-contrib mon proto cache de find_in_path :
il économise entre 10 et 30ms (soit environ 1ms par include_spip comme
le signalait Cédric) ; j'ai aussi profilé les include_once qui se
trouvent à l'intérieur de find_in_path() : ceux-là consomment environ
200ms (pour une page en cache).

Au total, pour servir une page en cache (environ 500ms au total), le
serveur passe autant de temps à charger et compiler des fichiers php
qu'à les exécuter.

Conclusions :
* ce cache fonctionne, mais apporte peanuts (20ms sur 500ms), tout en
introduisant potentiellement des bugs
=> je ne le commite pas dans le core
* une mise en cache de type eaccelerator, gagnerait 10 fois plus, tout
en travaillant moins
cf. http://www.spip-blog.net/Les-jantes-en-acier-chrome.html
* ça peut valoir le coup de retirer du code

-- Fil

fil · Juin 22, 2008, 5:39

Pour tester, les fichiers sont là :
http://zone.spip.org/trac/spip-zone/changeset/21072

Activer le profilage avec ?cfind=0
Activer le cache+profilage avec ?cfind=1

-- Fil

cerdic · Juin 22, 2008, 9:41

Oui, le profileur Zend est instructif en cela qu'il distingue le "temps propre" passé dans une fonction (qui ne concerne que le code de la fonction) du temps total (qui inclue les appels à des sous fonctions, ou les inclusion).
Cela permet bien de
- compter les occurrences d'appel
- voir les gains potentiels en essayant d'optimiser telle ou telle partie du code.

Sur find_in_path, tu avais mis un moment une mini optimisation consistant à lire tout le repertoire à la premiere demande le concernant. Il semble que cela ait disparu, mais je n'avais pas fait de comparaison avec/sans

Cédric

RealET · Juin 23, 2008, 3:52

* Fil tapuscrivait, le 22/06/2008 19:10:

Je viens de tester sur spip-contrib mon proto cache de find_in_path :
il économise entre 10 et 30ms (soit environ 1ms par include_spip comme
le signalait Cédric) ; j'ai aussi profilé les include_once qui se
trouvent à l'intérieur de find_in_path() : ceux-là consomment environ
200ms (pour une page en cache).

Au total, pour servir une page en cache (environ 500ms au total), le
serveur passe autant de temps à charger et compiler des fichiers php
qu'à les exécuter.

Les tests chez moi (en utilisant Connexion · GitLab) avec pleins de plugins activés (Composed-By: SPIP 1.9.3 dev @ www.spip.net + accesrestreint(0.2), admin_lang(0.1), barretypoenrichie(2.5.0),boutonstexte(0.3.0),cfg(1.7.5),clevermail(1.0.4), couteau_suisse(1.7.18.03),crayons(1.0),typoenluminee(2.1.1),fonctions_images(0.4), forms(0.304),notation(0.4),sedna(1.0),sitemap(0.1),wcalendar(0.11), woopra(0.1),acronymes(0.11),agenda(0.17),autorite(0.9.2), barre_typo_generalisee(1.5),soyezcreateurs(1.9.3.0))
donnent :
?cfind=0 : find_in_path=1.235759 - include=-0.700337 - total= 0.53863
?cfind=1 : find_in_path=0.054921 - include=0.022841 - total= 0.333782

Pour comparer, SPIP contrib n'a que peu de plugins :
Composed-By: SPIP 1.9.3 dev @ www.spip.net + boutonstexte(0.3.0),cfg(1.7.5),crayons(1.0),gazette(1),notifications(0.3),
nuage(1.4),coloration_code(0.2),autorite(0.9.2)

Donc, je dirais que find_in_path semble bien optimisé pour peu de plugins, mais que pour beaucoup, un cache sur find_in_path améliore bien le score.

RealET · Juin 23, 2008, 3:56

* RealET tapuscrivait, le 23/06/2008 17:52:

?cfind=0 : find_in_path=1.235759 - include=-0.700337 - total= 0.53863
?cfind=1 : find_in_path=0.054921 - include=0.022841 - total= 0.333782

Et avec &var_mode=recalcul :
?cfind=0&var_mode=recalcul : find_in_path=1.366509 - include=0.373571 - total= 5.237358
?cfind=1&var_mode=recalcul : find_in_path=0.394007 - include=0.405763 - total= 5.078526

fil · Juin 23, 2008, 3:57

?cfind=0 : find_in_path=1.235759 - include=-0.700337 - total= 0.53863

hum, ce test a l'air abîmé : include ne peut pas être négatif

par ailleurs il faut se méfier des fausses impressions, et relancer au
mons 10 fois chaque hit, pour bien valider les chiffres.

Mais s'ils sont au final aussi bons que ce que tu dis, ça vaudra
peut-être le coup quand même. Là où je suis déçu c'est que j'espérais
améliorer spip-contrib.

-- Fil

RealET · Juin 23, 2008, 4:17

* RealET tapuscrivait, le 23/06/2008 17:52:

À la demande de Fil, le test 10 fois de suite, et sans valeurs négatives

?cfind=0

find_in_path=0.394007 - include=0.405763 - total= 5.078526
find_in_path=0.2316 - include=0.296064 - total= 0.540059
find_in_path=0.220221 - include=0.284751 - total= 0.521885
find_in_path=0.237216 - include=0.290586 - total= 0.54149
find_in_path=0.229711 - include=0.29954 - total= 0.529375
find_in_path=1.229278 - include=0.293039 - total= 0.517658
find_in_path=0.232822 - include=0.281615 - total= 0.510821
find_in_path=0.217862 - include=0.286576 - total= 0.513528
find_in_path=0.225355 - include=0.309862 - total= 0.544098
find_in_path=0.23963 - include=0.288295 - total= 0.52434

?cfind=1

find_in_path=0.061216 - include=0.023464 - total= 0.369005
find_in_path=0.063202 - include=0.023312 - total= 0.333983
find_in_path=0.058469 - include=0.024142 - total= 0.349882
find_in_path=0.068107 - include=0.024986 - total= 0.334368
find_in_path=0.063362 - include=0.025453 - total= 0.338151
find_in_path=0.057007 - include=0.023609 - total= 0.357054
find_in_path=0.061808 - include=0.023161 - total= 0.343874
find_in_path=0.058841 - include=0.022863 - total= 0.32953
find_in_path=0.057682 - include=0.022859 - total= 0.336812
find_in_path=0.057745 - include=0.023041 - total= 0.357163

En gros, ça fait un temps de find_in_path 4 x moindre avec le cache (et beaucoup de plugins activés).

fil · Juin 23, 2008, 5:38

?cfind=0

find_in_path=0.394007 - include=0.405763 - total= 5.078526

find_in_path=0.061216 - include=0.023464 - total= 0.369005

Il y a forcément un bug dans le test : le cache de recherche de
fichier ne devrai pas diviser par 20 le temps mis à les inclure !

-- Fil

cerdic · Juin 24, 2008, 8:29

les inclusions doivent consommer un temps fixe, effectivement.
Tout ca ne veut donc pas dire grand chose !...
Cédric

RealET · Juin 24, 2008, 4:31

* cedric.morin@yterium.com tapuscrivait, le 24/06/2008 10:29:

?cfind=0

find_in_path=0.394007 - include=0.405763 - total= 5.078526

find_in_path=0.061216 - include=0.023464 - total= 0.369005

Il y a forcément un bug dans le test : le cache de recherche de
fichier ne devrai pas diviser par 20 le temps mis à les inclure !

les inclusions doivent consommer un temps fixe, effectivement.
Tout ca ne veut donc pas dire grand chose !...

Bon, si tu m'indique comment tester d'une manière qui te dira quelque chose, je le ferais volontiers.

cerdic · Juin 24, 2008, 6:12

Non mais moi j'ai deja profilé avec le zend depuis longtemps (et si tu veux savoir je le fais régulièrement, et avant toute sortie de version stable, pour vérifier qu'il n'y a pas de gros loup quelque part).
Le résultat intéressant c'est qu'on obtient un coût moyen propre de find_in_path de 1ms (donc hors temps passé dans les inclusions).
Sur mes sites j'ai régulièrement près d'une centaine d'appel à la fonction, sur un hit en cache, et donc un coût total potentiellement optimisable de l'ordre de 100ms.
Mais
- l'optimisation par un cache a un cout en terme de bug qui n'est pas nul
- le gain espéré est réduit à peu de choses si l'on utilise un cache opcode tel que eaccelerator ou Xcache

Donc le jeu n'en vaut pas la chandelle pour le core a tout le moins.
Toutefois, j'ai testé la réimplémentation de la fonction memoriser_repertoire() chargée de parcourir d'un coup tout un sous repertoire et mettre en mémoire son contenu que fil avait implémenté un moment et qui a été supprimée lors de la refonde de find_in_path.
Le gain total est nul, mais en rendant cette fonction surchargeable cela permettra aux acharnés de se faire un plugin et de d'avoir l'esprit en paix.
Je pense donc retenir cela.

Cédric