Si vous rêvez de faire des graphiques exposant vos optimisations avec des échelles logarithmiques, ce tuto est fait pour vous...
Sommaire
Outil de profiling de code
Côté système
La commande time est votre amie:
$ time python mon_module.py
real 2m35.527s
user 7m35.268s
sys 0m5.346s
- real: Temps réel écoulé entre le lancement et l'arrêt du processus. Cette valeur est influencée par les mises en pause dues à d'autres processus s'exécutant en en parallèle sur la machine.
- user: Temps CPU consommé seulement par le processus en user-mode. Cette valeur n'est pas influencée par la charge de la machine.
- sys: Temps CPU passé dans le noyau (exécution d'appels système gérés par le noyau car nécessitant des privilèges: allocation mémoire, accès aux périphériques).
PS: Temps CPU total = user time + sys time
Plus d'infos sur stackoverflow: output of time.
Côté Python
pycallgraph est un excellent outil de profiling permettant notamment d'obtenir le nombre d'appels et le temps de calcul nécessaire pour chaque fonction du code.
Dans la suite de l'article, les captures affichées proviendront de pycallgraph.
Installation:
$ sudo pip install pycallgraph
$ sudo pip install graphviz
Utilisation:
$ pycallgraph mon_module.py
Ou dans le code via un context manager pour tracer uniquement certains blocs:
from pycallgraph import PyCallGraph
from pycallgraph.output import GraphvizOutput
with PyCallGraph(output=GraphvizOutput()):
...code
Modifications du code Python
De bonnes intentions
Utilisez des listes, dictionnaires, et sets en intention partout, tout le temps ! Les boucles for en Python ne sont ni esthétiques ni efficaces; elles sont aussi le meilleur moyen de montrer que vous ne maîtrisez pas le langage.
Avant:
lvars = []
for lcl in self.__dynamic_constraints:
for clause in lcl:
solv.add_clause(clause)
lvars.append(self.vars_in_clause(clause))
Après:
[solv.add_clause(clause) for lcl in self.__dynamic_constraints for clause in lcl]
Autres exemples, avant:
ldc = self.__dynamic_constraints[-1]
nlc = []
for clause in ldc:
shift_c = self.__shift_clause(clause)
nlc.append(shift_c)
self.__dynamic_constraints.append(nlc)
######
final_dsol = []
for var in fsolution.frontier_values:
if var < 0:
final_dsol.append([var])
Après:
self.__dynamic_constraints.append(
[self.__shift_clause(clause)
for clause in self.__dynamic_constraints[-1]]
)
######
final_dsol = \
[[var] for var in fsolution.frontier_values if var < 0]
Gain: 27,42 secondes => 18,11 secondes
Puis réécrivons la fonction __shift_clause() appelée dans le bloc ci-dessus:
Avant:
shift_c = []
for lit in ncl:
if lit > 0:
slit = lit + self.__shift_step
else:
slit = lit - self.__shift_step
return shift_c
Après:
return [(lit + self.__shift_step) if lit > 0 else (lit - self.__shift_step)
for lit in ncl]
Avant:
Après l'optimisation en Python:
Gain: 27,42 secondes => 11,21 secondes
Limiter les appels de fonctions
Tout ce qui est fonction en Python est couteux. En temps normal il FAUT faire des fonctions pour découper le code et le rendre lisible par un humain, mais en cas de micro-optimisation préférez déclarer une variable une fois pour toutes, ou accéder directement à l'attribut privé d'un objet plutôt que d'appeler un getter de multiples fois.
Avant:
len1 = len(self.__unfolder.get_inputs())
len2 = len(self.__unfolder.get_free_clocks())
if len1 == 0 and len2 == 0:
return []
unflat = self.unflatten()
ic_traj = []
for xic in unflat:
xi_ic = self.extract_act_inputs_clocks(xic)
ic_traj.append(xi_ic)
return ic_traj
Après:
return [] \
if (len(self.__unfolder.get_inputs()) == 0) and (len(self.__unfolder.get_free_clocks()) == 0) \
else [self.extract_act_inputs_clocks(xic)
for xic in self.unflatten()]
Dans l'exemple ci-dessous, on remplace for i in range(len(sol)): par or i, sol in enumerate(self.__solution): ce qui permet d'itérer sur une valeur incrémentée et sur le contenu de la liste en même temps.
De plus l'appel à self.__unfolder.get_frontier() ne se fait plus qu'une fois par appel de la fonction au lieu d'une fois par tour de boucle.
Avant:
jmax = len(self.__unfolder.get_frontier())
fsol = []
j = 0
dec = self.__shift_step * self.__current_step
sol = self.__solution
for i in range(len(sol)):
# the variable is frontier var:
if abs(sol[i]) == self.__unfolder.get_frontier()[j]:
if self.__shift_direction == "FORWARD":
fsol.append(sol[i])
else:
fsol.append(sol[i+dec])
j += 1
if j == jmax:
return fsol
return fsol
Après:
frontiers = self.__unfolder.get_frontier()
jmax = len(frontiers)
fsol = list()
j = 0
dec = self.__shift_step * self.__current_step
for i, sol in enumerate(self.__solution):
# the variable is frontier var:
if abs(sol) == frontiers[j]:
if self.__shift_direction == "FORWARD":
fsol.append(sol)
else:
fsol.append(self.__solution[i+dec])
j += 1
if j == jmax:
return fsol
return fsol
Diff:
+ frontiers = self.__unfolder.get_frontier()
+ jmax = len(frontiers)
+ fsol = list()
j = 0
- sol = self.__solution
dec = self.__shift_step * self.__current_step
- for i in range(len(sol)):
+ for i, sol in enumerate(self.__solution):
# the variable is frontier var:
- if abs(sol[i]) == self.__unfolder.get_frontier()[j]:
+ if abs(sol) == frontiers[j]:
if self.__shift_direction == "FORWARD":
- fsol.append(sol[i])
+ fsol.append(sol)
else:
- fsol.append(sol[i+dec]) # look for initial values
+ fsol.append(self.__solution[i+dec])# look for initial values
j += 1
if j == jmax:
return fsol
return fsol
Les appels à get_frontier() en images:
Avant:
Après:
Gain total sur la fonction appelante: 10.36 secondes => 1,27 seconde
Soit un coefficient de: 8.2.
Lisibilité vs performance
En cas de micro-optimisations requises, on peut éventuellement sacrifier la lisibilité du code; Encore une fois, les one-liners sont toujours conseillés; on peut en user et en abuser, étant donné qu'ils sont toujours plus rapides que leurs équivalents développés.
Avant:
num_clause = []
for lit in clause.list_of_literals:
# Nouvelle variable à chaque tour de boucle
name = lit.name
if name[-1] == '`':
lit_cod = self.__var_code_table[name[:-1]] + self.__shift_step
else:
lit_cod = self.__var_code_table[name]
if not lit.sign:
lit_cod = - lit_cod
num_clause.append(lit_cod)
Notons qu'ici, à chaque tour de boucle une variable name est déclarée, or l'accès à l'attribut name de l'objet lit n'est PAS couteux alors que la déclaration l'est.
Il faut là aussi privilégier les one-liners (ici des opérateurs conditionnels ternaires).
Après:
num_clause = []
for lit in clause.list_of_literals:
if lit.name[-1] == '`':
num_clause.append(-(self.__var_code_table[lit.name[:-1]] + self.__shift_step) if not lit.sign else (self.__var_code_table[lit.name[:-1]] + self.__shift_step))
else:
num_clause.append(-self.__var_code_table[lit.name] if not lit.sign else self.__var_code_table[lit.name])
Gain: 10.2 secondes => 5.9 secondes
La fonction présentée ici se nomme __forward_code(), on voit sur l'image ci-dessous qu'elle est responsable d'un certain ralentissement, mais que son unique fonction appelante double également le temps de traitement; à titre d'introduction au dernier chapitre, voici ce que l'on peut espérer lors de la migration de ces fonctions dans un module écrit en C (au prix de 270 lignes de code...):
Avant le développement en C:
Après le développement en C:
Passage à la même fonction en C: 1,3 seconde
Coefficient depuis la réécriture du code: 7.8
Du vrai Python et de vrais algorithmes
Relire et corriger les algorithmes ! Le code stupide est partout ! Éviter d'implémenter des algos en Python comme on le ferait en C ou en Java !
Exemples de comparaison d'un ensemble d'éléments avec un autre :
1ière façon:
if len(self.frontier_values) == len(other.frontier_values):
sfr = frozenset(self.frontier_values)
xxx = sfr.intersection(other.frontier_values)
return len(self.frontier_values) == len(xxx)
else:
return False
return set(self.frontier_values) == set(other.frontier_values)
2ième façon:
if len(self.activated_frontier) == len(other.activated_frontier):
self.activated_frontier.sort()
other.activated_frontier.sort()
for i in range(len(self.activated_frontier)):
if other.activated_frontier[i] != self.activated_frontier[i]:
return False
return True
else:
return False
Version normale:
return set(self.frontier_values) == set(other.frontier_values)
Évidemment c'est plus rapide, et plus lisible...
Il faut essayer d'identifier les cas les plus fréquents permettant d'éviter de faire plus loin des vérifications couteuses:
Avant:
out = []
for s_varcode in s_vector:
cond1 = s_varcode in self.__unfolder.get_inputs()
cond2 = s_varcode in self.__unfolder.get_free_clocks()
if cond1 or cond2:
if s_varcode > 0:
out.append(s_varcode)
return out
Après:
inputs = frozenset(self.__unfolder.get_inputs())
free_clocks = frozenset(self.__unfolder.get_free_clocks())
return [s_varcode for s_varcode in s_vector
if (s_varcode > 0)
and ((s_varcode in inputs)
or (s_varcode in free_clocks))]
Dans la première version, get_inputs() et get_free_clocks() retournent des listes; or la recherche d'éléments à l'intérieur est très couteuse; d'autant plus que ces listes contiennent en fait plusieurs centaines de milliers d'éléments.
Pour les recherches dans des ensembles utilisez des structures de données adéquates: des set ou des frozenset (structures immuables) référençant les objets stockés sous forme hashée.
De plus s_varcode > 0 est une vérification peu couteuse qui permettrait précisément d'éviter les recherches (effectuées visiblement 2 476 929 fois avant optimisation du code)...
Avant:
Après:
Gain: 162,36 secondes => 3,92 secondes
Autre exemple d'algorithme réécrit: get_unshift_code()
Avant:
if var_num < 0:
varnum1 = -var_num
sign = -1
else:
varnum1 = var_num
sign = 1
var_code = (varnum1 - 1) % self.__shift_step + 1
if var_code <= self.__shift_step:
return var_code*sign
Après:
var_code = (abs(var_num) - 1) % self.__shift_step + 1
if var_code <= self.__shift_step:
return var_code * (-1 if var_num < 0 else 1)
Avant:
Après:
Gain: 21,29 secondes => 12,46 secondes
On s'aperçoit que cette section constitue toujours un goulet d'étranglement. Le chapitre suivant montrera que l'on peut encore avoir un gain de temps substantiel en utilisant un module écrit en C.
Migration du code en C
Quand faut-il abandonner Python ?
Presque jamais. Le langage est performant dans l'immense majorité des cas. S'il ne l'est pas c'est souvent car l'algo est à refaire. De plus, Python a tendance à forcer les gens à coder plus proprement que dans d'autres langages (encore que, même en Python on devrait retirer le clavier de certain(e)s). Concrètement avec Python, le développeur ne se soucie pas de la gestion de la mémoire, le code est réduit, plus facile à produire et surtout très lisible et maintenable [*].
Toutefois dans des cas bien précis, lorsqu'une application est arrivée à un stade mature et souffre toujours de ralentissements bien connus et identifiés, il peut être intéressant d'investir du temps en passant certaines de ses fonctions en C.
Quelques exemples de migration vers un code C sont donnés plus loin. Les gros désavantages sont que vous perdrez en maintenabilité, en souplesse de développement, et exposez votre programme aux fuites mémoire. Tout ceci peut être bien pire que les quelques secondes grappillées.
[*]: Évidemment si vous développez un container Docker, vous vous moquez de ces considérations puisque vous destinez votre code à être encapsulé dans une putain de boite opaque. Personne n'est parfait.
Exemples de conversion Python vers C
Au chapitre précédent la fonction get_unshift_code() avait été réécrite:
var_code = (abs(var_num) - 1) % self.__shift_step + 1
if var_code <= self.__shift_step:
return var_code * (-1 if var_num < 0 else 1)
Elle restait pourtant particulièrement côuteuse; passons-là donc en C:
static PyObject* get_unshift_code(PyObject *self, PyObject *args, PyObject *kwds)
{
#ifndef NDEBUG
/* Debugging code */
printf("get unshift code\n");
#endif
int var_num;
int shift_step;
static char* kwlist[] = {"var_num", "shift_step", NULL};
if (!PyArg_ParseTupleAndKeywords(args, kwds, "ii", kwlist,
&var_num,
&shift_step)) {
return NULL;
}
int var_code = (abs(var_num) - 1) % shift_step + 1;
if (var_code <= shift_step) {
return Py_BuildValue("i", var_code * ((var_num < 0) ? -1 : 1));
}
PyErr_SetString(PyExc_ValueError, "Not a DIMACS code of an initial variable.");
return NULL;
}
Résultat:
Gain: 12,46 secondes => 2,86 secondes
Coefficient depuis la réécriture du code: 4.4
Puis passons également la fonction appelante unflatten() en C:
shift = self.__shift_step
lv_traj = []
step = 0
dec = 0
len_shift_step_init = self.__unfolder.get_shift_step_init()
while dec + shift < len(self.__solution):
lv_traj.append(
[get_unshift_code(self.__solution[i+dec], self.__shift_step)
for i in range(len_shift_step_init)]
)
step += 1
dec = step * shift # first index of time step
return lv_traj # list of lists
static PyObject* unflatten(PyObject *self, PyObject *args, PyObject *kwds)
{
#ifndef NDEBUG
/* Debugging code */
printf("unflatten\n");
#endif
int shift_step;
int len_shift_step_init;
PyObject* solution;
static char* kwlist[] = {"solution", "len_shift_step_init", "shift_step", NULL};
if (!PyArg_ParseTupleAndKeywords(args, kwds, "Oii", kwlist,
&solution,
&len_shift_step_init,
&shift_step)) {
return NULL;
}
Py_ssize_t solution_size = PySequence_Size(solution);
PyObject *lv_traj = PyList_New(0);
if (lv_traj == NULL) {
PyErr_SetString(PyExc_SystemError, "failed to create a list");
return NULL;
}
Py_ssize_t step = 0;
Py_ssize_t dec = 0;
PyObject *unshift_code;
PyObject *item;
PyObject *tmp_traj;
PyObject *arglist;
while ((dec + shift_step) < solution_size) {
tmp_traj = PyList_New((Py_ssize_t)len_shift_step_init);
for (Py_ssize_t i = 0; i < (Py_ssize_t)len_shift_step_init; i++) {
// Get item of solution (int)
// New reference.
item = PySequence_GetItem(solution, i + dec);
if(item == NULL) {
return NULL;
}
// Build parameters of get_unshift_code
// {"var_num", "shift_step", NULL};
#ifdef IS_PY3K
arglist = Py_BuildValue("(ii)", PyLong_AS_LONG(item), shift_step);
#else
arglist = Py_BuildValue("(ii)", PyInt_AS_LONG(item), shift_step);
#endif
Py_DECREF(item);
unshift_code = get_unshift_code(self, arglist, NULL);
Py_DECREF(arglist);
if(unshift_code == NULL) {
/* Pass error back */
Py_DECREF(unshift_code);
return NULL;
}
PyList_SET_ITEM(tmp_traj, i, unshift_code);
}
PyList_Append(lv_traj, tmp_traj);
Py_DECREF(tmp_traj);
step++;
// first index of time step
dec = step * shift_step;
}
if (PyErr_Occurred()) {
/* propagate error */
Py_DECREF(lv_traj);
return PyErr_SetFromErrno(outofconflerr);
}
// Return list of all trajectories
return lv_traj;
}
Résultat:
Gain: 2,86 secondes => 0,36 secondes
Gain total: 56,74 secondes => 0,36 seconde
Coefficient depuis la réécriture du code: 157.6
Rappelez-vous cette ligne (cf. De bonnes intentions):
[solv.add_clause(clause) for lcl in self.__dynamic_constraints for clause in lcl]
La fonction add_clause() (déjà rédigée en C) accepte un élément d'un itérable mais pas l'itérable lui-même. Afin de limiter les appels de cette fonction et d'éviter la lourdeur des itérations en Python, on peut réaliser une fonction en C, se chargeant d'appeler add_clause() sur un itérable donné.
Appel de l'API en Python:
solv.add_clauses(itertools.chain(*self.__dynamic_constraints))
# Less efficient alternative
# solv.add_clauses([clause for lcl in self.__dynamic_constraints for clause in lcl])
Fonction add_clauses() en C:
static PyObject* add_clauses(Solver *self, PyObject *args, PyObject *kwds)
{
static char* kwlist[] = {"clauses", NULL};
PyObject *clauses;
if (!PyArg_ParseTupleAndKeywords(args, kwds, "O", kwlist, &clauses)) {
return NULL;
}
PyObject *iterator = PyObject_GetIter(clauses);
if (iterator == NULL) {
PyErr_SetString(PyExc_TypeError, "iterable object expected");
return NULL;
}
PyObject *clause;
PyObject *arglist;
PyObject *ret;
while ((clause = PyIter_Next(iterator)) != NULL) {
arglist = Py_BuildValue("(O)", clause);
ret = add_clause(self, arglist, NULL);
Py_DECREF(ret);
/* release reference when done */
Py_DECREF(arglist);
Py_DECREF(clause);
}
/* release reference when done */
Py_DECREF(iterator);
if (PyErr_Occurred()) {
return NULL;
}
Py_INCREF(Py_None);
return Py_None;
}
Gain: 5,7 secondes => 1,4seconde
Coefficient depuis la réécriture du code: 4
Reprenons la fonction __shift_clause() (cf. De bonnes intentions) en C:
Après l'optimisation en Python:
Après le passage en C:
Gain: 11,21 secondes => 8,63 secondes
Coefficient depuis la réécriture du code: 3.2
La fonction appelante vue dans le même chapitre s'est avérée être également un goulet d'étranglement:
self.__dynamic_constraints.append(
[self.__shift_clause(clause)
for clause in self.__dynamic_constraints[-1]]
)
Voici sa version en C:
static PyObject* shift_dynamic(PyObject *self, PyObject *args, PyObject *kwds)
{
#ifndef NDEBUG
/* Debugging code */
printf("shift dynamic\n");
#endif
int shift_step;
PyObject* constraints;
static char* kwlist[] = {"dynamic_constraint", "shift_step", NULL};
if (!PyArg_ParseTupleAndKeywords(args, kwds, "Oi", kwlist,
&constraints,
&shift_step)) {
return NULL;
}
if (!PySequence_Check(constraints)) {
PyErr_SetString(PyExc_TypeError, "list expected");
return NULL;
}
Py_ssize_t size = PySequence_Size(constraints);
if (size == 0) {
// Empty list, return empty list
return PyList_New(0);
}
//printf("List size: %d\n", size);
PyObject *shifted_clauses = PyList_New(PySequence_Size(constraints));
if (shifted_clauses == NULL) {
PyErr_SetString(PyExc_SystemError, "failed to create a list");
return NULL;
}
// Iterate on last item
PyObject *iterator = PyObject_GetIter(constraints);
if (iterator == NULL) {
/* propagate error */
PyErr_SetString(PyExc_SystemError, "could not create iterator on list");
return NULL;
}
PyObject *shifted_clause;
PyObject *clause;
PyObject *arglist;
Py_ssize_t i = 0;
while ((clause = PyIter_Next(iterator)) != NULL) {
// Build parameters of shift_clause
// shifted_clause = shift_clause(self, clause, shift_step);
arglist = Py_BuildValue("(Oi)", clause, shift_step);
shifted_clause = shift_clause(self, arglist, NULL);
Py_DECREF(arglist);
if(shifted_clause == NULL) {
/* Pass error back */
Py_DECREF(shifted_clauses);
Py_DECREF(iterator);
return NULL;
}
PyList_SET_ITEM(shifted_clauses, i, shifted_clause);
/* release reference when done */
// no DECREF on the return of shift_clause, because PyList_SET_ITEM steals reference
Py_DECREF(clause);
i++;
}
/* release reference when done */
Py_DECREF(iterator);
return shifted_clauses;
}
Avant le passage de shift_dynamic() et __shift_clause() en C:
Après:
Coefficient depuis la réécriture du code: 28
Conclusion
« Early optimisation is the root of all evil », l'optimisation précoce est la racine de tous les maux.
Au début du développement on doit faire du code sale, non structuré, c'est normal étant donné que l'on fait la preuve de concept.
Ensuite seulement, on s'intéresse à l'architecture du programme, puis à la toute fin, à son optimisation. Il est inutile de perdre du temps à peaufiner un travail qui subira de nombreuses modifications.
Python est un langage très haut niveau; en apparence peu exigeant il l'est en fait plus que certains langages comme le Java par exemple, car il ne pardonnera pas les erreurs dues au manque de maîtrise/pratique.
La migration de code Python vers du code C doit rester exceptionnelle; elle apporte une rapidité maximale aux algorithmes concernés mais c'est un prix lourd à payer pour les gens qui se chargeront de la maintenance du programme (les sources ne sont plus au même endroit, il y a une étape de compilation indépendante, la masse de code devient bien plus importante, et les fuites mémoires sont difficiles à tracer).
Il faut avant tout apprendre à mieux coder en Python pour bénéficier de gains de performances déjà très honorables !
Windows power
Ce qui est génial avec ce truc, c'est quand je veux profiler un script qui s'execute en 6secondes il met plus d'une minute. Ce qui est encore mieux, c'est qu'il me dit dans le graph que mon script met des minutes à s'exécuter. Et le point bonus c'est l'installation sur windows, car bien sur quand ils ont fait le packaging ils se sont dis que ce serait tellement mieux de faire une entrée dans le path qui pointe vers un executable que l'on doit installer soi-même.
Bon j'imagine que doit y avoir un problème quelque part, j'arrive pas à trouver la solution, ou alors c'est une sombre merde.
Lex
Effectivement, tous les outils de profiling ralentissent l'exécution du code...
Quant à l'installation des librairies sous Windows, c'est toujours le bazar. Python simplifie souvent les choses, mais j'avoue que j'en ai un peu rien à faire si mes packages ne s'installent pas sur cette plateforme. Si quelqu'un rencontre un pb il n'a qu'à le fixer et me faire une pull request car de toute façon je ne peux pas tester le code facilement.
Et puis je doute que ça serve à quelque chose de soutenir les systèmes mourrants (et propriétaires) :p