Pourquoi est-clock_gettime si imprévisible?

Intro

Section Vieille Question contient la question initiale (complément d'Enquête et Conclusion ont été ajoutés depuis).
Passez à la section complément d'Enquête ci-dessous pour une comparaison détaillée des différentes calendrier des méthodes (rdtsc, clock_gettime et QueryThreadCycleTime).
Je crois que le comportement erratique de la CGT peut être attribuée soit à un buggy noyau ou un buggy CPU (voir la section Conclusion).
Le code utilisé pour les essais est au bas de cette question (voir la section Annexe).
Mes excuses pour la longueur.

Vieille Question

En bref: je suis en utilisant clock_gettime pour mesurer le temps d'exécution de nombreux segments de code. Je suis en train de vivre très inégale des mesures entre les pistes séparées. La méthode a une valeur très élevée de l'écart type par rapport à d'autres méthodes (voir l'Explication ci-dessous).

Question: Est-il une raison pourquoi clock_gettime donnerait donc incompatible mesures par rapport aux autres méthodes? Est-il une autre méthode avec la même résolution que les comptes pour le fil du temps d'inactivité?

Explication: je suis en train de profil d'un certain nombre de petites parties de code C. Le temps d'exécution de chacun des segments de code n'est pas plus de quelques microsecondes. En un seul passage, chacun des segments de code exécutera quelques centaines de fois, ce qui produit des runs × hundreds de mesures.

J'ai aussi à mesurer que le temps le fil passe réellement en cours d'exécution (qui est pourquoi rdtsc n'est pas adapté). J'ai aussi besoin d'une haute résolution (qui est pourquoi times n'est pas adapté).

J'ai essayé les méthodes suivantes:

rdtsc (sur Linux et Windows),
clock_gettime (avec 'CLOCK_THREAD_CPUTIME_ID'; sur Linux), et
QueryThreadCycleTime (sur Windows).

Méthodologie: L'analyse a été réalisée sur 25 courses. Dans chaque course, séparer les segments de code à répéter une 101 fois. Donc j'ai 2525 mesures. Puis je regarde l'histogramme des mesures, et également calculer des trucs de base (comme la moyenne, la std.dev., la médiane, le mode, min et max).

Je ne présente pas la façon dont j'ai mesuré la "similarité" des trois méthodes, mais cela signifie simplement une base de comparaison de la proportion de temps passé dans chaque segment de code ('proportion' signifie que les temps sont normalisées). Je regarde ensuite la pure différences dans ces proportions. Cette comparaison a montré que tous les "rdtsc', 'QTCT", et " CGT " mesure les mêmes proportions lorsque la moyenne sur les 25 pistes. Cependant, les résultats ci-dessous montrent que la " CGT " a un très grand écart type. Cela le rend inutilisable dans mon cas d'utilisation.

Résultats:

Une comparaison de clock_gettime avec rdtsc pour le même segment de code (25 pistes de 101 mesures = 2525 lectures):

clock_gettime:
- 1881 mesures de 11 n.-é.,
- 595 mesures ont été répartis presque normalement) entre 3369 et 3414 ns,
- 2 mesures de 11680 ns,
- 1 mesure de 1506022 ns, et
- le reste est entre 900 et 5 000 ns.
- Min: 11 ns
- Max: 1506022 ns
- Dire: 1471.862 ns
- Médiane: 11 ns
- Mode: 11 ns
- Stddev: 29991.034
rdtsc (note: pas de changements de contexte s'est produite au cours de cette course, mais si cela arrive, il résulte généralement en une seule mesure de 30000 tiques ou presque):
- 1178 mesures entre 274 et 325 tiques,
- 306 mesures entre 326 et 375 tiques,
- 910 mesures entre 376 et 425 tiques,
- 129 mesures entre 426 et 990 tiques,
- 1 mesure de 1240 tiques, et
- 1 mesure de 1256 tiques.
- Min: 274 tiques
- Max: 1256 tiques
- Dire: 355.806 tiques
- Médiane: 333 tiques
- Mode: 376 tiques
- Stddev: 83.896

Discussion:

rdtsc donne des résultats très similaires sur Linux et Windows. Il est acceptable, écart-type--il est tout à fait cohérent/stable. Cependant, elle ne compte pas le fil du temps d'inactivité. Par conséquent, les changements de contexte à prendre les mesures erratiques (sur Windows, j'ai observé cette très souvent: un segment de code avec une moyenne de 1000 tiques ou prendre ~30000 tiques chaque maintenant et puis--certainement à cause de préemption).
QueryThreadCycleTime donne très cohérent de mesures--c'est à dire beaucoup plus faible écart-type lorsque comparé à rdtsc. Lorsque aucun des changements de contexte arriver, cette méthode est presque identique à rdtsc.
clock_gettime, d'autre part, est de produire des résultats très contradictoires (et pas seulement entre les courses, mais aussi entre les mesures). Les écarts-types sont extrêmes (comparativement à d' rdtsc).

J'espère que les statistiques sont d'accord. Mais ce qui pourrait être la raison d'une telle différence dans les mesures entre les deux méthodes? Bien sûr, il y a la mise en cache, le PROCESSEUR/de migration de base, et d'autres choses. Mais rien de tout cela devrait être responsable de ces différences entre les "rdtsc" et "clock_gettime'. Ce qui se passe?

Complément D'Enquête

J'ai étudié un peu plus loin. J'ai fait deux choses:

Mesuré la surcharge de simplement appeler clock_gettime(CLOCK_THREAD_CPUTIME_ID, &t) (voir code 1 en Annexe), et
dans une simple boucle dite clock_gettime et stockés les lectures dans un tableau (voir code 2 en Annexe). Je mesure la temps delta (différence successives dans le temps de mesure, ce qui devrait correspondre un peu à la surcharge de l'appel de clock_gettime).

J'ai mesuré sur deux ordinateurs différents avec deux différentes versions du Noyau Linux:

CGT:

CPU: Core 2 Duo L9400 @ 1.86 GHz

Noyau: Linux 2.6.40-4.fc15.i686 #1 SMP Fri Jul 29 18:54:39 UTC 2011 i686 i686 i386

Résultats:

Estimé clock_gettime généraux: entre 690-710 ns

Temps Delta:

Moyenne: 815.22 ns
Médiane: 713 ns
Mode: 709 ns
Min: 698 ns
Max: 23359 ns

Histogramme (gauche-out gammes de fréquences de 0):

      Range       |  Frequency
------------------+-----------
  697 < x ≤ 800   ->     78111  <-- cached?
  800 < x ≤ 1000  ->     16412
 1000 < x ≤ 1500  ->         3
 1500 < x ≤ 2000  ->      4836  <-- uncached?
 2000 < x ≤ 3000  ->       305
 3000 < x ≤ 5000  ->       161
 5000 < x ≤ 10000 ->       105
10000 < x ≤ 15000 ->        53
15000 < x ≤ 20000 ->         8
20000 < x         ->         5

CPU: 4 × Dual Core Processeur AMD Opteron 275

Noyau: Linux 2.6.26-2-amd64 #1 SMP Soleil Juin 20 20:16:30 UTC 2010 x86_64 GNU/Linux

Résultats:

Estimé clock_gettime généraux: entre 279-283 ns

Temps Delta:

Moyenne: 320.00
Médiane: 1
Mode: 1
Min: 1
Max: 3495529

Histogramme (gauche-out gammes de fréquences de 0):

      Range         |  Frequency
--------------------+-----------
          x ≤ 1     ->     86738  <-- cached?
    282 < x ≤ 300   ->     13118  <-- uncached?
    300 < x ≤ 440   ->        78
   2000 < x ≤ 5000  ->        52
   5000 < x ≤ 30000 ->         5
3000000 < x         ->         8

RDTSC:

Code relatives à l' rdtsc_delta.c et rdtsc_overhead.c.

CPU: Core 2 Duo L9400 @ 1.86 GHz

Noyau: Linux 2.6.40-4.fc15.i686 #1 SMP Fri Jul 29 18:54:39 UTC 2011 i686 i686 i386

Résultats:

Généraux estimés: entre 39-42 tiques

Temps Delta:

Moyenne: 52.46 tiques
Médiane: 42 tiques
Mode: 42 tiques
Min: 35 tiques
Max: 28700 tiques

Histogramme (gauche-out gammes de fréquences de 0):

      Range       |  Frequency
------------------+-----------
   34 < x ≤ 35    ->     16240  <-- cached?
   41 < x ≤ 42    ->     63585  <-- uncached? (small difference)
   48 < x ≤ 49    ->     19779  <-- uncached?
   49 < x ≤ 120   ->       195
 3125 < x ≤ 5000  ->       144
 5000 < x ≤ 10000 ->        45
10000 < x ≤ 20000 ->         9
20000 < x         ->         2

CPU: 4 × Dual Core Processeur AMD Opteron 275

Noyau: Linux 2.6.26-2-amd64 #1 SMP Soleil Juin 20 20:16:30 UTC 2010 x86_64 GNU/Linux

Résultats:

Généraux estimés: entre 13.7-17.0 tiques

Temps Delta:

Moyenne: 35.44 tiques
Médiane: 16 tiques
Mode: 16 tiques
Min: 14 tiques
Max: 16372 tiques

Histogramme (gauche-out gammes de fréquences de 0):

      Range       |  Frequency
------------------+-----------
   13 < x ≤ 14    ->       192
   14 < x ≤ 21    ->     78172  <-- cached?
   21 < x ≤ 50    ->     10818
   50 < x ≤ 103   ->     10624  <-- uncached?
 5825 < x ≤ 6500  ->        88
 6500 < x ≤ 8000  ->        88
 8000 < x ≤ 10000 ->        11
10000 < x ≤ 15000 ->         4
15000 < x ≤ 16372 ->         2

QTCT:

Code relatives à l' qtct_delta.c et qtct_overhead.c.

CPU: Core 2 6700 @ 2.66 GHz

Noyau: Windows 7 64-bit

Résultats:

Généraux estimés: entre 890-940 tiques

Temps Delta:

Moyenne: 1057.30 tiques
Médiane: 890 tiques
Mode: 890 tiques
Min: 880 tiques
Max: 29400 tiques

Histogramme (gauche-out gammes de fréquences de 0):

      Range       |  Frequency
------------------+-----------
  879 < x ≤ 890   ->     71347  <-- cached?
  895 < x ≤ 1469  ->       844
 1469 < x ≤ 1600  ->     27613  <-- uncached?
 1600 < x ≤ 2000  ->        55
 2000 < x ≤ 4000  ->        86
 4000 < x ≤ 8000  ->        43
 8000 < x ≤ 16000 ->        10
16000 < x         ->         1

Conclusion

Je pense que la réponse à ma question serait un buggy mise en œuvre sur ma machine (celle avec les Processeurs AMD avec un vieux noyau Linux).

La CGT résultats de l'AMD machine avec l'ancien noyau montrer certains de l'extrême lectures. Si l'on regarde le temps delta, nous allons voir que les plus fréquentes delta est de 1 ns. Cela signifie que l'appel à clock_gettime a pris moins d'une nanoseconde! En outre, il a également produit un nombre extraordinaire de grands deltas (de plus de 3000000 ns)! Cela semble être erronée du comportement. (Peut-être d'inventaire de base des migrations?)

Remarques:

Les frais généraux de la CGT et de la QTCT est assez grand.
Il est également difficile de tenir compte de leurs frais généraux, car la mise en cache du PROCESSEUR semble faire tout à fait une grande différence.
Peut-être coller à RDTSC, le verrouillage du processus à un noyau, et en attribuant la priorité en temps réel est le moyen le plus précis de dire combien de cycles d'un morceau de code utilisé...

Annexe

Code 1: clock_gettime_overhead.c

#include <time.h>
#include <stdio.h>
#include <stdint.h>

/* Compiled & executed with:

    gcc clock_gettime_overhead.c -O0 -lrt -o clock_gettime_overhead
    ./clock_gettime_overhead 100000
*/

int main(int argc, char **args) {
    struct timespec tstart, tend, dummy;
    int n, N;
    N = atoi(args[1]);
    clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tstart);
    for (n = 0; n < N; ++n) {
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
    }
    clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tend);
    printf("Estimated overhead: %lld ns\n",
            ((int64_t) tend.tv_sec * 1000000000 + (int64_t) tend.tv_nsec
                    - ((int64_t) tstart.tv_sec * 1000000000
                            + (int64_t) tstart.tv_nsec)) /N /10);
    return 0;
}

Code 2: clock_gettime_delta.c

#include <time.h>
#include <stdio.h>
#include <stdint.h>

/* Compiled & executed with:

    gcc clock_gettime_delta.c -O0 -lrt -o clock_gettime_delta
    ./clock_gettime_delta > results
*/

#define N 100000

int main(int argc, char **args) {
    struct timespec sample, results[N];
    int n;
    for (n = 0; n < N; ++n) {
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &sample);
        results[n] = sample;
    }
    printf("%s\t%s\n", "Absolute time", "Delta");
    for (n = 1; n < N; ++n) {
        printf("%lld\t%lld\n",
               (int64_t) results[n].tv_sec * 1000000000 + 
                   (int64_t)results[n].tv_nsec,
               (int64_t) results[n].tv_sec * 1000000000 + 
                   (int64_t) results[n].tv_nsec - 
                   ((int64_t) results[n-1].tv_sec * 1000000000 + 
                        (int64_t)results[n-1].tv_nsec));
    }
    return 0;
}

Code 3: rdtsc.h

static uint64_t rdtsc() {
#if defined(__GNUC__)
#   if defined(__i386__)
    uint64_t x;
    __asm__ volatile (".byte 0x0f, 0x31" : "=A" (x));
    return x;
#   elif defined(__x86_64__)
    uint32_t hi, lo;
    __asm__ __volatile__ ("rdtsc" : "=a"(lo), "=d"(hi));
    return ((uint64_t)lo) | ((uint64_t)hi << 32);
#   else
#       error Unsupported architecture.
#   endif
#elif defined(_MSC_VER)
    return __rdtsc();
#else
#   error Other compilers not supported...
#endif
}

Code 4: rdtsc_delta.c

#include <stdio.h>
#include <stdint.h>
#include "rdtsc.h"

/* Compiled & executed with:

    gcc rdtsc_delta.c -O0 -o rdtsc_delta
    ./rdtsc_delta > rdtsc_delta_results

Windows:

    cl -Od rdtsc_delta.c
    rdtsc_delta.exe > windows_rdtsc_delta_results
*/

#define N 100000

int main(int argc, char **args) {
    uint64_t results[N];
    int n;
    for (n = 0; n < N; ++n) {
        results[n] = rdtsc();
    }
    printf("%s\t%s\n", "Absolute time", "Delta");
    for (n = 1; n < N; ++n) {
        printf("%lld\t%lld\n", results[n], results[n] - results[n-1]);
    }
    return 0;
}

Code 5: rdtsc_overhead.c

#include <time.h>
#include <stdio.h>
#include <stdint.h>
#include "rdtsc.h"

/* Compiled & executed with:

    gcc rdtsc_overhead.c -O0 -lrt -o rdtsc_overhead
    ./rdtsc_overhead 1000000 > rdtsc_overhead_results

Windows:

    cl -Od rdtsc_overhead.c
    rdtsc_overhead.exe 1000000 > windows_rdtsc_overhead_results
*/

int main(int argc, char **args) {
    uint64_t tstart, tend, dummy;
    int n, N;
    N = atoi(args[1]);
    tstart = rdtsc();
    for (n = 0; n < N; ++n) {
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
        dummy = rdtsc();
    }
    tend = rdtsc();
    printf("%G\n", (double)(tend - tstart)/N/10);
    return 0;
}

Code 6: qtct_delta.c

#include <stdio.h>
#include <stdint.h>
#include <Windows.h>

/* Compiled & executed with:

    cl -Od qtct_delta.c
    qtct_delta.exe > windows_qtct_delta_results
*/

#define N 100000

int main(int argc, char **args) {
    uint64_t ticks, results[N];
    int n;
    for (n = 0; n < N; ++n) {
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        results[n] = ticks;
    }
    printf("%s\t%s\n", "Absolute time", "Delta");
    for (n = 1; n < N; ++n) {
        printf("%lld\t%lld\n", results[n], results[n] - results[n-1]);
    }
    return 0;
}

Code 7: qtct_overhead.c

#include <stdio.h>
#include <stdint.h>
#include <Windows.h>

/* Compiled & executed with:

    cl -Od qtct_overhead.c
    qtct_overhead.exe 1000000
*/

int main(int argc, char **args) {
    uint64_t tstart, tend, ticks;
    int n, N;
    N = atoi(args[1]);
    QueryThreadCycleTime(GetCurrentThread(), &tstart);
    for (n = 0; n < N; ++n) {
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
        QueryThreadCycleTime(GetCurrentThread(), &ticks);
    }
    QueryThreadCycleTime(GetCurrentThread(), &tend);
    printf("%G\n", (double)(tend - tstart)/N/10);
    return 0;
}

clock_gettime mesures en quelques secondes et nanosecondes, pas dans "tiques". Il fonctionne très cohérente pour moi. Êtes-vous sûr d'interpréter les domaines de la struct timespec correctement? Pouvez-vous montrer le code qui est-il?
Je tronquer (int64_t)ts.tv_sec * 1000000000 + (int64_t)ts.tv_nsec à int32_t et de la transmettre à un code qui fait la différence. Ce dernier prend les débordements en compte. Le même code est utilisé pour rdtsc et QueryThreadCycleTime et beaucoup d'autres méthodes sur différentes architectures-tous sont très bien testé. Je vais vous demander de supposer que ce dernier code est peu susceptible de contenir de l'erreur. Vous avez dit qu'il travaille pour vous. Comment et sur quoi avez-vous testé? Long de l'exécution de code? Je suis de mesure très courts segments.
Peut-être une meilleure version de la question: Pourquoi une telle différence entre clock_gettime et rdtsc?
Je l'ai utilisé pour à la fois longs et courts fragments. Actuellement, j'ai un cas de test où je viens de l'appeler clock_gettime deux fois sans aucun code entre les deux. Je reçois environ 1500 à 2000 ns différence sur un seul PROCESSEUR dual-core, et environ 700 à 1000 ns sur une machine plus puissante avec 2 dual-core xeons, très régulièrement. Plus intéressant est ce qui se passe avec certains calculs et sleep() jeté dans. Avec les noyaux 2.6 le temps indiqué n'inclut pas de sleep() de temps, et avec 2.4 il n'. Mais en tout cas je ne suis pas sauvage incohérences.
Hm, peut-être en 2.4 présente les choses mesures de la paroi du temps au lieu de temps CPU, ou peut-être les grains sont compilés avec différentes options CCF. Je ne suis pas sûr de l'endroit où continuer à partir d'ici.
Je suis désolé, mais je ne pouvais pas trouver toutes les réponses. Les épreuves de plus je cours, plus cela devient: je ne peux pas l'utiliser car il est, je dois en tenir à RDTSC. Aussi, j'ai oublié de mentionner que j'exécute profil et le même code sur de nombreux autres systèmes d'exploitation et de très étranges architectures (évidemment avec les différents mécanismes de synchronisation). La CGT simplement exécute bien pire par rapport au reste. Je suis en utilisant le noyau Linux 2.6.26, je vais essayer de le tester sur d'autres versions/machines, mais pour l'instant j'ai du abandonner. Merci pour votre aide!

InformationsquelleAutor sinharaj | 2011-07-25

5

Bien que CLOCK_THREAD_CPUTIME_ID est mis en œuvre à l'aide de rdtsc il sera susceptible de souffrir de problèmes comme ça. La page de manuel de clock_gettime dit:

La CLOCK_PROCESS_CPUTIME_ID et CLOCK_THREAD_CPUTIME_ID horloges
sont réalisés sur de nombreuses plates-formes à l'aide d'horaire à partir de la Cpu (TSC sur
i386, AR.L'ITC sur les systèmes Itanium). Ces registres peuvent différer entre les Cpu et de la
en conséquence ces horloges peuvent retourner de faux résultats si un
processus de migration vers un autre PROCESSEUR.

Qui sonne comme il pourrait expliquer vos problèmes? Peut-être que vous devriez verrouiller votre processus à un seul PROCESSEUR pour obtenir des résultats stables?
- Il n'est pas clair ce que signifient ces allégations. CLOCK_PROCESS_CPUTIME_ID est un par processus horloge. Il commence à 0 lorsque le processus démarre, s'arrête lorsqu'il n'est pas actif, et redémarre quand il reprend l'exécution. Comment migrer vers un autre CPU pourrait éventuellement affecter cette?
- Si les deux utilisent la même méthode, pourquoi une telle différence?
- Même si CLOCK_PROCESS_CPUTIME_ID est par processus, un processus (ou thread) peuvent migrer d'un PROCESSEUR à l'autre. Depuis rtdsc (environ) mesure le nombre de cycles d'horloge depuis un processeur était commencé, et depuis pas tous les processeurs sont lancés dans le même temps, au cours de bootstrap, il s'ensuit que le temps apparaissent discontinue si votre processus est déplacé vers un autre CPU par le noyau dans entre les appels à rtdsc.
- Des Processeurs récents ont constant_tsc ensemble. Que signifie "Constante TSC comportement garantit que la durée de chaque tic d'horloge est uniforme et prend en charge l'utilisation de la TSC comme une horloge murale minuteur même si le processeur core changements de fréquence. C'est l'architecture comportement aller de l'avant." et RDTSCP peut être utilisée pour voir si une migration de base qui s'est passé. Voir: download.intel.com/design/processor/manuals/253668.pdf
InformationsquelleAutor TomH
0

Quand vous avez une très inégale répartition qui ne peuvent pas aller négatif, vous allez voir de grandes différences entre la moyenne, la médiane et le mode.
L'écart type est assez vide de sens pour ce type de distribution.

Il est généralement une bonne idée d'ouvrir le transformer.
Qui va le rendre "plus normal".
- Le problème est que nous pour un très biaisée de la distribution. Simplement en regardant les ad-hoc 'histogramme' devrait être suffisant. J'ai inclus le reste, juste au cas où. Je l'avoue, je devrais avoir utilisé l'expression "être très irrégulière", plutôt que " d'avoir élevé les mst.dev.'.
- Quand il est fortement biaisée, l'histogramme vous dit qu'il est fortement biaisée, mais pas beaucoup d'autre. Je suggère que pour chaque fois que vous collectez, vous prenez son logarithme. Puis histogramme et de prendre les statistiques de ce. Il sera beaucoup plus instructif.
- J'ai calculé log(x) séparée pour chaque mesure et le tracé de façons diverses, mais en vain. En résumé, les mesures sont tout simplement trop incohérent pour mon cas d'utilisation. Je dois en tenir à RDTSC. Je suis d'abandonner. Merci en tout cas!
InformationsquelleAutor Mike Dunlavey

Vous devez vous connecter pour publier un commentaire.