Pour les gens pressés : allez directement à la conclusion.

Introduction

Pour un client, récemment j’ai été amené à importer une quinzaine de millier de produits.

Très vite, des problèmes de perfs apparaissent sur le serveur de prod : c’est lent et beaucoup trop long.

Chez de nombreux hébergeurs, des erreurs vont apparaître car le script (AdminImportController.php) n’aura pas fini dans le délai défini par la directive de php max_execution_time. Provoquant des erreurs HTTP 500. Ou alors ce sera le serveur web (Apache, Nginx) qui va se lasser de ne pas avoir de réponse et nous renvoyer une erreur HTTP 504 Gateway Timeout.

Changer cette directive et les paramètres du serveur web peuvent, dans certains cas (des serveurs rapides et petits lots d’importation) rendre le traitement possible, mais c’est de la bidouille.

On va donc sortir les outils de mesure — profiling — et essayer de trouver les goulots d’étranglements et voir si on peut améliorer tout ça.

Profilage

On lance xhprof et xhgui pour voir ce qui se passe réellement dans le code.

Conditions de test:

Import de 449 produits en CSV. À chaque importation, on efface les produits déjà présent en base. Chaque produit est associé à une image, mais ces images sont introuvables.

Premier lancement, ça met des plombes, mais les objets associés sont crées, c’est l’initialisation.

Deuxième lancement, on a des données interéssantes : 156 secondes (2min36) de traitement. Prestashop Xhprof

On peut lire que la très grande majorité du temps à été passé à faire des appels à la base de données.

Regardons dans le détail:

Prestashop Xhprof liste

C’est classé par temps de traitement dans chaque fonction elle-même (sans le temps passé dans chacun de ses descendants).

On retrouve bien sûr les fonctions liés à la BDD DbPDOCore en bonne position. L’information supplémentaire interessante est le “Call count”, c’est-à-dire le nombre de fois où chaque fonction à été appelée.

Appels  Fonction Appels / Produit
49 000 DbPDOCore::_query ~100
160 000 DBCore::escape ~320
100 000 ToolsCore::strtolower ~200

Ça fait vraiment beaucoup de requêtes par produit.

On va partir de la fonction qui nous intéresse : l’import de produit, pour avoir une vision plus précise et descendre dans l’arbre des appels.

AdminImportControllerCore::productImport

Regardons d’abord le nombre d’appels.

Prestashop Xhprof childs count

On remarque :

Tools::getValue à été invoquée 8 fois par produit ShopCore::isFeatureActive, 3 fois par produit.

Tools::getValue récupère une valeur dans _GET ou _POST. Lorsqu’on regarde le code, aucun appel n’est fonction du produit, le résultat ne change pas entre chaque appel. On pourrait donc sortir ces 8 appels de la boucle et les executer qu’une fois pour toute. Mais la colonne WallTime nous apprends qu’on ne gagnerait que quelques miettes.

IsFeatureActive est dans le même cas, d’une ligne à l’autre, son résultat ne va pas changer. On pourrait lui aussi le sortir de la boucle.

Regardons maintenant les fonctions qui consomment du temps :

Prestashop Xhprof childs

On remarque ces fonctions sont toutes appelées 449 fois, nous importons 449 produits. C’est donc normal.

Les deux fonctions les plus pénalisantes sont : ProductCore::Add et ImageCore::add (elles accaparent à elles seules 40% du temps de traitement de ProductImport)

ProductCore::setAdvancedStockManagement est également étrange, car je n’utilise pas le AdvancedStockManagement dans mon jeu de données et la gestion des stocks avancées n’est pas activé dans la boutique :

Prestashop Gestion des stocks

Plongeons dans ProductCore::Add

ProductCore::Add

Prestashop productCoreAdd

Si on trie par temps d’execution, on trouve dans le top ObjectModelCore::Add (insertion en BD du produit) et HookCore::Exec (execution des hooks).

Continuons la descente. Qu’est ce qui se passe dans ObjectModelCore::Add… ?

ObjectModelCore::Add

Prestashop ObjectModelCoreAdd_child

Surprise ! On retrouve HookCore::Exec et il prends même plus de temps que DbCore::insert!

Il est peu probable qu’on en trouve plus en continuant la piste de DBCore::insert. Regardons HookCore::Exec.

HookCore::Exec

Dans Prestashop, les hooks (ou crochets) permettent aux modules d’exécuter des actions à des moments bien précis. C’est une implémentation du patron de conception Observateur.

Chaque module va donc “s’abonner” à des actions via ce système de “hooks”.

Dans notre cas, pour chaque produit crée, un certain nombres d’actions vont être effectuées par les modules.

Retournons à xhprof :

Prestashop hookCore::exec

Dans Inclusive Wall Time on a le temps total passé dans HookCore::Exec.

On a vu que cette fonction est appelée pour chaque appel de ProductCore::Add et pour chaque appel de ObjectModelCore::Add. Regardons le code ProductCore::Add

//...
class ProductCore extends ObjectModel
{
    //...
    public function add($autodate = true, $null_values = false)
    {
        if (!parent::add($autodate, $null_values))
            return false;
        //...
        Hook::exec('actionProductSave', array('id_product' => (int)$this->id, 'product' => $this));
        return true;
    }
    //...
}

ProductCore::Add invoque Hook::exec(‘actionProductSave’) ET ObjectModel::Add (qui lui même invoque Hook::exec())

//...
abstract class ObjectModelCore 
{

    public function add($autodate = true, $null_values = false)
    {
        //...

        // @hook actionObject*AddBefore
        Hook::exec('actionObjectAddBefore', array('object' => $this));
        Hook::exec('actionObject'.get_class($this).'AddBefore', array('object' => $this));

        //...

        // @hook actionObject*AddAfter
        Hook::exec('actionObjectAddAfter', array('object' => $this));
        Hook::exec('actionObject'.get_class($this).'AddAfter', array('object' => $this));

        return $result;
    }
//.../

Chaque appel de ObjectModel::Add va donc invoquer 4 hooks. On remarque que les paramètres ne sont pas les mêmes, malheureusement xhprof ne nous permettra pas de faire la distinctions entre eux.

On sait donc maintenant pourquoi le compteur d’appel de HookCore::exec est si important (22 par produits), reste à savoir pourquoi c’est si long.

La colonne InclusiveWallTime nous informe qu’une minute complète (sur les 2min30 du total) à été passé à exécuter ces actions de modules.

C’est énorme ! On tient un suspect !

Regardons les fonctions enfants:

Prestashop hookCore::exec childs

Dans le top, on a Gamification::__call , BlockLayered::hookAfterSaveProduct , et dans une bien moindre mesure HookCore::getHookModuleExecList.

Le plus gros consommateur de temps (et de mémoire), c’est Gamification. Un module activé par défaut avec les versions récentes de Prestashop et qui pour l’importation ne sert à rien !

Deuxième coupable: BlockLayered.

Un module qui permet de faire de la recherche de produit par facette.

Il a donc besoin d’indexer les produits. Au lieu de reconstruire son indexe à chaque insertion de produit, il peut le faire qu’une seule fois pour toute, à la fin.

On va les désactiver tous les deux.

Prestashop BlockLayered Gamification Modules

Et c’est parti pour un troisième tour !

Modules désactivés

Prestashop BlockLayered Gamification Modules

Boom !!! 40% plus rapide et presque moitié moins de mémoire utilisée, juste en désactivant deux modules.

Function Call Count Self Wall Time Self CPU Inclusive Wall Time Inclusive CPU Inclusive Memory Usage
HookCore::exec 10338 987,550 µs 739,406 µs 62,357,007 µs 23,211,780 µs 18,617,208 bytes
HookCore::exec 10338 619,802 µs 481,420 µs 5,224,022 µs 4,631,482 µs 3,235,904 bytes

Comparons les graphes :

Prestashop xhprof graph 1 Prestashop xhprof graph 2

On a bien réduit le temps de traitement et accessoirement la mémoire utilisée.

Easy win !

Je ne l’ai pas explicité mais Gamification fait de nombreuses requêtes (dans mon cas 6 par produits) d’INSERT qui sont très consommatrices de resources.

En désactivant deux modules, on a pu réduire le nombre de requêtes et donc améliorer la performance. Mais ces requêtes restent un goulot d’étranglement et les perfs ne sont toujours pas très satisfaisantes.

Transactions

Une astuce trouvée sur programmation-web.net est interessante : les transactions.

Par défaut, MySQL va écrire chaque enregistrement immédiatement sur le disque dur. En utilisant les transactions, ces enregistrements seront gardés en mémoire et écrits qu’une seule fois.

La doc de MySQL sur les Transactions est une lecture interessante.

$db = Db::getInstance();
$db->query("START TRANSACTION");
//ici l'importation
$db->query("COMMIT");

Prestashop xhprof graph 3

Une tuerie !

On a encore bien réduit le temps de traitement.

Pour 31070 appels à DbPDOCore::_query, on passe de 67 secondes à 7 !

Images

Pas abordé dans cet article, mais lorsqu’on importe des images, il vaut mieux les avoir en local pour les transformer que d’avoir à les télécharger une par une.

En conclusion

Pour avoir une importation csv plus rapide, il faut :

  • la désactivation de modules (gamification et blocklayered)
  • le passage aux transactions
  • les images en local
  • l’amélioration du code de Prestashop