mp3tag - mp3 tag linux

¿Por qué clock_gettime es tan errático? (2)

Bueno, como CLOCK_THREAD_CPUTIME_ID se implementa con rdtsc , es probable que sufra los mismos problemas que él. La página del manual para clock_gettime dice:

Los relojes CLOCK_PROCESS_CPUTIME_ID y CLOCK_THREAD_CPUTIME_ID se realizan en muchas plataformas que usan temporizadores de las CPU (TSC en i386, AR.ITC en Itanium). Estos registros pueden diferir entre las CPU y, como consecuencia, estos relojes pueden devolver resultados falsos si un proceso se migra a otra CPU.

¿Qué parece que podría explicar tus problemas? ¿Tal vez deberías bloquear tu proceso en una CPU para obtener resultados estables?

Introducción

La pregunta anterior de la sección contiene la pregunta inicial (se han agregado más investigaciones y conclusiones desde).
Pase a la sección Investigación adicional a continuación para una comparación detallada de los diferentes métodos de temporización ( rdtsc , clock_gettime y QueryThreadCycleTime ).
Creo que el comportamiento errático de CGT se puede atribuir a un núcleo defectuoso o a una CPU defectuosa (consulte la sección Conclusión ).
El código utilizado para las pruebas se encuentra en la parte inferior de esta pregunta (consulte la sección Apéndice ).
Disculpas por la duración.

Vieja pregunta

En resumen : estoy usando clock_gettime para medir el tiempo de ejecución de muchos segmentos de código. Estoy experimentando mediciones muy inconsistentes entre ejecuciones separadas. El método tiene una desviación estándar extremadamente alta en comparación con otros métodos (consulte la explicación a continuación).

Pregunta : ¿Hay alguna razón por la cual clock_gettime daría mediciones tan inconsistentes en comparación con otros métodos? ¿Hay algún método alternativo con la misma resolución que tenga en cuenta el tiempo de inactividad del hilo?

Explicación : Estoy tratando de perfilar varias partes pequeñas de código C. El tiempo de ejecución de cada uno de los segmentos de código no es más que un par de microsegundos. En una sola ejecución, cada uno de los segmentos de código se ejecutará cientos de veces, lo que produce runs × hundreds de mediciones.

También tengo que medir solo el tiempo que el hilo realmente pasa ejecutando (razón por la cual rdtsc no es adecuado). También necesito una resolución alta (razón por la cual los times no son adecuados).

Probé los siguientes métodos:

rdtsc (en Linux y Windows),
clock_gettime (con ''CLOCK_THREAD_CPUTIME_ID''; en Linux), y
QueryThreadCycleTime (en Windows).

Metodología : el análisis se realizó en 25 carreras. En cada ejecución, los segmentos de código separados se repiten 101 veces. Por lo tanto, tengo 2525 mediciones. Luego miro un histograma de las medidas y también calculo algunas cosas básicas (como la media, std.dev., Mediana, modo, mín. Y máximo).

No presento cómo medí la ''similitud'' de los tres métodos, pero esto simplemente implicó una comparación básica de la proporción de veces que pasé en cada segmento de código (''proporción'' significa que los tiempos están normalizados). Luego miro las diferencias puras en estas proporciones. Esta comparación mostró que todos los ''rdtsc'', ''QTCT'' y ''CGT'' miden las mismas proporciones cuando se promedian en las 25 carreras. Sin embargo, los resultados a continuación muestran que ''CGT'' tiene una desviación estándar muy grande. Esto lo hace inutilizable en mi caso de uso.

Resultados :

Una comparación de clock_gettime con rdtsc para el mismo segmento de código (25 ejecuciones de 101 mediciones = 2525 lecturas):

clock_gettime :
- 1881 medidas de 11 ns,
- Se distribuyeron 595 mediciones (distribuidas casi con normalidad) entre 3369 y 3414 ns.
- 2 medidas de 11680 ns,
- 1 medida de 1506022 ns, y
- el resto está entre 900 y 5000 ns.
- Min: 11 ns
- Max: 1506022 ns
- Media: 1471.862 ns
- Mediana: 11 ns
- Modo: 11 ns
- Stddev: 29991.034
rdtsc (nota: no se produjeron cambios de contexto durante esta ejecución, pero si ocurre, por lo general, da como resultado una sola medida de 30000 tics o menos):
- 1178 mediciones entre 274 y 325 tics,
- 306 mediciones entre 326 y 375 tics,
- 910 mediciones entre 376 y 425 garrapatas,
- 129 mediciones entre 426 y 990 garrapatas,
- 1 medida de 1240 garrapatas, y
- 1 medida de 1256 tics.
- Min: 274 ticks
- Máx .: 1256 tics
- Media: 355.806 tics
- Mediana: 333 tics
- Modo: 376 tics
- Stddev: 83.896

Discusión :

rdtsc da resultados muy similares en Linux y Windows. Tiene una desviación estándar aceptable, en realidad es bastante consistente / estable. Sin embargo, no tiene en cuenta el tiempo de inactividad del hilo. Por lo tanto, los interruptores de contexto hacen que las mediciones sean erráticas (en Windows he observado esto bastante a menudo: un segmento de código con un promedio de 1000 tics más o menos tomará ~ 30000 tics de vez en cuando, definitivamente debido a la anticipación).
QueryThreadCycleTime proporciona mediciones muy consistentes, es decir, una desviación estándar mucho más baja en comparación con rdtsc . Cuando no se producen cambios de contexto, este método es casi idéntico a rdtsc .
clock_gettime , por otro lado, produce resultados extremadamente inconsistentes (no solo entre ejecuciones, sino también entre mediciones). Las desviaciones estándar son extremas (en comparación con rdtsc ).

Espero que las estadísticas estén bien. Pero, ¿cuál podría ser el motivo de tal discrepancia en las mediciones entre los dos métodos? Por supuesto, hay almacenamiento en caché, migración de CPU / núcleo y otras cosas. Pero nada de esto debería ser responsable de tales diferencias entre ''rdtsc'' y ''clock_gettime''. Que esta pasando?

Investigación exahustiva

He investigado esto un poco más. He hecho dos cosas:

Medido la sobrecarga de llamar a clock_gettime(CLOCK_THREAD_CPUTIME_ID, &t) (ver el código 1 en el Apéndice ), y
en un ciclo simple llamado clock_gettime y almacenó las lecturas en una matriz (ver el código 2 en el Apéndice ). Mido los tiempos delta (diferencia en los tiempos de medición sucesivos, que deberían corresponder un poco a la sobrecarga de la llamada de clock_gettime ).

Lo he medido en dos computadoras diferentes con dos versiones diferentes de Linux Kernel:

CGT :

CPU : Core 2 Duo L9400 a 1.86GHz
Kernel : Linux 2.6.40-4.fc15.i686 # 1 SMP vie 29 de jul 18:54:39 UTC 2011 i686 i686 i386
Resultados :
- clock_gettime generales estimados de clock_gettime : entre 690 y 710 ns
- Tiempos del Delta :
  - Promedio: 815.22 ns
  - Mediana: 713 ns
  - Modo: 709 ns
  - Min: 698 ns
  - Max: 23359 ns
  - Histograma (los rangos omitidos tienen frecuencias 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 : procesador de doble núcleo AMD Opteron de 4 × 275
Núcleo : Linux 2.6.26-2-amd64 # 1 SMP Dom 20 de junio 20:16:30 UTC 2010 x86_64 GNU / Linux
Resultados :
- clock_gettime generales estimados de clock_gettime : entre 279-283 ns
- Tiempos del Delta :
  - Promedio: 320.00
  - Mediana: 1
  - Modo: 1
  - Min: 1
  - Max: 3495529
  - Histograma (los rangos omitidos tienen frecuencias 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 :

Código relacionado rdtsc_delta.c y rdtsc_overhead.c .

CPU : Core 2 Duo L9400 a 1.86GHz
Kernel : Linux 2.6.40-4.fc15.i686 # 1 SMP vie 29 de jul 18:54:39 UTC 2011 i686 i686 i386
Resultados :
- Gastos generales estimados : entre 39 y 42 tics
- Tiempos del Delta :
  - Promedio: 52.46 tics
  - Mediana: 42 tics
  - Modo: 42 tics
  - Min: 35 ticks
  - Máx .: 28700 tics
  - Histograma (los rangos omitidos tienen frecuencias 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 : procesador de doble núcleo AMD Opteron de 4 × 275
Núcleo : Linux 2.6.26-2-amd64 # 1 SMP Dom 20 de junio 20:16:30 UTC 2010 x86_64 GNU / Linux
Resultados :
- Gastos generales estimados : entre 13.7 y 17.0 tics
- Tiempos del Delta :
  - Promedio: 35.44 tics
  - Mediana: 16 tics
  - Modo: 16 tics
  - Min: 14 tics
  - Máx .: 16372 tics
  - Histograma (los rangos omitidos tienen frecuencias 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 :

Código relacionado qtct_delta.c y qtct_overhead.c .

CPU : Core 2 6700 a 2.66 GHz
Kernel : Windows 7 de 64 bits
Resultados :
- Gastos generales estimados : entre 890 y 940 tics
- Tiempos del Delta :
  - Promedio: 1057.30 tics
  - Mediana: 890 tics
  - Modo: 890 tics
  - Min: 880 ticks
  - Máx .: 29400 tics
  - Histograma (los rangos omitidos tienen frecuencias 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

Conclusión

Creo que la respuesta a mi pregunta sería una implementación defectuosa en mi máquina (la que tiene CPUs AMD con un antiguo kernel de Linux).

Los resultados de la CGT de la máquina AMD con el kernel antiguo muestran algunas lecturas extremas. Si miramos los tiempos delta, veremos que el delta más frecuente es 1 ns. Esto significa que la llamada a clock_gettime tomó menos de un nanosegundo. Además, también produjo una serie de deltas grandes extraordinarios (¡de más de 3000000 ns)! Esto parece ser un comportamiento erróneo. (¿Migraciones centrales no contadas?)

Observaciones:

La sobrecarga de CGT y QTCT es bastante grande.
También es difícil tener en cuenta su sobrecarga, ya que el almacenamiento en caché de CPU parece marcar una gran diferencia.
Tal vez seguir con RDTSC, bloquear el proceso en un núcleo, y asignar prioridad en tiempo real es la forma más precisa de decir cuántos ciclos utilizó una pieza de código ...

Apéndice

Código 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; }

Código 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; }

Código 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 }

Código 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; }

Código 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; }

Código 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; }

Código 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; }

Cuando tiene una distribución muy sesgada que no puede ser negativa, verá grandes discrepancias entre la media, la mediana y el modo. La desviación estándar es bastante insignificante para dicha distribución.

Por lo general, es una buena idea realizar una transformación de registro. Eso lo hará "más normal".