Profiling MidiDriver playback - Sound choppy
smarek opened this issue · 9 comments
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.
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
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.
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.
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.
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!
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.
Well, thank you, I can confirm that on heavy-usage use-case this works really nicely and smoothly.
Issue is solved using the OpenSLES
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.
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