Mesure de code

   Pendant le développement, il peut être utile de mesurer les performances d'un code afin
d'identifier les goulots d'étranglement qui ralentissent le programme et méritent optimisation.

   Si on a besoin de performances, comparer différentes approches sur une section donnée permet de conserver la plus rapide.

   Tout le monde s' accorde à dire qu'aucune mesure n'est absolument fiable. Elles représentent cependant un excellent indicateur.

   Les exemples de code ci-dessous sont en langage C.

I.1 Mesure de l' ordre de la seconde, en C ANSI sous Windows et *NIX


Avec time_t et difftime():
   //Source: http://www.cplusplus.com/ref/ctime/difftime.html
   #include <stdio.h>
   #include <time.h>

   int main ()
   {
     time_t start,end;
     char szInput [256];
     double dif;

     time (&start);
     printf ("Please, enter your name: ");
     gets (szInput);
     time (&end);
     dif = difftime (end,start);
     printf ("Hi %s.\n", szInput);
     printf ("You have taken %.2lf seconds to type your name.\n", dif );
 
     return 0;
   }
Avec clock_t:
  //Source: http://c.developpez.com/sources/c/?page=IIIDATE_calcul_temps_execution
  #include <stdio.h>
  #include <time.h>

  int main (void)
  {
    clock_t start, end;

    start = clock ();
    {
      /* Portion de code a chronometrer */
    }
    end = clock ();
    printf ("Temps en secondes : %f\n", (end - start) / (double)CLOCKS_PER_SEC);
    return 0;
  }
Avec time_t:
  #include <stdio.h>
  #include <time.h>

  int main()
  {
    time_t depart, fin;
    double duree;

    depart = clock();
    // code à mesurer
    fin = clock();

    duree = (double)(fin-depart)/CLOCKS_PER_SEC;

    printf("Durée: %.2lf\n", duree);
    return 0;
}

I.2 Mesure de l' ordre de la milliseconde


1 milliseconde = 10^-3 seconde.

I.2.a Sous Windows

Avec GetTickCount():
  //Source: Bert
  #include <stdio.h>
  #include <windows.h>

  int main()
  {
    long depart=0, fin=0; duree=0;

    depart = GetTickCount();
    // Code à mesurer
    fin = GetTickCount();

    duree = fin - depart;
    // En divisant par mille, obtient également le nombre de secondes
    printf("durée: %ld ms soit %ld secondes\n", duree, duree/1000);

    return 0;
  }
Avec GetLocalTime():
  //Source: Bert
  #include <stdio.h>
  #include <time.h>
  #include <windows.h>

  int main()
  {
    SYSTEMTIME st;
    GetLocalTime(&st);
    char szBuf[284];
    LPCSTR lpEvent="evenement";
    wsprintf(szBuf,"%02d:%02d:%02d.%03dms\t%s",
       st.wHour, st.wMinute, st.wSecond, st.wMilliseconds, lpEvent);
    puts(szBuf); //affiche 13:24:36.640ms evenement

    getchar();
    return 0;
  }

I.2.b Sous *NIX: getrusage()
  //source: http://souptonuts.sourceforge.net/code/getrusage.cc.html
  #include <stdio.h>
  #include <stdlib.h>
  #include <unistd.h>
  #include <sys/time.h>
  #include <sys/resource.h>

  int main(int argc, char **argv)
  {
      struct rusage buf;

      if(argc == 2) {
        system(argv[1]);
      }else {
        fprintf(stderr,"./getrusage  \"ls -l >/dev/null\"\n");
        exit(0);
      }
      int err = getrusage(RUSAGE_CHILDREN, &buf);
      //int err = getrusage(RUSAGE_SELF, &buf);
      printf("ERR=%d\n", err);
      printf("%20s:%ld/%ld\t%s\n",
  	     "ru_utime",
  	     buf.ru_utime.tv_sec,
  	     buf.ru_utime.tv_usec,
  	     "user time used (secs/usecs)");
      printf("%20s:%ld/%ld\t%s\n",
  	     "ru_stime",
	     buf.ru_stime.tv_sec,
	     buf.ru_stime.tv_usec,
	     "system time used (secs/usecs)");
      printf("%20s:%-10ld\t%s\n", 
	     "ru_maxrss",
	     buf.ru_maxrss,
	     "maximum resident set size");
      printf("%20s:%-10ld\t%s\n",
	     "ru_ixrss", 
	     buf.ru_ixrss,
	     "integral shared memory size");
      printf("%20s:%-10ld\t%s\n",
	     "ru_idrss",
	     buf.ru_idrss,
	     "integral unshared data size");
      printf("%20s:%-10ld\t%s\n", 
	     "ru_isrss",
	     buf.ru_isrss,
	     "integral unshared data stack size");
      printf("%20s:%-10ld\t%s\n", 
	     "ru_minflt",
	     buf.ru_minflt,
	     "page reclaims");
      printf("%20s:%-10ld\t%s\n",
	     "ru_majflt",
	     buf.ru_majflt,
	     "page faults");
      printf("%20s:%-10ld\t%s\n",
	     "ru_nswap",
	     buf.ru_nswap,
	     "swaps");
      printf("%20s:%-10ld\t%s\n",
	     "ru_inblock",
	     buf.ru_inblock,
	     "block input operations");
      printf("%20s:%-10ld\t%s\n",
	     "ru_oublock",
	     buf.ru_oublock,
	     "block output operations");
      printf("%20s:%-10ld\t%s\n",
	     "ru_msgsnd",
	     buf.ru_msgsnd,
	     "messages sent");
      printf("%20s:%-10ld\t%s\n",
	     "ru_msgrcv",
	     buf.ru_msgrcv,
	     "messages received");
      printf("%20s:%-10ld\t%s\n",
	     "ru_nsignals",
	     buf.ru_nsignals,
	     "signals received");
      printf("%20s:%-10ld\t%s\n",
	     "ru_nvcsw",
	     buf.ru_nvcsw,
	     "voluntary context switches");
      printf("%20s:%-10ld\t%s\n",
	     "ru_nivcsw",
	     buf.ru_nivcsw,
	     "involuntary context switches");
    exit(0);
  }


I.3 Mesure de l' ordre de la microseconde


1 microseconde = 10^-6 seconde.

I.3.a Sous Windows

Avec QueryPerformanceCounter() :
  //Source: Bert
  #include <stdio.h>
  #include <windows.h>

  int main()
  {
    LARGE_INTEGER freq, depart, fin;
    double duree=0;
    QueryPerformanceFrequency(&freq); // Obtient fréquence

    QueryPerformanceCounter(&depart);
    // Code à mesurer
    QueryPerformanceCounter(&fin);

    duree = ((fin.QuadPart-depart.QuadPart)/(double)freq.QuadPart)*1000L;
    printf("Durée: %.4lf millisecondes\n", duree);

    return 0;
  }

I.3.b Sous *NIX :

Avec gettimeofday():
  //Source: Bert
  #include <stdio.h>
  #include <sys/time.h>

  int main()
  {
    struct timeval depart, fin;
    struct timezone tz;
    long duree=0;

    gettimeofday(&depart, &tz);
    // code à mesurer
    gettimeofday(&fin, &tz);

    duree=(fin.tv_sec-depart.tv_sec) * 1000000L + (fin.tv_usec-depart.tv_usec);  
    printf("Durée: %ld microsecondes\n", duree);

    return 0;
  }

    tv_sec contient le nombre de secondes.
    tv_usec contient le nb de microsecondes de la dernière seconde.
    Par conséquent on calcule les différences de secondes et microsecondes entre fin et depart,
    multiplie le nombre de secondes par 10^6 pour obtenir des microsecondes,
    et lui ajoute les microsecondes restantes pour avoir la durée en microsecondes.

I.4 Mesure de processus très longs


UNIX et assimilés fournissent à cet effet des outils de monitoring, installés par défaut.

Les processus d'un seul utilisateur:
 $ ps -u
 USER     PID  %CPU %MEM   VSZ  RSS TTY      STAT START   TIME COMMAND
 Joe      6612  0.0  0.4  3124 1664 pts/0    Ss   13:15   0:04 bash
 Joe      6680  0.0  0.3  2672 1464 pts/0    R    13:53   5:21 bash
 Joe      6749  0.0  0.2  2564  844 pts/0    R+   14:50   0:00 ps u

    La colonne START indique l'heure de départ en h:mn.
    La colonne TIME indique la durée en h:mn -> 00:00 signifie moins d'une minute!


Pour contrôler plusieurs processus en temps réel:
 $ top

L' affichage est rafraichi fréquemment. Il est conseillé de spécifier un intervalle de rafraichissement en secondes :
 $ top -d 30

    Appuyez sur h pour help, et q pour quitter.




II Mesure du processus complet


time est une commande UNIX. Le binaire est dans /usr/bin. Son principe consiste à lancer un exécutable pour mesurer le temps pris par le processus fils.

Attention, sous Windows cette commande a un autre rôle: définir l' heure systême!

Lancer une console BASH.
Cette première commande dresse la liste des fichiers, et affiche le temps qu'il a fallu pour excécuter cette commande:

 $ time ls -la

 Total 3
 drwxr-xr-x   2 user user    4096 2006-06-06 11:09 .designer
 drwxr-xr-x   2 user user    4096 2006-07-28 15:56 Desktop
 -rw-------   1 user user      26 2006-03-03 20:28 .dmrc

 real    0m0.076s
 user    0m0.008s
 sys     0m0.008s

      (Avec le tiret pour les arguments par convention UNIX, merci David!)

Pour plus d'infos sur time:
 $ info time
 $ man time


Lancer une console NON BASH (DASH par exemple)
 $ time --help

 Usage: time [-apvV] [-f format] [-o file] [--append] [--verbose]
        [--portability] [--format=format] [--output=file] [--version]
        [--quiet] [--help] command [arg...]


Exemples
En Admettant que vous ayez un exécutable ('monexe') qui prend en argument un nom de fichier ('monarg')

1) Lancement simple
 $ time monexe monarg

 0.01user 0.00system 0:00.15elapsed 10%CPU (0avgtext+0avgdata 0maxresident)k
 0inputs+0outputs (0major+158minor)pagefaults 0swaps

2) Formate la sortie
 $ time -f "\t%E real,\t%U user,\t%S sys" monexe monarg

        0:00.13 real,   0.01 user,      0.00 sys

3) Encore plus d'arguments
 $ time -f "\t%C\n\t%t Ko Avg resident set size of the process\n\t%K Ko Avg total
       (data+stack+text)\n\t%E real mn:s:us,\n\t%U user,\n\t%S sys" monexe monarg

        monexe monarg
        0 Ko Average resident set size of the process
        0 Ko Average total (data+stack+text)
        0:00.03 real mn:s:us,
        0.01 user,
        0.00 sys

4) Mode Verbose (bavard)
 $ time -v monexe monarg

5) Stocke toute la sortie vers log.txt
 $ time -v -o log.txt monexe monarg

    log.txt contient:
	Command being timed: "monexe monarg"
	User time (seconds): 0.02
	System time (seconds): 0.00
	Percent of CPU this job got: 9%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.20
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 0
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 161
	Voluntary context switches: 1
	Involuntary context switches: 7
	Swaps: 0
	File system inputs: 0
	File system outputs: 0
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
6) Idem mais ajoute la ligne au fichier sans l' écraser (append) :
 $ time -v -a -o log.txt monexe monarg





III REFERENCES




Linux & Win32
    difftime
    clock_t
    clock()
    Optimisation_de_code
    Linux/Win32 Performance Comparison
    Haypo fréquence processeur

Linux
    Unix, C, and C++ Function Reference Time
    GNU time command
    timing_linux
    Resource Usage And Limitation
    getrusage

Win32
    Win32 Performance Measurement Options
    GetProcessTimes
    fonctionnalités d'optimisation de Visual C++
    MSDN QueryPerformanceCounter
    Support QueryPerformanceCounter
    QueryPerformanceCounter