Problème de performances pour récupérer le nombre de commentaires d'un thread #63

Récupérer le nombre de commentaires d'un thread (thread.comments.count()) est très lent.

Sur certaines pages, on peut arriver à des temps de chargement dépassant la seconde, quand bien même on a pas tant de topics que ça… Exemple : https://v5.planet-casio.com/forum/discussion/ (~1,5 s de temps de génération)

Il faut trouver un moyen de corriger le problème, parce que c'est un sacré bottleneck. On peut éventuellement stocker le nombre de commentaires en tant qu'attribut du Thread, mais je trouve ça bof.

J'en profite pour partager la doc sur le profilage dans SQLAlchemy, qui pourra être utile à l'occasion.

Bon, après une fois que la pagination (#64) sera mis en place, le problème sera peut-être moins critique. J'espère la complexité par Thread est en O(1), ça serait pas mal. Normalement oui puisque SQLAlchemy doit convertir le .count() en count(*) FROM table WHERE …

Ça peut aussi venir d'un index manquant dans la BDD. On n'explicite pas l'index des commentaires par thread, donc si SQLAlchemy ne le fait pas il est possible que ça vienne de là.

Actuellement la page est générée en 0.37742s .
Ça reste beaucoup mais c'est bien plus acceptable que les 1.5s d'origine.
Quels sont les modifications apportés autres que la pagination ?

Pour rappel, thread.comments.count() fait référence à une relation définie par une clé étrangère dans Comment :

class Comment:
    # (...)
    
    # Parent thread
    thread_id = db.Column(db.Integer, db.ForeignKey('thread.id'),
                          nullable=False)
    thread = db.relationship('Thread',
        backref=backref('comments', lazy='dynamic'),
        foreign_keys=thread_id)

Et si on regarde les index sur la table comment (commande ici) :

       table_name        |                  index_name                   |   column_name
-------------------------+-----------------------------------------------+-----------------
(...)
 comment                 | comment_pkey                                  | id

Clairement donc il n'y a aucun index qui permette de trouver les commentaires par Thread, ce qui est absurde. La documentation de SQLAlchemy montre comment régler ce problème.

class Comment:
   # (...)
   thread_id = db.Column(db.Integer, db.ForeignKey('thread.id'),
                         nullable=False, index=True)

Notez que pour la version plus élaborée on peut spécifier un Index directement dans la table :

class Comment:
   # (...)
   thread_id = db.Column(db.Integer, db.ForeignKey('thread.id'),
                         nullable=False)
   db.Index(...)

Je pousse en preprod pour valider les perfs et puis je reviens. Actuellement https://v5.planet-casio.com/forum/discussion/ prend 0.25~0.40 seconde à générer, avec des pics occasionels à 1s environ (je soupçonne un peu de cache).

(Il y a aussi des clés étrangères cycliques entre Thread et Comment, je verrai ça après.)

Ça a pas changé grand-chose (mais c'était important de le faire quand même). Quand on y regarde de plus près je pense que le problème c'est surtout de faire des requêtes séparément. On peut le voir en direct dans le shell :

% flask shell
>>> import timeit
>>> from app.models.topic import Topic
>>> from app.models.comment import Comment

Lister tous les messages du topic à 5004 commentaires prend dans les 6.4 ms :

>>> ta199 = Topic.query.get(764)
>>> ta199.title, ta199.thread.comments.count()
('Topic auto 199', 5004)
>>> timeit.timeit(lambda: ta199.thread.comments.count(), number=100)
0.6441334136761725

Et le faire pour un autre topic aléatoire ayant 5 commentaires prend dans les 4.2 ms :

>>> ta199 = Topic.query.get(762)
>>> ta198.title, ta198.thread.comments.count()
('Topic auto 198', 5)
>>> timeit.timeit(lambda: ta198.thread.comments.count(), number=100)
0.4208924351260066

Par contre, dès qu'on comment à faire plein de requêtes à la suite, ça marche moins bien ; si je demande tous les topics individuellement (8 pages), ça prend 1.8 seconde :

>>> def count_all():
...   total = 0
...   for t in Topic.query.all():
...     total += t.thread.comments.count()
...   print(total)
...
>>> timeit.timeit(count_all, number=1)
5765
1.801109447143972

Par comparaison, sortir tous les commentaires prend 108 ms (oui c'est plus facile parce qu'on ne regarde pas les numéros de topics).

>>> timeit.timeit(lambda: print(len(Comment.query.all())), number=1)
5770
0.10828896099701524

Quelque chose me dit que le problème donc c'est pas le fait d'avoir des gros topics mais le fait de faire une requête par topic sur la page. Ce qui est corroboré par les chiffres, puisque charger la page 2 du forum de discussion, qui n'a qu'un commentaire par topic, prend autant de temps.

Ça montre aussi que l'ORM est tout aussi chiant à utiliser correctement que le SQL original, ce qui est assez frustrant vu la grosse courbe d'apprentissage.

Je vais voir si je peux trouver une solution pour améliorer les perfs de ce cas-là, histoire d'avoir un peu plus d'expérience pour identifier/résoudre les cas similaires dans le futur.

Ça a pas changé grand-chose (mais c'était important de le faire quand même). Quand on y regarde de plus près je pense que le problème c'est surtout de faire des requêtes séparément. On peut le voir en direct dans le shell : ``` % flask shell >>> import timeit >>> from app.models.topic import Topic >>> from app.models.comment import Comment ``` Lister tous les messages du topic à 5004 commentaires prend dans les 6.4 ms : ``` >>> ta199 = Topic.query.get(764) >>> ta199.title, ta199.thread.comments.count() ('Topic auto 199', 5004) >>> timeit.timeit(lambda: ta199.thread.comments.count(), number=100) 0.6441334136761725 ``` Et le faire pour un autre topic aléatoire ayant 5 commentaires prend dans les 4.2 ms : ``` >>> ta199 = Topic.query.get(762) >>> ta198.title, ta198.thread.comments.count() ('Topic auto 198', 5) >>> timeit.timeit(lambda: ta198.thread.comments.count(), number=100) 0.4208924351260066 ``` Par contre, dès qu'on comment à faire plein de requêtes à la suite, ça marche moins bien ; si je demande tous les topics individuellement (8 pages), ça prend 1.8 seconde : ``` >>> def count_all(): ... total = 0 ... for t in Topic.query.all(): ... total += t.thread.comments.count() ... print(total) ... >>> timeit.timeit(count_all, number=1) 5765 1.801109447143972 ``` Par comparaison, sortir tous les commentaires prend 108 ms (oui c'est plus facile parce qu'on ne regarde pas les numéros de topics). ``` >>> timeit.timeit(lambda: print(len(Comment.query.all())), number=1) 5770 0.10828896099701524 ``` Quelque chose me dit que le problème donc c'est pas le fait d'avoir des gros topics mais le fait de faire une requête par topic sur la page. Ce qui est corroboré par les chiffres, puisque charger [la page 2 du forum de discussion](https://v5.planet-casio.com/forum/discussion/p/2), qui n'a qu'un commentaire par topic, prend autant de temps. Ça montre aussi que l'ORM est tout aussi chiant à utiliser correctement que le SQL original, ce qui est assez frustrant vu la grosse courbe d'apprentissage. Je vais voir si je peux trouver une solution pour améliorer les perfs de ce cas-là, histoire d'avoir un peu plus d'expérience pour identifier/résoudre les cas similaires dans le futur.

Le commit ci-dessus descend le temps de 250-400 ms pour la page avec le gros topic à 100-150 ms, et même un peu moins de 100 ms pour les pages moins chargées, donc je pense que j'ai tapé à peu près au bon endroit.

Si c'est satisfaisant, je pense qu'on peut fermer pour l'instant. Je vais rajouter un warning visuel pour les pages qui mettent longtemps à charger pour les devs histoire que d'autres problèmes de ce genre ne nous échappent pas dans le futur, et je propose de laisser venir ensuite.

Voilà pour le warning. J'ai mis 400 ms comme limite, sachant que c'est calculé au début du rendu, pas à la fin (pour ça il faudrait générer à la fin de la page un script pour modifier le header ; peut-être plus tard).

Ci-dessous un exemple (avec la limite à 50 ms).

Screenshot 2021-07-07 at 18-43-18 Planète Casio.png

87 KiB