Warum ist clock_gettime so unberechenbar?

Intro

• Abschnitt Alte Frage enthält die erste Frage (Weitere Untersuchungen und Abschluss wurden Hinzugefügt, da).

• Fahren Sie mit dem Abschnitt Weitere Untersuchungen unten für einen detaillierten Vergleich der verschiedenen timing Methoden (rdtsc, clock_gettime und QueryThreadCycleTime).

• Ich glaube, das erratische Verhalten von CGT zugeschrieben werden kann, um entweder einen buggy kernel oder ein buggy-CPU (siehe Abschnitt Abschluss).

• Den code zum testen verwendet, ist an der Unterseite dieser Frage (siehe Abschnitt Anhang).

• Entschuldigung für die Länge.

---

Alte Frage

In kurzen: ich bin mit clock_gettime zum Messen der Ausführungszeit von vielen code-Segmente. Ich bin mit sehr inkonsistenten Messungen zwischen den einzelnen Läufen. Die Methode hat eine extrem hohe Standardabweichung im Vergleich zu anderen Methoden (siehe Erklärung unten).

Frage: gibt es einen Grund, warum clock_gettime geben würde, also inkonsistente Messungen im Vergleich zu anderen Methoden? Gibt es eine alternative Methode mit der gleichen Auflösung, die Konten für die thread-Leerlaufzeit?

Erklärung: ich bin versucht zu Profil, eine Anzahl kleiner Teile von C-code. Die Ausführungszeit der einzelnen code-Segmente ist nicht mehr als ein paar Mikrosekunden. In einem einzigen Durchlauf jeweils die code-Segmente ausgeführt wird, einige Hunderte Male, die produziert runs × hundreds Messungen.

Muss ich auch noch Messen nur die Zeit, die der thread eigentlich verbringt ausführen (das ist, warum rdtsc ist nicht geeignet). Ich brauche auch eine hohe Auflösung (die ist, warum times ist nicht geeignet).

Ich habe versucht, die folgenden Methoden:

• rdtsc (Linux und Windows),

• clock_gettime (mit 'CLOCK_THREAD_CPUTIME_ID'; auf Linux), und

• QueryThreadCycleTime (auf Windows).

Methodik: Die Analyse erfolgte auf der 25 läuft. In jedem Lauf, separate code-Segmente wiederholen 101 mal. Also ich habe 2525 Messungen. Dann schaue ich auf ein Histogramm, das Messungen und kalkulieren Sie auch einige grundlegende Sachen (wie Mittelwert, std.dev., median, Modus, min und max).

Ich nicht, wie ich gemessen die 'ähnlichkeit' der drei Methoden, aber diese einfach involviert einen grundsätzlichen Vergleich der Anteil der Verweilzeit in den einzelnen code-segment ('Anteil' bedeutet, dass sich die Zeiten wieder normalisiert). Ich habe dann Blick auf die reinen Unterschiede in diesen Proportionen. Dieser Vergleich zeigte, dass alle 'rdtsc', 'QTCT' und 'CGT' Messen Sie die gleichen Proportionen, wenn gemittelt über die 25 läuft. Aber die Ergebnisse unten zeigen, dass 'CGT' hat eine sehr große Standardabweichung. Dies macht es unbrauchbar in meinem Fall verwenden.

Ergebnisse:

Einen Vergleich der clock_gettime mit rdtsc für die gleichen code-segment (25 runs 101 Messungen = 2525 Lesungen):

• clock_gettime:

  • 1881-Messungen von 11 ns,
  • 595 Messungen wurden (distributed fast normal) zwischen 3369 und 3414 ns,
  • 2 Messungen von 11680 ns,
  • 1 Messung von 1506022 ns, und

  • der rest ist zwischen 900 und 5000 ns.

  • Min: 11 ns

  • Max: 1506022 ns
  • Bedeuten: 1471.862 ns
  • Median: 11 ns
  • - Modus: 11 ns
  • Stddev: 29991.034

• rdtsc (Hinweis: keine context-switches aufgetreten, die während dieser Ausführung, aber wenn es passiert, es führt in der Regel nur eine einzige Messung mit 30000 ticks oder so):

  • 1178 Messungen zwischen 274 und 325 Zecken,
  • 306 Messungen zwischen 326 und 375 Zecken,
  • 910 Messungen zwischen 376 und 425 Zecken,
  • 129 Messungen zwischen 426 und 990 ticks,
  • 1 Messung von 1240 Zecken, und

  • 1 Messung von 1256 Zecken.

  • Min: 274 Zecken

  • Max: 1256 Zecken
  • Bedeuten: 355.806 Zecken
  • Median: 333 Zecken
  • - Modus: 376 ticks
  • Stddev: 83.896

Diskussion:

• rdtsc gibt sehr ähnliche Ergebnisse sowohl auf Linux und Windows. Es hat eine akzeptable Standardabweichung--es ist eigentlich ziemlich konstant/stabil. Es wird jedoch nicht berücksichtigt thread idle-Zeit. Daher, context-switches machen die Messungen unregelmäßig (unter Windows habe ich beobachtet, dass dies sehr oft: eine code-segment mit einem Durchschnitt von 1000 ticks oder so nehmen ~30000 ticks, die jeder jetzt und dann--definitiv, weil der pre-emption).

• QueryThreadCycleTime gibt sehr konsistente Messungen-d.h. viel geringere Standardabweichung als im Vergleich zu rdtsc. Wenn kein Kontext-switches passieren, diese Methode ist fast identisch mit rdtsc.

• clock_gettime, auf der anderen Seite, ist die Herstellung extrem inkonsistente Ergebnisse (nicht nur zwischen den Läufen, aber auch zwischen den Messungen). Die Standardabweichungen sind extrem (im Vergleich zu rdtsc).

Ich hoffe, dass die Statistik in Ordnung sind. Aber was könnte der Grund für diese Diskrepanz in den Messungen zwischen den beiden Methoden? Natürlich gibt es caching, CPU/core migration, und andere Dinge. Aber keines dieser sollte dafür verantwortlich sein, solche Unterschiede zwischen 'rdtsc' und 'clock_gettime'. Was ist Los?

---

Weitere Untersuchungen

Habe ich untersucht, das ein bisschen weiter. Ich habe zwei Dinge getan:

1. Gemessen den Aufwand nur zum telefonieren clock_gettime(CLOCK_THREAD_CPUTIME_ID, &t) (siehe code 1 in Anhang), und

2. in einer einfachen Schleife genannt clock_gettime und gespeichert werden die Messwerte in ein array (siehe code 2 in Anhang). Ich Maß die delta mal (Unterschied in aufeinander folgenden messzeitpunkten, entsprechen sollte etwas auf den overhead des Aufrufs von clock_gettime).

Gemessen habe ich es auf zwei verschiedenen Rechnern mit zwei verschiedenen Linux-Kernel-Versionen:

CGT:

1. CPU: Core 2 Duo L9400 @ 1,86 GHz

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

   Ergebnisse:

   • Geschätzt clock_gettime overhead: zwischen 690-710 ns

   • Delta mal:

     • Durchschnitt: 815.22 ns
     • Median: 713 ns
     • - Modus: 709 ns
     • Min: 698 ns
     • Max: 23359 ns

     • Histogramm (Links-out-Bereiche haben Frequenzen von 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
       

2. CPU: 4 × - Dual-Core-AMD-Opteron-Prozessor 275

   Kernel: Linux 2.6.26-2-amd64 #1 SMP Sun Jun 20 20:16:30 UTC 2010 x86_64 GNU/Linux

   Ergebnisse:

   • Geschätzt clock_gettime overhead: zwischen 279-283 ns

   • Delta mal:

     • Durchschnitt: 320.00
     • Median: 1
     • - Modus: 1
     • Min: 1
     • Max: 3495529

     • Histogramm (Links-out-Bereiche haben Frequenzen von 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:

Zugehörigen code rdtsc_delta.c und rdtsc_overhead.c.

1. CPU: Core 2 Duo L9400 @ 1,86 GHz

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

   Ergebnisse:

   • Geschätzte Aufwand: zwischen 39-42 Zecken

   • Delta mal:

     • Durchschnitt: 52.46 Zecken
     • Median: 42 ticks
     • - Modus: 42 ticks
     • Min: 35 Zecken
     • Max: 28700 Zecken

     • Histogramm (Links-out-Bereiche haben Frequenzen von 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
       

2. CPU: 4 × - Dual-Core-AMD-Opteron-Prozessor 275

   Kernel: Linux 2.6.26-2-amd64 #1 SMP Sun Jun 20 20:16:30 UTC 2010 x86_64 GNU/Linux

   Ergebnisse:

   • Geschätzte Aufwand: zwischen 13.7-17.0 Zecken

   • Delta mal:

     • Durchschnitt: 35.44 Zecken
     • Median: 16 Zecken
     • - Modus: 16 Zecken
     • Min: 14 Zecken
     • Max: 16372 Zecken

     • Histogramm (Links-out-Bereiche haben Frequenzen von 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:

Zugehörigen code qtct_delta.c und qtct_overhead.c.

1. CPU: Core 2 6700 @ 2,66 GHz

   Kernel: Windows 7 64-bit

   Ergebnisse:

   • Geschätzte Aufwand: zwischen 890-940 Zecken

   • Delta mal:

     • Durchschnitt: 1057.30 Zecken
     • Median: 890 Zecken
     • - Modus: 890 Zecken
     • Min: 880 Zecken
     • Max: 29400 Zecken

     • Histogramm (Links-out-Bereiche haben Frequenzen von 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
       

---

Abschluss

Ich glaube, die Antwort auf meine Frage wäre ein buggy-Implementierung auf meinem Rechner (mit AMD-CPUs mit einer alten Linux-kernel).

Die CGT Ergebnisse der AMD-Maschine mit dem alten kernel zeigen einige extreme Lesungen. Wenn wir uns an das delta mal, wir werden sehen, dass die am häufigsten ist delta 1 ns. Dies bedeutet, dass der Aufruf zu clock_gettime dauerte weniger als eine Nanosekunde! Außerdem, es produziert auch eine Reihe von außerordentlich großen deltas (von mehr als 3000000 ns)! Dies scheint zu sein fehlerhaftes Verhalten. (Vielleicht vermisst core-Migrationen?)

Bemerkungen:

• Den Aufwand der CGT und QTCT ist ziemlich groß.

• Schwierig ist es auch, zu berücksichtigen, für Ihren Aufwand, da die CPU-caching zu machen scheint schon ein großer Unterschied.

• Vielleicht kleben RDTSC, schließ den Prozess an einen Kern, und die Zuweisung Echtzeit-Priorität ist der Genaueste Weg, zu sagen, wie viele Zyklen ein Stück code verwendet...

---

Anhang

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;
}