Stutter/skips in Android client

[otis_bartleh]

I've never used the stock kernel, I use Trinity and leankernel on my Galaxy Nexus, both with the stuttering issue... Franco kernel just isn't as good on my phone, guess I'll have to bring that up in the other kernel threads...

[NTolerance]

I've never used the stock kernel, I use Trinity and leankernel on my Galaxy Nexus, both with the stuttering issue... Franco kernel just isn't as good on my phone, guess I'll have to bring that up in the other kernel threads...

The Franco kernel has some documented I/O scheduling tweaks that the other kernels may not have.

[otis_bartleh]

I've never used the stock kernel, I use Trinity and leankernel on my Galaxy Nexus, both with the stuttering issue... Franco kernel just isn't as good on my phone, guess I'll have to bring that up in the other kernel threads...

The Franco kernel has some documented I/O scheduling tweaks that the other kernels may not have.

Both kernels are way better than Franco's, like I said, gonna have to check those threads and post about it, not going to ruin my phone by going to Franco kernel just for Subsonic, I'll just use a player that works. Franco also turns off fsync by default which can result in data corruption...

[NTolerance]

I've never used the stock kernel, I use Trinity and leankernel on my Galaxy Nexus, both with the stuttering issue... Franco kernel just isn't as good on my phone, guess I'll have to bring that up in the other kernel threads...

The Franco kernel has some documented I/O scheduling tweaks that the other kernels may not have.

Both kernels are way better than Franco's, like I said, gonna have to check those threads and post about it, not going to ruin my phone by going to Franco kernel just for Subsonic, I'll just use a player that works. Franco also turns off fsync by default which can result in data corruption...

I'm not trying to sell you a kernel, but rather I'm just attempting to highlight the core technical issue, which is that of poor I/O performance depending on kernel configuration.

Also, I know someone who is using the stock Verizon 4.0.4 kernel, and he can reproduce some stuttering and popping while streaming via Google Music, which from a technical perspective works a lot like Subsonic does.

[otis_bartleh]

No, I gotcha, but Google Music and all other players works fine for me, it is only Subsonic that does this... And like I mentioned, the performance of Franco is way behind both leankernel and Trinity both, on my device. I'll try his latest though to see if I can replicate the issue, and if not, I'll post in those threads on Rootzwiki. Thanks for the info!!

[jakebriggs]

I ditched my S1, and got an S3 (cm10 nightlies), I don't get the stuttery bzzzts anymore but I do get the skips.

I tested it with the subsonic demo server, with a bbc discovery podcast (the sound of deafness) since its long enough, using DSub instead of the stock. One thing I did notice, is that when the song skips for the first time "pause" icon/button actually switches to the "stop" icon/button temporarily.

Then afterwards, I get the skips as per normal.

I tried it again with the podcast "ham nation", number 59, 64 kbps, 71 minutes, and I get the same hing - skips and pauses while the file is downloading.

Moving back to the normal subsonic android app, I tried it with a podcast from my personal server, 192 kbps and the skips are still there - they seemed longer and more frequent.

I am quickly running out of patience to be honest. I mean, I basically paid for this software - donating in order to get "premium" features. But, I've basically paid for frustration, stuttery music, and no support.

There has got to be something I can do to help here before I give up all together. Log files? A version of the android app with some verbose debugging, so I can play music and note down mp3 specs, times when it skips, etc..?

I am willing to invest time into fixing this (since I am a software engineer, I think I could help), despite having already invested money into it.

[GJ51]

My SIII is rooted but running a very close to stock rom. Both DSub and the latest Subsonic Android app run fine on all my servers and SS instances ... EXCEPT ... the DEMO site.

Go figure.

Send me a PM if you want to test on one of my sites that I know works with the SIII or if you want me to test your site with my SIII.

[jakebriggs]

I also tried with my workmates S3, with stock firmware, against my server - this works fine :/

[GJ51]

So why not switch to a different rom? I'm using dazedandconfused's Wicked Sensations rom. Stable, and clean. I've got three different Android Subsonic apk's on my phone and all of them work perfect. It may be a Sprint only rom though, you'd have to check, but there should be a good rom out there that works.

[jakebriggs]

Attached is a log file generated from adb logcat - with only the subsonic process grepped out. The gaps happened 3 times, and I think they happened because the mediaPlayer object ran out of the partial file to read, causing the OnCompletionListener callback to fire, which reset the mediaplayer to start playing a different partial file at the point where the previous file had finished. Obviously this is just a guess from 30 minutes reading the code and looking at the log files - the times when this happens seems to be at the same time I hear the gaps in playback.

From the log file:

Code: Select all

...
...
I/DownloadFile( 5382): Downloaded 25.22 MB of Layer 04
I/DownloadFile( 5382): Downloaded 25.96 MB of Layer 04
I/DownloadFile( 5382): Downloaded 26.64 MB of Layer 04
I/DownloadFile( 5382): Downloaded 27.32 MB of Layer 04
I/DownloadFile( 5382): Downloaded 28.07 MB of Layer 04
I/DownloadFile( 5382): Downloaded 28.76 MB of Layer 04
I/DownloadServiceImpl( 5382): STARTED -> COMPLETED (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): Requesting restart from 122828 of 5608000
D/CancellableTask( 5382): Cancelling BufferTask (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): COMPLETED -> IDLE (DownloadFile (Layer 04))
D/CancellableTask( 5382): Starting thread for BufferTask (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): IDLE -> DOWNLOADING (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): Buffering /storage/sdcard1/subsonic/music/Mixes/Autonomic Podcasts/Layer 04.0.partial.mp3 (30323208/30446088, false)
I/DownloadServiceImpl( 5382): Buffering /storage/sdcard1/subsonic/music/Mixes/Autonomic Podcasts/Layer 04.0.partial.mp3 (30550544/30446088, false)
I/DownloadServiceImpl( 5382): DOWNLOADING -> IDLE (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): IDLE -> PREPARING (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): PREPARING -> PREPARED (DownloadFile (Layer 04))
I/DownloadServiceImpl( 5382): Restarting player from position 122828
I/DownloadServiceImpl( 5382): PREPARED -> STARTED (DownloadFile (Layer 04))
I/DownloadServiceLifecycleSupport( 5382): Serialized currentPlayingIndex: 0, currentPlayingPosition: 122880
I/FileUtil( 5382): Serialized object to /data/data/net.sourceforge.subsonic.androidapp/cache/downloadstate.ser
...
...


This logging happens when the gaps appear I think. Perhaps its the serialization thats causing the gaps on CM10. I might augment the debugging with a timestamp somehow, and see if that helps me narrow down the issue.

[jakebriggs]

I put some simple timings in against a few Log.* - this sort of thing:

Code: Select all

    Log.i(TAG, System.currentTimeMillis() +  " - Requesting restart from " + pos  + " of " + duration);
    Log.i(TAG, System.currentTimeMillis() +  " - Restarting player from position " + position);


and I get an output like this (Again, from logcat, grepping out process id 6750, and a snippet of when I think the gap happened):

Code: Select all

I/DownloadServiceImpl( 6750): 1349824056713 - STARTED -> COMPLETED (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824056717 - Requesting restart from 6060 of 5608000
D/CancellableTask( 6750): Cancelling BufferTask (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824056733 - COMPLETED -> IDLE (DownloadFile (Layer 04))
D/CancellableTask( 6750): Starting thread for BufferTask (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824056739 - IDLE -> DOWNLOADING (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824056741 - Buffering /storage/sdcard1/subsonic/music/Mixes/Autonomic Podcasts/Layer 04.0.partial.mp3 (1641912/1764792, false)
I/DownloadFile( 6750): Downloaded 1.76 MB of Layer 04
I/DownloadServiceImpl( 6750): 1349824057742 - Buffering /storage/sdcard1/subsonic/music/Mixes/Autonomic Podcasts/Layer 04.0.partial.mp3 (1906896/1764792, false)
I/DownloadServiceImpl( 6750): 1349824057745 - DOWNLOADING -> IDLE (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824057780 - IDLE -> PREPARING (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824057790 - PREPARING -> PREPARED (DownloadFile (Layer 04))
I/DownloadServiceImpl( 6750): 1349824057790 - Restarting player from position 6060
I/DownloadServiceImpl( 6750): 1349824057801 - PREPARED -> STARTED (DownloadFile (Layer 04))

Once thing I notice is the time it takes from "Requesting restart from 6060 of 5608000" till "Restarting player from position 6060" is 1349824057790 - 1349824056717 = 1073 milliseconds, which in seconds is 1.073, which is suspiciously similar in length to the gaps I am hearing.

Now, the app requests the restart in the callback function that is fired when the mediaPlayer object finishes playing, which is eventually done a second later when the app tells the mediaPlayer to seek to the restart position. Whatever happens between that callback onCompletion function and the doPlay method being called again which eventually tells the mediaplayer to seek if the position is not zero is taking some time. Now, that lag could be in anything - perhaps the cm10 mediaPlayer is broken, or perhaps the filesystem is taking time somewhere blocking either subsonic or mediaPlayer for a little while.

[jakebriggs]

This output (grepped FINDME from log file):

Code: Select all

I/DownloadServiceImpl(32528): 1349829962261 FINDME - doPLay start
I/DownloadServiceImpl(32528): 1349829973041 FINDME - Requesting restart from 10292 of 5708000
I/DownloadServiceImpl(32528): 1349829973057 FINDME - just run reset
I/DownloadServiceImpl(32528): 1349829973058 FINDME - just made a new buffertask
I/DownloadServiceImpl(32528): 1349829973059 FINDME - just asked buffertask to start
I/DownloadServiceImpl(32528): 1349829974063 FINDME - doPLay start
I/DownloadServiceImpl(32528): 1349829974100 FINDME - Restarting player from position 10292
I/DownloadServiceImpl(32528): 1349829974103 FINDME - Restarted player from position 10292

came from this code (standard with debugging added):

Code: Select all

...
...
private synchronized void doPlay(final DownloadFile downloadFile, int position, boolean start) {
        try {
            Log.i(TAG, System.currentTimeMillis() +  " FINDME - doPLay start");                       
            final File file = downloadFile.isCompleteFileAvailable() ? downloadFile.getCompleteFile() : downloadFile.getPartialFile();
            downloadFile.updateModificationDate();
            mediaPlayer.setOnCompletionListener(null);
            mediaPlayer.reset();
            setPlayerState(IDLE);
            mediaPlayer.setAudioStreamType(AudioManager.STREAM_MUSIC);
            mediaPlayer.setDataSource(file.getPath());
            setPlayerState(PREPARING);
            mediaPlayer.prepare();
            setPlayerState(PREPARED);
           
            mediaPlayer.setOnCompletionListener(new MediaPlayer.OnCompletionListener() {
                @Override
                public void onCompletion(MediaPlayer mediaPlayer) {

                    // Acquire a temporary wakelock, since when we return from
                    // this callback the MediaPlayer will release its wakelock
                    // and allow the device to go to sleep.
                    wakeLock.acquire(60000);

                    setPlayerState(COMPLETED);

                    // If COMPLETED and not playing partial file, we are *really" finished
                    // with the song and can move on to the next.
                    if (!file.equals(downloadFile.getPartialFile())) {
                        onSongCompleted();
                        return;
                    }

                    // If file is not completely downloaded, restart the playback from the current position.
                    int pos = mediaPlayer.getCurrentPosition();
                    synchronized (DownloadServiceImpl.this) {

                        // Work-around for apparent bug on certain phones: If close (less than ten seconds) to the end
                        // of the song, skip to the next rather than restarting it.
                        Integer duration = downloadFile.getSong().getDuration() == null ? null : downloadFile.getSong().getDuration() * 1000;
                        if (duration != null) {
                            if (Math.abs(duration - pos) < 10000) {
                                Log.i(TAG, System.currentTimeMillis() +  " FINDME - Skipping restart from " + pos  + " of " + duration);
                                onSongCompleted();
                                return;
                            }
                        }

                        Log.i(TAG, System.currentTimeMillis() +  " FINDME - Requesting restart from " + pos  + " of " + duration);
                        reset();
                        Log.i(TAG, System.currentTimeMillis() +  " FINDME - just run reset");                       
                        bufferTask = new BufferTask(downloadFile, pos);
                        Log.i(TAG, System.currentTimeMillis() +  " FINDME - just made a new buffertask");                       
                        bufferTask.start();
                        Log.i(TAG, System.currentTimeMillis() +  " FINDME - just asked buffertask to start");                       
                    }
                }
            });
           
            if (position != 0) {
                Log.i(TAG, System.currentTimeMillis() +  " FINDME - Restarting player from position " + position);
                mediaPlayer.seekTo(position);
                Log.i(TAG, System.currentTimeMillis() +  " FINDME - Restarted player from position " + position);               
            }
...
...

which came from DownloadServiceImpl.java

So, it takes a second from when the bufferTask is asked to start (bufferTask.start();) till the doPLay method actually starts, then another 40 milliseconds to get to the point where we tell the mediaPlayer to seek. I think I am chasing a red herring here, since you would expect the buffer to take a little while to fill.

Here is some more detailed logs:

Code: Select all

I/DownloadServiceImpl(32528): 1349829973059 FINDME - just asked buffertask to start
D/CancellableTask(32528): Starting thread for BufferTask (DownloadFile (Layer 06))
I/DownloadServiceImpl(32528): 1349829973060 - IDLE -> DOWNLOADING (DownloadFile (Layer 06))
I/DownloadServiceImpl(32528): 1349829973061 - Buffering /storage/sdcard1/subsonic/music/Mixes/Autonomic Podcasts/Layer 06.0.partial.mp3 (2904944/3027824, false)
I/DownloadFile(32528): Downloaded 2.88 MB of Layer 06
I/DownloadServiceImpl(32528): 1349829974062 - Buffering /storage/sdcard1/subsonic/music/Mixes/Autonomic Podcasts/Layer 06.0.partial.mp3 (3155448/3027824, false)
I/DownloadServiceImpl(32528): 1349829974063 FINDME - doPLay start


and we see that all the time is taken up in the while loop that waits for the buffer to complete - if the buffering is not complete then is sleeps for 1000 milliseconds! Which seems like the delay I am looking for. But, does any of this get in the way of the music thats playing? Hmmm. If so, making the buffer bigger would make the gap longer. But it will always sleep for 1 second no matter how small the buffer is unless the buffer is so small that it is filled before the BufferTask is started.

I am gonna try two things. One, make the buffer smaller somehow once I work out how to. Two, make the thread sleep for 10 milliseconds. But my line of reasoning does't seem right though, even a 10 millisecond gap would be audible and annoying and the stock rom has no issues.

Does mediaPlayer decode faster than it plays, and when it fires the completion listener is much before that actual audio has played? Meaning you can have a gap between the mediaPlayer stopping decoding and starting decoding again, since something else is still playing the decoded audio? In that case, a 1 second thread sleep would make no real difference!

[jakebriggs]

I changed my mind. I am gonna increase the buffer from 5 seconds to 30.

Code: Select all

   
...
...
private class BufferTask extends CancellableTask {

        private static final int BUFFER_LENGTH_SECONDS = 30;
...
...


[jakebriggs]

I did a

Code: Select all

./adb logcat | grep FINDME

and the restarts and sleeps did not correlate to the pauses AT ALL. It was a red herring. The issue must be in MediaPlayer somewhere, or somewhere deeper. Back to the drawing board

[jakebriggs]

I am getting these that SEEM to correlate with the gaps:

Code: Select all

W/AudioTrack( 1916): releaseBuffer() track 0x40eb5300 name=0x1 disabled, restarting


but my correlation detection is a bit poor, as we have seen....