Profiling MidiDriver playback - Sound choppy

[smarek]

Hello,

first, thank you for the wonderful work you did on this solution. second, I'm facing problem when generating MIDI events in high rate.

I've added time profiling to playback loop in DriverThread like this:

            while (running) {
                // Write the midi events
                long a = System.currentTimeMillis();
                synchronized (queuedEvents) {
                    for (byte[] queuedEvent : queuedEvents)
                        write(queuedEvent);

                    queuedEvents.clear();
                }
                long b = System.currentTimeMillis();

                // Render the audio

                if (render(buffer) == 0) {
                    break;
                }

                // Write audio to audiotrack

                status = audioTrack.write(buffer, 0, buffer.length);
                long c = System.currentTimeMillis();

                if (status < 0) {
                    break;
                }
                Log.d("MidiDriver", String.format("%d %d", b - a, c - a));
            }

Which gives out output similar to this:

08-31 15:53:26.489  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.489  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.489  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.489  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.609  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 119
08-31 15:53:26.609  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.610  15348-15646/org.testing.application.midi D/MidiDriver﹕ 1 1
08-31 15:53:26.610  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.610  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.710  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 100
08-31 15:53:26.710  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.710  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.710  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.710  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.830  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 120
08-31 15:53:26.830  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.830  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.830  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.831  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 1
08-31 15:53:26.951  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 120
08-31 15:53:26.951  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.951  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.951  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:26.951  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:27.071  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 120
08-31 15:53:27.073  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 2
08-31 15:53:27.074  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 1
08-31 15:53:27.074  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:27.074  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 0
08-31 15:53:27.194  15348-15646/org.testing.application.midi D/MidiDriver﹕ 0 120

Which clearly shows that calling audioTrack.write(buffer, 0, buffer.length); is taking up to 120ms on my device (Nexus 5), which is breaking MIDI generated music by inserting these delays at random places in audio stream.

This is code I used to generate midi stream

            while (playbackStarted) {
                // Off the note
                sendMidiSoundCommand(0, 0x80, 40, 0);
                // On the note
                sendMidiSoundCommand(0, 0x90, 40, 127);
                try {
                    Thread.sleep(128);
                } catch (InterruptedException e) {
                    Log.e(TAG, "playback interrupted", e);
                }
            }

Have you encountered such issue yet? My idea is to offload writing to audio stream to different thread, which should give out consistent output, but I'd be grateful for your (or the community) input on this.

[smarek]

Update, it looks like this is long-lasting issue on side of Google AudioTrack implementation, see: https://code.google.com/p/android/issues/detail?id=3434

I'm now trying to compensate it using two threads, like the example here: https://github.com/gkasten/high-performance-audio

[billthefarmer]

I would suggest that if you want to play music, it might be better to use the MediaPlayer to play a midi file. All the midi apps I have written use user interaction to play notes so there isn't an issue.

[smarek]

Thank you, that is of course good idea, however I'm rendering both audio and visual output on-the-fly, so I don't have MIDI files available to "just play them". I tried to play with BUFFER_SIZE and SAMPLE_RATE, which did nothing except delaying the issue with choppy playback to occur in longer intervals.

[billthefarmer]

I've looked at this again and realised something like this is somewhat inevitable because of the time taken to output the data. Rendering 512 stereo samples at 22050 samples/sec takes about 23ms. That's 128 (mixBufferSize) x 4 = 512. 512 / 22050 x 1000 = 23.22. It looks like the audio track is buffering about five lots of data before rendering, so it should take about 23.22 x 5 = 116ms, about what you're getting on average.

I have developed a new version of the driver using the built in OpenSLES library. The EAS rendering is driven by a callback from the audio player. The only contention is between the EAS render function and the EAS write function, as they driven by different threads. I have used a mutex to resolve this, which appears to work just fine. However I don't have an application which generates a high rate of midi events.

[smarek]

Wow man, I really appreciate your hard work on this issue. The reason you listed seems pretty solid, however in meantime I switched over to MediaPlayer and https://github.com/LeffelMania/android-midi-lib real-time rendering of MidiFiles

I'll try to test your new version as soon as possible, which is in my case in matter of days. I'll get back to you!

[billthefarmer]

I put some debugging code in the driver to see what is happening.

// get elapsed time millis
long getElapsedTimeMillis()
{
    static struct timespec last;
    static struct timespec time;

    clock_gettime(CLOCK_MONOTONIC, &time);

    long elapsed = (time.tv_sec - last.tv_sec) * 1000 +
        (time.tv_nsec - last.tv_nsec) / 1000000;

    last = time;

    return elapsed;
}

// this callback handler is called every time a buffer finishes
// playing
void bqPlayerCallback(SLAndroidSimpleBufferQueueItf bq, void *context)
{
    EAS_RESULT result;
    EAS_I32 numGenerated;
    EAS_I32 count;

    assert(bq == bqPlayerBufferQueue);
    assert(NULL == context);

    long a = getElapsedTimeMillis();

    // for streaming playback, replace this test by logic to fill the
    // next buffer

    count = 0;
    while (count < bufferSize)
    {
    // lock
    pthread_mutex_lock(&mutex);

    result = pEAS_Render(pEASData, buffer + count,
                 pLibConfig->mixBufferSize, &numGenerated);
    // unlock
    pthread_mutex_unlock(&mutex);      

    assert(result == EAS_SUCCESS);

    count += numGenerated * pLibConfig->numChannels;
    }

    long b = getElapsedTimeMillis();

    // enqueue another buffer
    result = (*bqPlayerBufferQueue)->Enqueue(bq, buffer,
                         bufferSize * sizeof(EAS_PCM));

    // the most likely other result is SL_RESULT_BUFFER_INSUFFICIENT,
    // which for this code example would indicate a programming error
    assert(SL_RESULT_SUCCESS == result);

    long c = getElapsedTimeMillis();

    LOG_D(LOG_TAG, "Elapsed: %ld %ld %ld ms", a, b, c);
}

Output:

D/MidiDriver( 5392): Elapsed: 18 0 0 ms
D/MidiDriver( 5392): Elapsed: 0 0 0 ms
D/MidiDriver( 5392): Elapsed: 0 0 0 ms
D/MidiDriver( 5392): Elapsed: 4 0 0 ms
D/MidiDriver( 5392): Elapsed: 21 0 0 ms
D/MidiDriver( 5392): Elapsed: 26 0 0 ms
D/MidiDriver( 5392): Elapsed: 26 0 0 ms
D/MidiDriver( 5392): Elapsed: 26 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 21 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 23 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms
D/MidiDriver( 5392): Elapsed: 22 0 0 ms

The resolution is not quite high enough to show exactly what is happening, but midi rendering each buffer and queueing it takes less than a millisecond, and the callback is being called every 23 ms roughly. So there is less that a millisecond contention with the midi stream.

[smarek]

Well, thank you, I can confirm that on heavy-usage use-case this works really nicely and smoothly. Issue is solved using the OpenSLES

[smarek]

Also I've published my version of library, which is based on Gradle, merging some features from jhidin branch (java constants, etc..) and is edited version of latest master commits (2 commits ahead as of now)
Feel free to link/use this version, GPL license honored.

https://github.com/smarek/mididriver

[smarek]

My version also includes Gradle based NDK compilation for ARM (armeabi), ARM7 (armeabi-v7a), x86 and MIPS, excluding 64-bit variants per your instructions on latest OpenSLES development