Logo Blog perso d'Ozwald

Une vitesse de tous les diables

Par Oz le - Informatique
Python unicode performance tracing

Pour ce premier billet depuis la résurrection de mon blog et sa migration vers Pelican, je vais vous présenter une bizarrerie de Python2. Ce sera l'occasion de parler de persévérance, de temps perdu, et d'analyse de performance de code Python.

"Mickey Brown" driving an old dragster - CC BY SA by "Insomnia Cured Here" on Flickr

Le contexte

Il y a quelques années1 j'avais rédigé vite fait une petite librairie Python2 mono-fichier me permettant d'afficher proprement2 des tableaux dans un terminal. Bien que pleine de défauts, cette petite librairie est toujours utilisée par une poignée de projets au travail et j'avais donc toujours dans un coin de ma tête l'idée de la ré-écrire plus proprement. Le moteur principal de cette envie c'était de corriger LE défaut majeur de la librairie tel que je m'en souvenais : quand elle traite des tableaux dépassant le millier de lignes, elle devient vraiment lente (jusqu'à plusieurs dizaines de secondes juste pour l'affichage du tableau, en fonction de votre CPU).

Ce (long) weekend, je m'étais lancé dans l'écriture d'une librairie générant des graphiques en nuages de points dans un terminal3. Dans l'élan, je me suis enfin attelé à la ré-écriture de cet afficheur de tableau ! Quatre années s'étant écoulées depuis la précédente version, la nouvelle sera écrite en Python3 avec un algorithme totalement différent pour calculer la largeur optimale des colonnes4. À la fin de la journée, en ayant codé "une heure par-ci, dix minutes par-là", ma nouvelle version de la librairie était prête à être testée.

Je lance quelques tests et j'observe un premier effet inattendu (mais très agréable) : le choix de largeur des colonnes est beaucoup plus pertinent sur ma nouvelle version que sur l'ancienne ! Fort de cette agréable surprise, j'attaque confiant la vérification du gain de performance tant recherché. Pour comparer les performances de l'ancienne et de la nouvelle librairie, je jette une vingtaine de lignes de code dans un fichier que j'appelle "stresstest.py"

import random

data = []
for _ in range(2000):
    line = [random.randint(1,i+1)*'{0:.04f}'.format(random.random()) for i in range(25)]
    data.append(line)

import time
before = time.time()

import NEWLIB
a = NEWLIB.Array(data)
print(a)
after1 = time.time()

import OLDLIB
b = OLDLIB.ascii_array()
for row in data:
    b.add_row(row)
print(b)
after2 = time.time()

print("Nouvelle librairie : {0}s".format(after1-before))
print("Ancienne librairie : {0}s".format(after2-after1))

Je lance ce fichier et...

$ python3 stresstest.py
...
Traceback (most recent call last):
  File "(...)OLDLIB.py", line 55, in __init__
    content = unicode(content, errors='replace')
NameError: name 'unicode' is not defined

Prévisible. Une librairie écrite il y a 4 ans pour du Python2 avait quand même de fortes chances de ne pas fonctionner avec du Python3. Pas grave, pour le comparatif, je n'ai qu'à lancer stresstest.py avec un interpréteur Python2. Évidemment, cette fois c'est la nouvelle librairie qui refuse de fonctionner. Que faire ? Sachant que :

  • J'avais en tête de remplacer la vieille librairie par la nouvelle (or la vieille librairie est actuellement utilisée par quelques projets qui tournent encore en Python2) ;
  • Le code de la nouvelle librairie était encore frais dans ma tête (car tout juste écrit), contrairement au code de l'ancienne (pas relu depuis sa création initiale) ;
  • En 4 ans je pense que j'ai progressé et que le code de la nouvelle librairie est plus facilement maintenable/modifiable que le code de l'ancienne librairie.

J'ai donc décidé de modifier ma nouvelle librairie pour la rendre compatible Python2.

Le détail où se cache le diable

Le premier problème (quand je lance ma nouvelle librairie en Python2) c'est que mon code de test demande l'affichage d'un tableau dans lequel certaines cellules contiennent des caractères nationaux. Voici l'un d'eux avec un accent sur le "e" de Fév(rier) :

│     T1    │     T2     │Futur│
│Jan│Fév│Mar│Avr│Mai│Juin│     │
│0.0│0.2│0.8│1.3│0.7│0.7 │  ?  │
│0.7│0.9│1.3│1.4│0.9│1.2 │  ?  │

N'ayant rien précisé sur ces chaines de caractère, Python2 considère qu'il s'agit de son type par défaut, à savoir string. Le problème c'est que, en l'absence d'indication contraire, Python2 traite les données des string comme si elles étaient encodées en ascii or nos caractères nationaux n'existent pas en ascii. Ainsi, Python2 "plante"5 dès qu'il tente de traiter cet accent.

La première correction a donc été plutôt rapide : j'ai supprimé les accents de mon jeu de données de test. Ça me permet bien de contourner le plantage, mais la sortie affichée est immonde puisque tous les caractères unicodes que j'utilise (tout particulièrement les barres verticales délimitant les colonnes du tableau) sont affichées en tant que séquence d'échapement :

$ python3 -c 'print("\u2502")'

$ python2 -c 'print("\u2502")'
\u2502

Autant vous dire que mes tableaux ne ressemblent plus à rien. Le problème est similaire au précédent : en l'absence de précision, Python2 considère que ma chaine de caractère est une chaine ascii et il n'interprète donc pas la séquence d'échapement unicode. Pour corriger ça on peut, par exemple, re-passer sur l'ensemble du code et préfixer les chaines de caractères qui contiennent de l'unicode par la lettre "u" :

$ python2 -c 'print("\u2502")'
\u2502
$ python2 -c 'print(u"\u2502")'

Étant pressé de tester la performance de ma nouvelle librairie, j'opte pour une solution plus rapide qui consiste à utiliser un import "magique" précisant à Python2 qu'il doit considérer toutes mes chaines de caractères comme étant de l'unicode. Cette précision amène ainsi Python2 à se comporter comme Python3 vis à vis des chaines de caractères, ce qui va me simplifier la vie6 puisque la librairie est écrite pour Python3 :

from __future__ import unicode_literals

Avec ça, je n'aurai plus de problème d'interprétation de caractères unicode puisque l'interpréteur Python2 se comportera exactement comme l'interpréteur Python3 :

$ python2 -c 'from __future__ import unicode_literals;print("\u2502")'

$ python3 -c 'from __future__ import unicode_literals;print("\u2502")'

Je re-lance le test mais, cette fois, c'est une vérification de conformité de ma nouvelle librairie qui grogne. En effet, ma nouvelle librairie exige que toutes les cellules du tableau à afficher ne contiennent que des chaines unicodes. La librairie ne se charge pas de transformer d'éventuels entiers, flottants, ou datetime.datetime en chaines imprimables. Cette conversion en chaine de caractères imprimables, c'est le boulot du code qui appelle la librairie. Sauf que, pour vérifier que le code appelant respecte bien cette convention de type, j'ai utilisé un if isinstance(cell, str). La classe str correspond bien à une chaine unicode en Python3, mais pas en Python2. En Python2, les chaines unicodes sont de type unicode, pas de type str...et mon import "magique" vient de transformer toutes mes chaines str en unicode... Bon, il suffit de modifier la condition de mon test de conformité pour que ça passe :

from sys import version_info

(...)

    if isinstance(cell, str)\
        or ((version_info<(3,0) and cell.__class__.__name__=='unicode')):  # Python2

Nouvelle tentative : la librairie fonctionne bien...jusqu'au print final qui me retourne le tant redouté "UnicodeEncodeError: 'ascii' codec can't encode character u'\u2502' in position 4: ordinal not in range(128)"... Bon, je sais comment corriger ce "petit" problème : il faut appeler encode(...) et decode(...) aux bons moments sur les chaines que je souhaite imprimer, mais ça risque d'être un peu fastidieux et, surtout, d'insérer beaucoup de code Python2 dans ma librairie Python3. Heureusement, j'ai une solution alternative : j'avais tout codé de façon à pouvoir désactiver facilement l'utilisation de caractères unicodes exotiques pour enjoliver l'ascii-art. Je n'ai donc qu'à changer le comportement par défaut (afficher de l'unicode, sauf mention contraire) en son inverse pour le Python2 (à savoir : ne pas utiliser d'unicode, sauf mention contraire) :

class BEFORE:
    def __init__(self, only_ascii=False, ...)
        self.only_ascii = only_ascii


class AFTER:
    def __init__(self, only_ascii=None, ...)
        self.only_ascii = only_ascii
        if only_ascii is None:
            self.only_ascii = False if version_info>=(3,0) else True

La modification est très simple et, en fait, j'aurai du y penser avant de faire un import "magique" qui transforme la quasi totalité de mes textes en chaines unicode (on en reparlera...). Au final, j'ai touché à moins de 10 lignes et, maintenant, la librairie accepte de m'afficher des tableaux lorsqu'elle est exécutée avec un interpréteur Python2. C'est moins joli (puisque je me restreint aux symboles ascii), mais c'est quand même très lisible :

|     T1    |     T2     |Futur|
|Jan|Fev|Mar|Avr|Mai|Juin|     |
|0.0|0.2|0.8|1.3|0.7|0.7 |  ?  |
|0.7|0.9|1.3|1.4|0.9|1.2 |  ?  |

Le moment de la confrontation est donc enfin venu, je lance mon comparateur, super confiant :

$ python2 stresstest.py
(...)
Nouvelle librairie : 12.8832149506s
Ancienne librairie : 2.36754417419s

Douche froide. Une fois la première vague de déception avalée, je hack dans ma nouvelle librairie une optimisation que j'avais été contraint de faire sur l'ancienne (sinon elle était vraiiiiiment lente) : au lieu de prendre en compte toutes les lignes pour calculer la largeur idéale des colonnes, je n'en considère qu'un échantillon. (Mal?)Heureusement, ça ne sert à rien du tout et je retire ce vieux hack.

Le diagnostic

Devant un problème de vitesse, j'ai pris l'habitude de dégainer cProfile. Aussitôt dit, aussitôt fait : je commente les 6 lignes qui importent puis appellent l'ancienne librairie puis je relance le stresstest en traçant son exécution.

$ python2 -m cProfile -s cumtime stresstest.py
(...)
Nouvelle librairie : 14.5225701332s
(...)
         1110680 function calls in 15.248 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.258    0.258   15.248   15.248 stresstest.py:1(<module>)
        1   12.006   12.006   13.847   13.847 NEWLIB.py:902(__str__)
        1    0.232    0.232    0.812    0.812 NEWLIB.py:853(compute_col_width)
    50000    0.479    0.000    0.774    0.000 NEWLIB.py:733(formatted)
(...)

Cette fois, cProfile me laisse un peu tomber. En effet, ce profileur a pleins de qualités (dont celles d'être dans la librairie standard et très simple à utiliser) mais il ne trace que les appels de fonctions et, visiblement, dans mon cas ça ne sera pas assez précis. En effet, la trace m'indique qu'il passe bien 13.847s (des 14.5225701332s que stresstest.py mesure lui-même) dans la fonction __str__ de ma nouvelle librairie mais nous ne saurons pas qu'est-ce-qui, dans cette fonction de 28 petites lignes, prend le plus gros du temps (puisque la fonction qui a pris le plus de temps juste après est négligeable avec ses 0.812s alors que je pensais que ça serait justement elle la plus lente puisque c'est cette portion de code qui était critique dans la vieille version).

Heureusement, Google ne me laisse pas tomber et je découvre rapidement l'existence de line_profiler. Je l'installe donc dans un environnement virtuel avec pip install line_profiler, j'ajoute un @profile au dessus de ma fonction __str__, je baisse drastiquement le nombre de lignes du tableau (pour ne pas attendre encore 15s pour avoir mon résultat) et c'est parti :

$ kernprof -l -v stresstest.py
(...)
Total time: 2.68528 s
File: NEWLIB.py
Function: __str__ at line 902

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   902                                               @profile
   903                                               def __str__(self):
   904         1     308429.0 308429.0     11.5          self.compute_col_width()
(...)
   913     17500     865419.0     49.5     32.2                  result += '|' if self.only_ascii else '\u2502'
(...)
   923     17500     882593.0     50.4     32.9                      result += to_add
(...)

La surprise n'est pas immense, mais ça fait plaisir d'avoir des "preuves". D'abord, on note que le calcul de largeur des colonnes prend ici 11.5% du temps alors qu'il ne représentait que 5,86% sous cProfile... C'est peut-être la différence de traceur qui explique cet écart, ou la réduction drastique du nombre de lignes. En tout cas, il reste marginal face aux 65% passés dans deux lignes anodines : des concaténations de chaines.

Anodines ? Pas tant que ça en fait. La vitesse de concaténation des chaines de caractères en Python est un sujet assez souvent évoqué sur Internet. D'ailleurs, pour rapidement construire une chaine de caractère en Python2, on voit très souvent des appels à la fonction join, censée être beaucoup plus rapide :

bigstring = ''
small_string = 'plop'

# Ça, c'est censé être lent
for _ in range(500):
    bigstring += small_string

# Ça, c'est censé être rapide
bigstring = ''.join([small_string for _ in range(500)])

Je le savais déjà, j'avais déjà utilisé ce genre de formulation (y compris dans ma vieille librairie), mais je n'avais jamais vérifié si il y avait un vrai gain de performance. Il est donc temps de vérifier ! Après cProfile, on va donc utiliser timeit, un autre module standard qui est justement conçu pour faire des comparaison de performances.

$ python2  -m timeit -s 'bigstring=""' 'for i in range(1000):' ' bigstring+="plop"'
10000 loops, best of 3: 69.7 usec per loop
$ python2  -m timeit -s 'bigstring=""' 'bigstring+="".join(["plop" for _ in range(1000)])'
10000 loops, best of 3: 49 usec per loop

D'accord c'est plus rapide, mais je n'ai même pas un facteur 2. On est loin du facteur 6 que l'ancienne librairie met à ma nouvelle.

Découverte du paradoxe

Je commence donc à être circonspect sur mon analyse. D'autant plus que, lorsque je faisais mes tests fonctionnels pendant le développement de la nouvelle librairie, elle ne m'avait pas l'air si lente que ça...

Par acquis de conscience, je prends le stresstest.py dont j'ai commenté la partie relative à l'ancienne librairie, je supprime le décorateur @profile, et je lance ce stresstest deux fois d'affilés en changeant juste l'interpréteur :

$ python2 stresstest.py
(...)
Nouvelle librairie : 66.7044699192s
(...)

$ python3 stresstest.py
(...)
Nouvelle librairie : 0.8455526828765869s
(...)

Rho la vache ! Ça serait juste une question d'interpréteur ?! La version 3 de Python aurait-elle amené un gain aussi énorme sur une fonction aussi basique qu'une concaténation de chaine ?! Vérifions, avec timeit, si le Python3 met vraiment une claque au Python2 (ça tombe bien, on a testé Python2 il y a un pragraphe de ça :-D).

$ python3  -m timeit -s 'bigstring=""' 'for i in range(1000):' ' bigstring+="plop"'
2000 loops, best of 5: 104 usec per loop
$ python3  -m timeit -s 'bigstring=""' 'bigstring+="".join(["plop" for _ in range(1000)])'
5000 loops, best of 5: 49.1 usec per loop

Là, c'est le moment où j'en ai perdu mon latin. Python3 est en fait légèrement plus lent que Python2 sur ces opérations de concaténation de chaine qui sont censées prendre la majorité du temps et, pourtant, Python2 est 79 fois plus lents que Python3 sur mon stresstest.py (sur 2000 lignes) !

Conclusion

À ce moment de l'analyse j'ai passé une bonne demi-heure à vérifier tout un tas d'hypothèse à coup de timeit. Systématiquement, Python2 était dans le même ordre de grandeur de vitesse que Python3. Puis j'ai eu une illumination...

from __future__ import unicode_literals

Évidemment, j'avais fait tous mes timeit avec des string standard or avec l'import de unicode_literals j'avais, quasi-silencieusement, transformé presque toutes mes string standard de l'interpréteur Python2 par des objets d'un type totalement différents (des objets unicode). Voyons voir si Python2 manipule aussi bien les unicode que les str :

$ python2  -m timeit -s 'bigstring=""' 'for i in range(1000):' ' bigstring+="plop"'
10000 loops, best of 3: 69.9 usec per loop
$ python2  -m timeit -s 'bigstring=u""' 'for i in range(1000):' ' bigstring+=u"plop"'
100 loops, best of 3: 117 msec per loop

Et bien voilà un joli facteur 1674 ! L'explication de l'extrème lenteur de ma nouvelle librairie quand on utilise un interpréteur Python2 se décompose donc ainsi :

  • J'ai transformé quasiment tous les objets str en objets unicode pour le Python2 avec mon import "magique"
  • Python2 est beaucoup plus lent à manipuler des objets unicode que des objets str

Pour une comparaison plus honnête entre mes deux librairies, je lance alors un stresstest de l'ancienne librairie avec un interpréteur Python2 et un autre de la nouvelle librairie avec un interpréteur Python3 :

$ python2 stresstest2.py
(...)
Ancienne librairie : 6.01993203163s

$ python3 stresstest3.py
Nouvelle librairie : 0.8533799648284912s

Pour afficher un tableau de 2000 lignes la nouvelle librairie va donc 7 fois plus vite que l'ancienne. De plus, l'affichage est meilleur7. Malheureusement, je ne peux pas remplacer mon ancienne librairie par la nouvelle dans les projets les plus importants au boulot car ils tournent encore en Python2 et qu'ils doivent traiter des caractères non-ascii. Dommage...

Au moins j'ai la nouvelle librairie pour les projets Python3, j'ai découvert line_profile, et si j'arrive à me motiver je pourrai toujours plonger dans le code de la vieille librairie pour lui adapter le nouvel algorithme de calcul de largeur des colonnes8.

  1. Le 6 aout 2016 pour être précis, donc il y a environ 4 ans (merci git :)).
  2. Cette librairie permet d'afficher des en-tête, des colonnes bien alignées les unes à côté des autres, et le contenu des cellules est tronqué de façon "intelligente" quand tout ne rentre pas dans la largeur du terminal.
  3. J'aime bien utiliser le terminal et j'aime bien les librairies minimalistes.
  4. Je suis passé d'un algo assez naïf tentant maladroitement d'implémenter du "Regret Minimization" à quelque chose de beaucoup plus court n'utilisant que deux mesures statistiques pour tenter d'aller plus vite.
  5. En réalité il remonte une exception propre, mais le résultat est le même : le programme s'arrête sur une stacktrace.
  6. En réalité, c'était une grave erreur qui va me faire perdre une heure...on s'en rendra compte plus tard
  7. C'est le premier effet bénéfique inattendu dont j'ai parlé tout en début d'article et qui découle directement du changement complet d'algorithme de calcul de la largeur optimale des colonnes
  8. On se console comme on peut.