latency/walt/AudioTest.java

/*
 * 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);
    }
}