<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE entry [
  <!ENTITY echoping '<link url="http://echoping.sourceforge.net/">echoping</link>'>
  <!ENTITY thttpd '<wikipedia xml:lang="en">thttpd</wikipedia>'>
  <!ENTITY apache '<wikipedia name="Apache HTTP Server">Apache</wikipedia>'>
]>
<entry title="Mesurer le temps d'exécution d'un programme">
<date>2006-09-18</date>
<update_date>2006-11-05</update_date>
<content>
<p>On lit très souvent des discussions sur l'optimisation d'un
programme informatique, discussions pleines d'argument du genre "X est
plus rapide que Y" où X et Y sont des <wikipedia>algorithmes</wikipedia>, des
<wikipedia name="Système de gestion de base de données">SGBD</wikipedia>, des
<wikipedia>langages de programmation</wikipedia>... Très souvent, les asséneurs de ces
arguments n'ont aucun fait sur lequel appuyer leurs affirmations, car
ils n'ont jamais <emphasis>mesuré</emphasis>.</p>
<p><foreign>Premature optimisation is the root of all evil</foreign> a
affirmé le célèbre <wikipedia name="Charles Antony Richard Hoare">C.A.R. Hoare</wikipedia>. Il voulait insister sur l'importance
qu'il y a un faire un programme correct, avant de faire un programme
rapide. Mais on peut aussi appliquer son dicton à l'importance qu'il y
a à <emphasis>tester</emphasis> les techniques pour voir laquelle est
réellement plus rapide (ou moins gourmande en espace ou autres
ressources).</p>
<p>Sur un système <wikipedia>Unix</wikipedia>, la manière la plus
évidente de tester est d'utiliser la commande
<computer><unix>time</unix></computer>, ici pour tester un programme <wikipedia name="Perl (langage)">Perl</wikipedia> :
<code>
% time perl parse-with-regexp.pl `cat ./test-file`
...
... 0.07s user 0.03s system 24% cpu 0.421 total
</code>
On voit que le programme a mis 0,421 secondes à s'exécuter, mais que
seul un quart de ce temps à été consacré à du travail du
<wikipedia name="Processeur">CPU</wikipedia>. Soit le programme faisait beaucoup
d'<wikipedia name="Entrées-sorties">entrées/sorties</wikipedia>, soit d'autres programmes
s'exécutaient au même moment sur la machine.</p>
<p>Un autre bon exemple d'utilisation de <unix>time</unix> est
présenté par Denis
Barbier qui montre que, certes, <wikipedia>grep</wikipedia>
fonctionne partiellement en <wikipedia>UTF-8</wikipedia> (un problème
que j'ai pour <link local="pas-encore-utf8">passer à UTF-8</link>)
mais qu'il est <link
url="http://lists.debian.org/debian-devel-french/2005/09/msg00029.html">beaucoup plus lent avec cet encodage</link>.</p>
<p>La principale limite de <computer>time</computer> est qu'elle prend
en compte l'initialisation du programme (pour <wikipedia name="Perl (langage)">Perl</wikipedia>, c'est le chargement du
<wikipedia>compilateur</wikipedia> et de la <wikipedia>machine virtuelle</wikipedia>, puis la compilation du code, avant même que son
exécution ne commence). Si je testais une base de données,
<computer>time</computer> prendrait en compte le temps de connexion en
plus du temps d'exécution de la requête. Si je testais une opération
réseau, par exemple avec <wikipedia>wget</wikipedia>,
<computer>time</computer> prendrait en compte le temps de résolution
<wikipedia name="Domain Name System">DNS</wikipedia>, ce dont je n'ai pas forcément envie.</p>
<p>Il est donc généralement préférable de ne déclencher le chronomètre
qu'après que l'initialisation aie été faite. C'est ce que fait
&echoping;, qui
ne lance ledit chronomètre (en appelant
<computer><unix>gettimeofday</unix></computer>) qu'après que la
résolution de noms en adresse aie été faite (par <computer><unix
section="3">getaddrinfo</unix></computer>) et juste avant de tenter
une connexion (par <computer><unix>connect</unix></computer>).</p>
<p>Bien sûr, la mesure reste un monde compliqué et plein
d'embûches. Par exemple, il est recommandé d'exécuter  la commande
plusieurs fois, pour tenir compte du résultat des <wikipedia
name="cache">caches</wikipedia>. C'est pour cette raison que la
plupart des <foreign><wikipedia name="Test de performance">benchmarks</wikipedia></foreign> ne signifient pas grand'chose.</p>
<p>Voici un exemple de mesure de performance d'un serveur réseau. Ici,
on veut comparer deux serveurs <wikipedia name="Hypertext Transfer Protocol">HTTP</wikipedia>,
&apache; et &thttpd;. Pour
distinguer le temps de résolution de noms (qui dépend du
<wikipedia name="Domain Name System">DNS</wikipedia>) du temps de connexion
<wikipedia name="Transmission Control Protocol">TCP</wikipedia> (qui, si le serveur est une machine
<wikipedia>Unix</wikipedia>, ne dépend que du
<wikipedia name="Noyau de système d'exploitation">noyau</wikipedia>, pas du serveur), du temps total, on peut
utiliser <wikipedia name="CURL">curl</wikipedia>, qui dispose
d'options comme <computer>--write-out</computer>, qui
permettent de n'afficher que le temps considéré
comme "utile" :
<code>
% curl --silent --output /dev/null --write-out 'DNS: %{time_namelookup} s\nConnect:%{time_connect} s\nTotal: %{time_total} s\n' http://www.demaziere.fr/ 
DNS: 0.001 s
Connect:0.001 s
Total: 0.126 s
</code>
Et le même test avec &echoping; :
<code>
% echoping -v -h / www.demaziere.fr       
...
TCP Latency: 0.046543 seconds
Sent (92 bytes)...
Application Latency: 0.065827 seconds
610 bytes read from server.
Elapsed time: 0.118573 seconds
</code>
On voit ici que l'essentiel du temps est bien dû au serveur. &echoping;, lui, dispose
de davantage d'options <wikipedia
name="Statistiques">statistiques</wikipedia>, par exemple
<computer>-n</computer> qui permet de répéter un test pour s'assurer
de sa reproductibilité et de calculer <wikipedia>moyenne</wikipedia>
et surtout <wikipedia name="Médiane (centre)">médiane</wikipedia>, une valeur en général bien
plus utile sur Internet. Essayons pour comparer
nos serveurs HTTP :
<code>
% echoping -n 4 -h / preston.sources.org 
...
Median time: 0.007902 seconds (32397 bytes per sec.)
...
</code>
Ce premier test était fait sur un serveur
&apache;. Avec un serveur
&thttpd;, sur la même machine, on obtient :
<code>
...
Median time: 0.011717 seconds (21849 bytes per sec.)
...
</code>
Bref, thttpd n'est pas plus rapide, dans ces conditions. Bien sûr, ce
test n'épuise pas tout le problème. thttpd résiste peut-être mieux à
la charge, par exemple. Mais cela montre l'importance de mesurer les
performances, pas de simplement croire les auteurs du logiciel, qui
présentent toujours leur logiciel comme "plus meilleur".
</p>
<p>Il existe de nombreux autres outils de mesure des performances des
serveurs réseau. <!-- ab (Apache Benchmark)
http://forum.slicehost.com/comments.php?DiscussionID=1946, cf. benchmark-http -->Par exemple, pour <link
url="http://www.generic-nic.net/sheets/practical/nameserver-en">mesurer
les performances</link> d'un serveur <wikipedia name="Domain Name System">DNS</wikipedia>, on
utilise souvent le programme <link local="performances-serveur-dns">queryperf</link>, distribué avec
<wikipedia>BIND</wikipedia>. Et en local ?</p>
<p>Tous les langages de programmation offrent aujourd'hui un moyen de
mesurer le temps d'exécution. Par exemple, pour <wikipedia
name="Python (langage)">Python</wikipedia>, on a le module <computer><link url="http://docs.python.org/lib/module-timeit.html">timeit</link></computer>.</p>
<p>Voici un exemple de test de performance, entre plusieurs modules
d'accès à une base de données <wikipedia>PostgreSQL</wikipedia>. Si on
avait voulu comparer plusieurs <wikipedia name="Système de gestion de base de données">SGBD</wikipedia>, la méthode
aurait été la même. On commence par créer une base de données, à
l'aide des instructions <wikipedia name="Structured Query Language">SQL</wikipedia> suivants :
<code>
CREATE TABLE Registrars (id SERIAL UNIQUE, 
                   created TIMESTAMP NOT NULL DEFAULT now() , name TEXT UNIQUE N
OT NULL);
INSERT INTO Registrars (name) VALUES ('Indomco');
INSERT INTO Registrars (name) VALUES ('Verisign');
INSERT INTO Registrars (name) VALUES ('Gandi');

CREATE TABLE Domains (id SERIAL UNIQUE, name TEXT UNIQUE NOT NULL, 
     created TIMESTAMP NOT NULL DEFAULT now(), 
             registrar INTEGER REFERENCES Registrars(id) NOT NULL);
</code>
puis le programme Python suivant va se connecter à la base (en
utilisant tel ou tel module, selon la valeur de la variable
d'environnement PYTHON_DB) :
<code>
import timeit
import os
import sys

repetitions = 100
inserts = 1000
selects = inserts
deletes = inserts

domain_prefix = "example"

try:
    if os.environ['PYTHON_DB'] == 'psycopg':
        import psycopg
        db_module = psycopg
    elif os.environ['PYTHON_DB'] == 'pypg':
        import pypg
        db_module = pypg
    elif os.environ['PYTHON_DB'] == 'popy':
        import PoPy
        db_module = PoPy
        """ TODO: PoPy has a problem with the paramstyle pyformat. http://www.python.org/peps/pep-0249.html says:
            paramstyle

                String constant stating the type of parameter marker
                formatting expected by the interface. Possible values are
                [2]:

                    'qmark'         Question mark style, 
                                    e.g. '...WHERE name=?'
                    'numeric'       Numeric, positional style, 
                                    e.g. '...WHERE name=:1'
                    'named'         Named style, 
                                    e.g. '...WHERE name=:name'
                    'format'        ANSI C printf format codes, 
                                    e.g. '...WHERE name=%s'
                    'pyformat'      Python extended format codes, 
                                    e.g. '...WHERE name=%(name)s'

    but PoPy crashes:
        src/samples/db-comparison % python test.py
    Traceback (most recent call last):
      File "test.py", line 46, in ?
        run(connection, cursor)
      File "test.py", line 25, in run
        {'name': "%s-%i" % (domain_prefix, i), 'registrar': 'Gandi'})
    PoPy.ProgrammingError: ERROR:  column "gandi" does not exist

    """
    else:
        raise Exception("Unsupported DB module %s" %
                        os.environ['PYTHON_DB'])
except KeyError:
    sys.stderr.write("You must define the environment variable PYTHON_DB\n")
    sys.exit(1)

insertion_time = 0
selection_time = 0
deletion_time = 0

def run(operation, iterations, connection, cursor):
    if operation == "INSERT":
        cursor.execute("SELECT id FROM Registrars WHERE name='Gandi'")
        id = cursor.fetchone()[0]
        for i in range(1,iterations):
            cursor.execute("""
               INSERT INTO Domains (name, registrar) VALUES
                    ('%s', %i)""" %
                       ("%s-%i" % (domain_prefix, i), id))
        connection.commit()
    elif operation == "SELECT":
        for i in range(1,iterations):
            cursor.execute("""
               SELECT Domains.id, Domains.name, Domains.created,
                         Registrars.name AS registrar
                      FROM Domains,Registrars WHERE
                          Domains.name = '%s' AND Domains.registrar = Registrars.id""" %
                 "%s-%i" % (domain_prefix, i))
        connection.commit()
    elif operation == "DELETE":
        for i in range(1,iterations):
            cursor.execute("""
                DELETE FROM Domains WHERE name = '%s'""" %
                "%s-%i" % (domain_prefix, i))
        connection.commit()
    else:
        raise Exception("Unknown operation: %s" % operation)

def run_all(connection, cursor):
    global insertion_time, selection_time, deletion_time
    t = timeit.Timer(stmt="""
run("INSERT", inserts, connection, cursor)
""", setup="""
from __main__ import run, inserts, connection, cursor
""")
    insertion_time = insertion_time + t.timeit(number=1)
    t = timeit.Timer(stmt="""
run("SELECT", selects, connection, cursor)
""", setup="""
from __main__ import run, selects, connection, cursor
""")
    selection_time = selection_time + t.timeit(number=1)
    t = timeit.Timer(stmt="""
run("DELETE", deletes, connection, cursor)
""", setup="""
from __main__ import run, deletes, connection, cursor
""")
    deletion_time = deletion_time + t.timeit(number=1)

if os.environ['PYTHON_DB'] != 'pypg':
    # pypg does not support connection strings :-(
    connection = db_module.connect("dbname=db-comp-registry")
else: # Broken pypg
    connection = db_module.connect(host='localhost', database='db-comp-registry')
cursor = connection.cursor()
# Clean the DB
cursor.execute("DELETE FROM Domains")
connection.commit()

if __name__ == '__main__':
    print "Result with %s" % db_module
    sys.stderr.write("%i repetitions:\n" % repetitions)
    for i in range(1, repetitions+1):
        sys.stderr.write("%i... " % i)
        sys.stderr.flush()
        run_all(connection, cursor)
    sys.stderr.write("\n")
    print "INSERT: %.1f msec/pass" % (insertion_time*1000/inserts/repetitions)
    print "SELECT (with join): %.1f msec/pass" % (selection_time*1000/selects/repetitions)
    print "DELETE: %.1f msec/pass" % (deletion_time*1000/deletes/repetitions)
</code>Son exécution donne :
<code>
INSERT: 0.5 msec/pass
SELECT (with join): 4.5 msec/pass
DELETE: 3.9 msec/pass
</code> ce qui indique que le programme met une demi-milliseconde par
insertion, soit 2000 insertions par seconde. On peut refaire tourner
le programme avec d'autres modules d'accès à la base pour voir s'il ya
 des différences de performance.</p>
<p>Empruntées à Andrew Bromage, et pour compléter la citation de Hoare
ci-dessus, une belle liste de lois sur l'optimisation :
<enum>
<item><foreign>Rule 1. Don't do it.</foreign></item>
<item><foreign>Rule 2. (For experts only) Don't do it yet.</foreign></item>
<item><foreign>Rule 3. (For real experts only) When you've found a performance issue,
profile first, find where the bottlenecks are, and then optimise.  For
if you guess, you'll guess wrong.</foreign></item>
<item><foreign>Rule 4. (For serious guru experts only) Sometimes, performance matters.
When it matters, it really matters.  If you find yourself in this
situation, then the performance that you need must be designed in; it
can't be added later.  So go ahead and spend ten minutes optimising your
code on the back of an envelope before writing anything.</foreign></item>
</enum></p>
</content>
</entry>
