diff options
Diffstat (limited to 'android/WALT/app/src/main/java/org/chromium/latency/walt/AudioTest.java')
-rw-r--r-- | android/WALT/app/src/main/java/org/chromium/latency/walt/AudioTest.java | 458 |
1 files changed, 458 insertions, 0 deletions
diff --git a/android/WALT/app/src/main/java/org/chromium/latency/walt/AudioTest.java b/android/WALT/app/src/main/java/org/chromium/latency/walt/AudioTest.java new file mode 100644 index 0000000..6987d7c --- /dev/null +++ b/android/WALT/app/src/main/java/org/chromium/latency/walt/AudioTest.java @@ -0,0 +1,458 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.chromium.latency.walt; + +import android.content.Context; +import android.media.AudioManager; +import android.os.Handler; + +import java.io.IOException; +import java.util.ArrayList; +import java.util.Locale; + +import static org.chromium.latency.walt.Utils.getIntPreference; + +class AudioTest extends BaseTest { + + static { + System.loadLibrary("sync_clock_jni"); + } + + static final int CONTINUOUS_TEST_PERIOD = 500; + static final int COLD_TEST_PERIOD = 5000; + + enum AudioMode {COLD, CONTINUOUS} + + private Handler handler = new Handler(); + private boolean userStoppedTest = false; + + // Sound params + private final double duration = 0.3; // seconds + private final int sampleRate = 8000; + private final int numSamples = (int) (duration * sampleRate); + private final byte generatedSnd[] = new byte[2 * numSamples]; + private final double freqOfTone = 880; // hz + + private AudioMode audioMode; + private int period = 500; // time between runs in ms + + // Audio in + private long last_tb = 0; + private int msToRecord = 1000; + private final int frameRate; + private final int framesPerBuffer; + + private int initiatedBeeps, detectedBeeps; + private int playbackRepetitions; + private static final int playbackSyncAfterRepetitions = 20; + + // Audio out + private int requestedBeeps; + private int recordingRepetitions; + private static int recorderSyncAfterRepetitions = 10; + private final int threshold; + + ArrayList<Double> deltas_mic = new ArrayList<>(); + private ArrayList<Double> deltas_play2queue = new ArrayList<>(); + ArrayList<Double> deltas_queue2wire = new ArrayList<>(); + private ArrayList<Double> deltasJ2N = new ArrayList<>(); + + long lastBeepTime; + + public static native long playTone(); + public static native void startWarmTest(); + public static native void stopTests(); + public static native void createEngine(); + public static native void destroyEngine(); + public static native void createBufferQueueAudioPlayer(int frameRate, int framesPerBuffer); + + public static native void startRecording(); + public static native void createAudioRecorder(int frameRate, int framesToRecord); + public static native short[] getRecordedWave(); + public static native long getTeRec(); + public static native long getTcRec(); + public static native long getTePlay(); + + AudioTest(Context context) { + super(context); + playbackRepetitions = getIntPreference(context, R.string.preference_audio_out_reps, 10); + recordingRepetitions = getIntPreference(context, R.string.preference_audio_in_reps, 5); + threshold = getIntPreference(context, R.string.preference_audio_in_threshold, 5000); + + //Check for optimal output sample rate and buffer size + AudioManager am = (AudioManager) context.getSystemService(Context.AUDIO_SERVICE); + String frameRateStr = am.getProperty(AudioManager.PROPERTY_OUTPUT_SAMPLE_RATE); + String framesPerBufferStr = am.getProperty(AudioManager.PROPERTY_OUTPUT_FRAMES_PER_BUFFER); + logger.log("Optimal frame rate is: " + frameRateStr); + logger.log("Optimal frames per buffer is: " + framesPerBufferStr); + + //Convert to ints + frameRate = Integer.parseInt(frameRateStr); + framesPerBuffer = Integer.parseInt(framesPerBufferStr); + + //Create the audio engine + createEngine(); + createBufferQueueAudioPlayer(frameRate, framesPerBuffer); + logger.log("Audio engine created"); + } + + AudioTest(Context context, AutoRunFragment.ResultHandler resultHandler) { + this(context); + this.resultHandler = resultHandler; + } + + void setPlaybackRepetitions(int beepCount) { + playbackRepetitions = beepCount; + } + + void setRecordingRepetitions(int beepCount) { + recordingRepetitions = beepCount; + } + + void setPeriod(int period) { + this.period = period; + } + + void setAudioMode(AudioMode mode) { + audioMode = mode; + } + + AudioMode getAudioMode() { + return audioMode; + } + + int getOptimalFrameRate() { + return frameRate; + } + + int getThreshold() { + return threshold; + } + + void stopTest() { + userStoppedTest = true; + } + + void teardown() { + destroyEngine(); + logger.log("Audio engine destroyed"); + } + + void beginRecordingMeasurement() { + userStoppedTest = false; + deltas_mic.clear(); + deltas_play2queue.clear(); + deltas_queue2wire.clear(); + deltasJ2N.clear(); + + int framesToRecord = (int) (0.001 * msToRecord * frameRate); + createAudioRecorder(frameRate, framesToRecord); + logger.log("Audio recorder created; starting test"); + + requestedBeeps = 0; + doRecordingTestRepetition(); + } + + private void doRecordingTestRepetition() { + if (requestedBeeps >= recordingRepetitions || userStoppedTest) { + finishRecordingMeasurement(); + return; + } + + if (requestedBeeps % recorderSyncAfterRepetitions == 0) { + try { + waltDevice.syncClock(); + } catch (IOException e) { + logger.log("Error syncing clocks: " + e.getMessage()); + if (testStateListener != null) testStateListener.onTestStoppedWithError(); + return; + } + } + + requestedBeeps++; + startRecording(); + switch (audioMode) { + case CONTINUOUS: + handler.postDelayed(requestBeepRunnable, msToRecord / 2); + break; + case COLD: // TODO: find a more accurate method to measure cold input latency + requestBeepRunnable.run(); + break; + } + handler.postDelayed(stopBeepRunnable, msToRecord); + } + + void beginPlaybackMeasurement() { + userStoppedTest = false; + if (audioMode == AudioMode.CONTINUOUS) { + startWarmTest(); + } + try { + waltDevice.syncClock(); + waltDevice.startListener(); + } catch (IOException e) { + logger.log("Error starting test: " + e.getMessage()); + if (testStateListener != null) testStateListener.onTestStoppedWithError(); + return; + } + deltas_mic.clear(); + deltas_play2queue.clear(); + deltas_queue2wire.clear(); + deltasJ2N.clear(); + + logger.log("Starting playback test"); + + initiatedBeeps = 0; + detectedBeeps = 0; + + waltDevice.setTriggerHandler(playbackTriggerHandler); + + handler.postDelayed(playBeepRunnable, 300); + } + + private WaltDevice.TriggerHandler playbackTriggerHandler = new WaltDevice.TriggerHandler() { + @Override + public void onReceive(WaltDevice.TriggerMessage tmsg) { + // remove the far away playBeep callback(s) + handler.removeCallbacks(playBeepRunnable); + + detectedBeeps++; + long enqueueTime = getTePlay() - waltDevice.clock.baseTime; + double dt_play2queue = (enqueueTime - lastBeepTime) / 1000.; + deltas_play2queue.add(dt_play2queue); + + double dt_queue2wire = (tmsg.t - enqueueTime) / 1000.; + deltas_queue2wire.add(dt_queue2wire); + + logger.log(String.format(Locale.US, + "Beep detected, initiatedBeeps=%d, detectedBeeps=%d\n" + + "dt native playTone to Enqueue = %.2f ms\n" + + "dt Enqueue to wire = %.2f ms\n", + initiatedBeeps, detectedBeeps, + dt_play2queue, + dt_queue2wire + )); + + if (traceLogger != null) { + traceLogger.log(lastBeepTime + waltDevice.clock.baseTime, + enqueueTime + waltDevice.clock.baseTime, + "Play-to-queue", + "Bar starts at play time, ends when enqueued"); + traceLogger.log(enqueueTime + waltDevice.clock.baseTime, + tmsg.t + waltDevice.clock.baseTime, + "Enqueue-to-wire", + "Bar starts at enqueue time, ends when beep is detected"); + } + if (testStateListener != null) testStateListener.onTestPartialResult(dt_queue2wire); + + // Schedule another beep soon-ish + handler.postDelayed(playBeepRunnable, (long) (period + Math.random() * 50 - 25)); + } + }; + + private Runnable playBeepRunnable = new Runnable() { + @Override + public void run() { + // debug: logger.log("\nPlaying tone..."); + + // Check if we saw some transitions without beeping, might be noise audio cable. + if (initiatedBeeps == 0 && detectedBeeps > 1) { + logger.log("Unexpected beeps detected, noisy cable?"); + return; + } + + if (initiatedBeeps >= playbackRepetitions || userStoppedTest) { + finishPlaybackMeasurement(); + return; + } + + initiatedBeeps++; + + if (initiatedBeeps % playbackSyncAfterRepetitions == 0) { + try { + waltDevice.stopListener(); + waltDevice.syncClock(); + waltDevice.startListener(); + } catch (IOException e) { + logger.log("Error re-syncing clock: " + e.getMessage()); + finishPlaybackMeasurement(); + return; + } + } + + try { + waltDevice.command(WaltDevice.CMD_AUDIO); + } catch (IOException e) { + logger.log("Error sending command AUDIO: " + e.getMessage()); + return; + } + long javaBeepTime = waltDevice.clock.micros(); + lastBeepTime = playTone() - waltDevice.clock.baseTime; + double dtJ2N = (lastBeepTime - javaBeepTime)/1000.; + deltasJ2N.add(dtJ2N); + if (traceLogger != null) { + traceLogger.log(javaBeepTime + waltDevice.clock.baseTime, + lastBeepTime + waltDevice.clock.baseTime, "Java-to-native", + "Bar starts when Java tells native to beep and ends when buffer written in native"); + } + logger.log(String.format(Locale.US, + "Called playTone(), dt Java to native = %.3f ms", + dtJ2N + )); + + + // Repost doBeep to some far away time to blink again even if nothing arrives from + // Teensy. This callback will almost always get cancelled by onIncomingTimestamp() + handler.postDelayed(playBeepRunnable, (long) (period * 3 + Math.random() * 100 - 50)); + + } + }; + + + private Runnable requestBeepRunnable = new Runnable() { + @Override + public void run() { + // logger.log("\nRequesting beep from WALT..."); + String s; + try { + s = waltDevice.command(WaltDevice.CMD_BEEP); + } catch (IOException e) { + logger.log("Error sending command BEEP: " + e.getMessage()); + return; + } + last_tb = Integer.parseInt(s); + logger.log("Beeped, reply: " + s); + handler.postDelayed(processRecordingRunnable, (long) (msToRecord * 2 + Math.random() * 100 - 50)); + } + }; + + private Runnable stopBeepRunnable = new Runnable() { + @Override + public void run() { + try { + waltDevice.command(WaltDevice.CMD_BEEP_STOP); + } catch (IOException e) { + logger.log("Error stopping tone from WALT: " + e.getMessage()); + } + } + }; + + private Runnable processRecordingRunnable = new Runnable() { + @Override + public void run() { + long te = getTeRec() - waltDevice.clock.baseTime; // When a buffer was enqueued for recording + long tc = getTcRec() - waltDevice.clock.baseTime; // When callback receiving a recorded buffer fired + long tb = last_tb; // When WALT started a beep (according to WALT clock) + short[] wave = getRecordedWave(); + int noisyAtFrame = 0; // First frame when some noise starts + while (noisyAtFrame < wave.length && wave[noisyAtFrame] < threshold) + noisyAtFrame++; + if (noisyAtFrame == wave.length) { + logger.log("WARNING: No sound detected"); + doRecordingTestRepetition(); + return; + } + + // Length of recorded buffer + double duration_us = wave.length * 1e6 / frameRate; + + // Duration in microseconds of the initial silent part of the buffer, and the remaining + // part after the beep started. + double silent_us = noisyAtFrame * 1e6 / frameRate; + double remaining_us = duration_us - silent_us; + + // Time from the last frame in the buffer until the callback receiving the buffer fired + double latencyCb_ms = (tc - tb - remaining_us) / 1000.; + + // Time from the moment a buffer was enqueued for recording until the first frame in + // the buffer was recorded + double latencyEnqueue_ms = (tb - te - silent_us) / 1000.; + + logger.log(String.format(Locale.US, + "Processed: L_cb = %.3f ms, L_eq = %.3f ms, noisy frame = %d", + latencyCb_ms, + latencyEnqueue_ms, + noisyAtFrame + )); + + if (testStateListener != null) testStateListener.onTestPartialResult(latencyCb_ms); + if (traceLogger != null) { + traceLogger.log((long) (tb + waltDevice.clock.baseTime + remaining_us), + tc + waltDevice.clock.baseTime, + "Beep-to-rec-callback", + "Bar starts when WALT plays beep and ends when recording callback received"); + } + + deltas_mic.add(latencyCb_ms); + doRecordingTestRepetition(); + } + }; + + private void finishPlaybackMeasurement() { + stopTests(); + waltDevice.stopListener(); + waltDevice.clearTriggerHandler(); + waltDevice.checkDrift(); + + // Debug: logger.log("deltas_play2queue = array(" + deltas_play2queue.toString() +")"); + logger.log(String.format(Locale.US, + "\n%s audio playback results:\n" + + "Detected %d beeps out of %d initiated\n" + + "Median Java to native time is %.3f ms\n" + + "Median native playTone to Enqueue time is %.1f ms\n" + + "Buffer length is %d frames at %d Hz = %.2f ms\n" + + "-------------------------------\n" + + "Median time from Enqueue to wire is %.1f ms\n" + + "-------------------------------\n", + audioMode == AudioMode.COLD? "Cold" : "Continuous", + detectedBeeps, initiatedBeeps, + Utils.median(deltasJ2N), + Utils.median(deltas_play2queue), + framesPerBuffer, frameRate, 1000.0 / frameRate * framesPerBuffer, + Utils.median(deltas_queue2wire) + )); + + if (resultHandler != null) { + resultHandler.onResult(deltas_play2queue, deltas_queue2wire); + } + if (testStateListener != null) testStateListener.onTestStopped(); + if (traceLogger != null) traceLogger.flush(context); + } + + private void finishRecordingMeasurement() { + waltDevice.checkDrift(); + + // Debug: logger.log("deltas_mic: " + deltas_mic.toString()); + + logger.log(String.format(Locale.US, + "\nAudio recording/microphone results:\n" + + "Recorded %d beeps.\n" + + "-------------------------------\n" + + "Median callback latency - " + + "time from sampling the last frame to recorder callback is %.1f ms\n" + + "-------------------------------\n", + deltas_mic.size(), + Utils.median(deltas_mic) + )); + + if (resultHandler != null) { + resultHandler.onResult(deltas_mic); + } + if (testStateListener != null) testStateListener.onTestStopped(); + if (traceLogger != null) traceLogger.flush(context); + } +} |