volume: Get more data from volume tests

This makes the volume tests run in two loops and print the minimum,
maximum and standard deviation of readings from the inner loop. This
makes it easier to reason out performance drops (i.e. algorithmic
problems vs. other system issues such as processor contention).

diff --git a/src/pulsecore/svolume_arm.c b/src/pulsecore/svolume_arm.c
index 42e8cbf93849b653e2bbcf043f8f0e808787281d..098f10eef9bde155089fc02e85d5a634598761d3 100644 (file)
--- a/src/pulsecore/svolume_arm.c
+++ b/src/pulsecore/svolume_arm.c
@@ -130,6 +130,7 @@ static void pa_volume_s16ne_arm(int16_t *samples, int32_t *volumes, unsigned cha
 #define CHANNELS 2
 #define SAMPLES 1022
 #define TIMES 1000
+#define TIMES2 100
 #define PADDING 16
 
 static void run_test(void) {
@@ -140,6 +141,9 @@ static void run_test(void) {
     int i, j, padding;
     pa_do_volume_func_t func;
     pa_usec_t start, stop;
+    int k;
+    pa_usec_t min = INT_MAX, max = 0;
+    double s1 = 0, s2 = 0;
 
     func = pa_get_volume_func(PA_SAMPLE_S16NE);
 
@@ -159,25 +163,45 @@ static void run_test(void) {
     for (i = 0; i < SAMPLES; i++) {
         if (samples[i] != samples_ref[i]) {
             printf ("%d: %04x != %04x (%04x * %04x)\n", i, samples[i], samples_ref[i],
-                  samples_orig[i], volumes[i % CHANNELS]);
+                      samples_orig[i], volumes[i % CHANNELS]);
         }
     }
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy(samples, samples_orig, sizeof(samples));
-        pa_volume_s16ne_arm(samples, volumes, CHANNELS, sizeof(samples));
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples, samples_orig, sizeof(samples));
+            pa_volume_s16ne_arm(samples, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
+
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("ARM: %llu usec.", (long long unsigned int) (stop - start));
+    pa_log_info("ARM: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
+
+    min = INT_MAX; max = 0;
+    s1 = s2 = 0;
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples_ref, samples_orig, sizeof(samples));
+            func(samples_ref, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy(samples_ref, samples_orig, sizeof(samples));
-        func(samples_ref, volumes, CHANNELS, sizeof(samples));
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("ref: %llu usec.", (long long unsigned int) (stop - start));
+    pa_log_info("ref: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
+
+    pa_assert_se(memcmp(samples_ref, samples, sizeof(samples)) == 0);
 }
 #endif
 

diff --git a/src/pulsecore/svolume_mmx.c b/src/pulsecore/svolume_mmx.c
index 421156ea8ee8bb4b77d75494cb14b0c6f663eedf..7286b4a2b7744554ff5420bb269b6c9a01617e68 100644 (file)
--- a/src/pulsecore/svolume_mmx.c
+++ b/src/pulsecore/svolume_mmx.c
@@ -241,6 +241,7 @@ static void pa_volume_s16re_mmx(int16_t *samples, int32_t *volumes, unsigned cha
 #define CHANNELS 2
 #define SAMPLES 1022
 #define TIMES 1000
+#define TIMES2 100
 #define PADDING 16
 
 static void run_test(void) {
@@ -251,6 +252,9 @@ static void run_test(void) {
     int i, j, padding;
     pa_do_volume_func_t func;
     pa_usec_t start, stop;
+    int k;
+    pa_usec_t min = INT_MAX, max = 0;
+    double s1 = 0, s2 = 0;
 
     func = pa_get_volume_func(PA_SAMPLE_S16NE);
 
@@ -277,21 +281,39 @@ static void run_test(void) {
         }
     }
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy(samples, samples_orig, sizeof(samples));
-        pa_volume_s16ne_mmx(samples, volumes, CHANNELS, sizeof(samples));
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples, samples_orig, sizeof(samples));
+            pa_volume_s16ne_mmx(samples, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
+
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("MMX: %llu usec.", (long long unsigned int)(stop - start));
+    pa_log_info("MMX: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
+
+    min = INT_MAX; max = 0;
+    s1 = s2 = 0;
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples_ref, samples_orig, sizeof(samples));
+            func(samples_ref, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy(samples_ref, samples_orig, sizeof(samples));
-        func(samples_ref, volumes, CHANNELS, sizeof(samples));
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("ref: %llu usec.", (long long unsigned int)(stop - start));
+    pa_log_info("ref: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
 
     pa_assert_se(memcmp(samples_ref, samples, sizeof(samples)) == 0);
 }

diff --git a/src/pulsecore/svolume_orc.c b/src/pulsecore/svolume_orc.c
index db07ba6140ffe963d868ad1f6d1e1aad84f564c1..270b2911eb8616b2fc41a11beb1a8f2325ac62ff 100644 (file)
--- a/src/pulsecore/svolume_orc.c
+++ b/src/pulsecore/svolume_orc.c
@@ -52,9 +52,10 @@ pa_volume_s16ne_orc(int16_t *samples, int32_t *volumes, unsigned channels, unsig
 #define CHANNELS 2
 #define SAMPLES 1022
 #define TIMES 1000
+#define TIMES2 100
 #define PADDING 16
 
-static void run_test (void) {
+static void run_test(void) {
     int16_t samples[SAMPLES];
     int16_t samples_ref[SAMPLES];
     int16_t samples_orig[SAMPLES];
@@ -62,22 +63,25 @@ static void run_test (void) {
     int i, j, padding;
     pa_do_volume_func_t func;
     pa_usec_t start, stop;
+    int k;
+    pa_usec_t min = INT_MAX, max = 0;
+    double s1 = 0, s2 = 0;
 
-    func = pa_get_volume_func (PA_SAMPLE_S16NE);
+    func = pa_get_volume_func(PA_SAMPLE_S16NE);
 
-    printf ("checking ORC %zd\n", sizeof (samples));
+    printf("checking ORC %zd\n", sizeof(samples));
 
-    pa_random (samples, sizeof (samples));
-    memcpy (samples_ref, samples, sizeof (samples));
-    memcpy (samples_orig, samples, sizeof (samples));
+    pa_random(samples, sizeof(samples));
+    memcpy(samples_ref, samples, sizeof(samples));
+    memcpy(samples_orig, samples, sizeof(samples));
 
     for (i = 0; i < CHANNELS; i++)
         volumes[i] = PA_CLAMP_VOLUME(rand() >> 1);
     for (padding = 0; padding < PADDING; padding++, i++)
         volumes[i] = volumes[padding];
 
-    func (samples_ref, volumes, CHANNELS, sizeof (samples));
-    pa_volume_s16ne_orc (samples, volumes, CHANNELS, sizeof (samples));
+    func(samples_ref, volumes, CHANNELS, sizeof(samples));
+    pa_volume_s16ne_orc(samples, volumes, CHANNELS, sizeof(samples));
     for (i = 0; i < SAMPLES; i++) {
         if (samples[i] != samples_ref[i]) {
             printf ("%d: %04x != %04x (%04x * %04x)\n", i, samples[i], samples_ref[i],
@@ -85,21 +89,39 @@ static void run_test (void) {
         }
     }
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy (samples, samples_orig, sizeof (samples));
-        pa_volume_s16ne_orc (samples, volumes, CHANNELS, sizeof (samples));
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples, samples_orig, sizeof(samples));
+            pa_volume_s16ne_orc(samples, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
+
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("ORC: %llu usec.", (long long unsigned int)(stop - start));
+    pa_log_info("ORC: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
+
+    min = INT_MAX; max = 0;
+    s1 = s2 = 0;
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples_ref, samples_orig, sizeof(samples));
+            func(samples_ref, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy (samples_ref, samples_orig, sizeof (samples));
-        func (samples_ref, volumes, CHANNELS, sizeof (samples));
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("ref: %llu usec.", (long long unsigned int)(stop - start));
+    pa_log_info("ref: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
 
     pa_assert_se(memcmp(samples_ref, samples, sizeof(samples)) == 0);
 }

diff --git a/src/pulsecore/svolume_sse.c b/src/pulsecore/svolume_sse.c
index ef07a2436c65a025969f6c998df8c26f55d91109..8fed69b29a53914675480013f42fdf6e89889f08 100644 (file)
--- a/src/pulsecore/svolume_sse.c
+++ b/src/pulsecore/svolume_sse.c
@@ -253,6 +253,7 @@ static void pa_volume_s16re_sse2(int16_t *samples, int32_t *volumes, unsigned ch
 #define CHANNELS 2
 #define SAMPLES 1022
 #define TIMES 1000
+#define TIMES2 100
 #define PADDING 16
 
 static void run_test(void) {
@@ -263,6 +264,9 @@ static void run_test(void) {
     int i, j, padding;
     pa_do_volume_func_t func;
     pa_usec_t start, stop;
+    int k;
+    pa_usec_t min = INT_MAX, max = 0;
+    double s1 = 0, s2 = 0;
 
     func = pa_get_volume_func(PA_SAMPLE_S16NE);
 
@@ -286,21 +290,39 @@ static void run_test(void) {
         }
     }
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy(samples, samples_orig, sizeof(samples));
-        pa_volume_s16ne_sse2(samples, volumes, CHANNELS, sizeof(samples));
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples, samples_orig, sizeof(samples));
+            pa_volume_s16ne_sse2(samples, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
+
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("SSE: %llu usec.", (long long unsigned int)(stop - start));
+    pa_log_info("SSE: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
+
+    min = INT_MAX; max = 0;
+    s1 = s2 = 0;
+    for (k = 0; k < TIMES2; k++) {
+        start = pa_rtclock_now();
+        for (j = 0; j < TIMES; j++) {
+            memcpy(samples_ref, samples_orig, sizeof(samples));
+            func(samples_ref, volumes, CHANNELS, sizeof(samples));
+        }
+        stop = pa_rtclock_now();
 
-    start = pa_rtclock_now();
-    for (j = 0; j < TIMES; j++) {
-        memcpy(samples_ref, samples_orig, sizeof(samples));
-        func(samples_ref, volumes, CHANNELS, sizeof (samples));
+        if (min > (stop - start)) min = stop - start;
+        if (max < (stop - start)) max = stop - start;
+        s1 += stop - start;
+        s2 += (stop - start) * (stop - start);
     }
-    stop = pa_rtclock_now();
-    pa_log_info("ref: %llu usec.", (long long unsigned int)(stop - start));
+    pa_log_info("ref: %llu usec (min = %llu, max = %llu, stddev = %g).", (long long unsigned int)s1,
+            (long long unsigned int)min, (long long unsigned int)max, sqrt(TIMES2 * s2 - s1 * s1) / TIMES2);
 
     pa_assert_se(memcmp(samples_ref, samples, sizeof(samples)) == 0);
 }