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).

4 files changed, 147 insertions, 57 deletions

diff --git a/src/pulsecore/svolume_arm.c b/src/pulsecore/svolume_arm.c
index 42e8cbf9..098f10ee 100644
--- 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 421156ea..7286b4a2 100644
--- 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 db07ba61..270b2911 100644
--- 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 ef07a243..8fed69b2 100644
--- 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);
 }