Kodi Community Forum
OpenELEC Testbuilds for RaspberryPi Part 2 - Printable Version

+- Kodi Community Forum (https://forum.kodi.tv)
+-- Forum: Support (https://forum.kodi.tv/forumdisplay.php?fid=33)
+--- Forum: General Support (https://forum.kodi.tv/forumdisplay.php?fid=111)
+---- Forum: Raspberry Pi (https://forum.kodi.tv/forumdisplay.php?fid=166)
+---- Thread: OpenELEC Testbuilds for RaspberryPi Part 2 (/showthread.php?tid=184866)



RE: OpenELEC Testbuilds for RaspberryPi Part 2 - doveman2 - 2013-08-20

(2013-08-20, 00:59)RichG Wrote: That's exactly what causes my reboot, in Pictures, Videos, Movies, TV Series, Music or Programs. Same if I try to change either of the sort options too. Never had this before.

BTW I'm using a mysql database and accessing files over NFS (if that matters at all).

I'm using NFS but not mysql, so that would seem to rule the latter out at least.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - spjonez - 2013-08-20

Had the freeze issue again tonight, no buffering or any other indicator on screen. File resumed after ~20s and did a fast forward / audio garble to catch up.

Log snippet:
Code:
22:05:43 T:2716857440  NOTICE: not a 3D movie
22:05:43 T:2716857440  NOTICE: Display resolution ADJUST : 1920x1080 @ 24.00 - Full Screen (23) (weight: 0.002)
22:05:44 T:3060412416  NOTICE: Using GL_TEXTURE_2D
22:05:44 T:3060412416  NOTICE: GL: Using BYPASS render method
22:05:44 T:3060412416  NOTICE: GL: NPOT texture support detected
***22:25:53 T:2708468832   ERROR: Read - Error( -1, 22, Invalid argument ) - Retrying
***22:26:23 T:2708468832   ERROR: Read - Error( -1, 22, Invalid argument )
***22:26:53 T:2708468832   ERROR: Read - Error( -1, 22, Invalid argument ) - Retrying
22:28:46 T:2708468832  NOTICE: COMXPlayer::OnExit()
22:28:46 T:2708468832  NOTICE: OMXPlayer: eof, waiting for queues to empty
22:28:46 T:2708468832  NOTICE: OMXPlayer: closing audio stream
22:28:46 T:2708468832  NOTICE: Closing audio stream

If I play the file again it won't freeze, it seems to happen randomly. Any ideas on what's going wrong?


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - Milhouse - 2013-08-20

Maybe the new improved readrate buffering?

In fact can anyone explain how readbufferfactor is meant to work, is it still in conjunction with cachemembuffersize?

In the codec info window, is cachemembuffersize the initial value of vb: xxxx as whatever I set cachemembuffersize to in my advancedsettings.xml, it always starts off at 9830400.

Increasing or lowering readbufferfactor seems to have no effect on how much is read per second by my Pi (latest openelec-3.2 git build, 1GHz ARM, wired ethernet, XBMC NFS) as my Pi is reading between 2.1MB/s and 2.5MB/s when playing "Blade Runner - Final Cut" (VC1 video with codec license, Dolby Digital 5.1 audio selected although it also has a TrueHD track and three DD2.0 tracks). This movie buffers frequently but I actually think it buffered less (as in never, except when starting) with builds from a month or two ago.

I'd have expected the Pi to buffer more (ie. read more from the network) as the buffer began to run down, but no - it always reads roughly the same amount no matter what setting I specify and consequently it rapidly gets to a point where the buffer is empty and the movie stutters while it is refilled.

Edit1: Reverting to a build from Jul 5, I see the buffer increasing quite nicely while playing this same movie, with network traffic peaking noticeably higher (as high as 4.5MB/s), thus keeping the buffer filled with no buffering/stuttering. So somewhere in the last few weeks there has been a regression with respect to network buffering. Will roll forward through my builds and try to narrow it down...

Edit2: The buffering changes noticeably for the worse between the following two builds (from the openelec-3.2 branch):
Code:
OpenELEC-RPi.arm-devel-20130721181939-r15042 (Jun  6 2013 18:30:04 firmware)
OpenELEC-RPi.arm-devel-20130726174835-r15231 (Jul 22 2013 22:07:37 firmware)
The Jul 26 build buffers "Blade Runner" with seemingly capped network reads, which is what I still see today and so it rapidly exhausts the buffer.

It doesn't appear to be firmware related, as using the Jun 6 firmware with the Jul 26 build results in no obvious difference - the Jul 26 build with Jun 6 firmware continues to buffer with restricted network read rates. Anyone able to suggest a possible cause?

During these tests I've been using default OpenELEC advancedsettings.xml values, ie. cachemembuffersize: 20971520.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - Ned Scott - 2013-08-20

Cache buffer stuff explained: HOW-TO:Modify the cache (wiki)

Feel free to improve upon the explanations, as I only understand just a bit of what was said to me :)


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - Milhouse - 2013-08-20

Thanks Ned, if I understand it all correctly, then something isn't working right as builds since Jul 26 are much more prone to buffering than previous builds which had no buffering problems at all.

Edit: I notice that if I set <alwaysforcebuffer>1</alwaysforcebuffer> then I get a ~30MB cache in the codec info and very stuttery performance (but the buffer (B x%) is always much fuller, however the vq: x% doesn't remain high and often reaches 0). The default for alwaysforcebuffer would therefore seem to be 0, and in this case my cache is shown as "cache: 0", and this setting was fine on Jul 21 (both B: x% and vq: x% would be about 60%) but now since Jul 26 the default caching/buffering behaviour is not sufficient to prevent stuttering (B: x% and vq: x% both go to zero).


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - popcornmix - 2013-08-20

(2013-08-20, 03:40)spjonez Wrote: Had the freeze issue again tonight, no buffering or any other indicator on screen. File resumed after ~20s and did a fast forward / audio garble to catch up.
Did the stall coincide with one of these messages:
Quote:***22:25:53 T:2708468832 ERROR: Read - Error( -1, 22, Invalid argument ) - Retrying
I don't actually know where that comes from. It's not from omxplayer, but perhaps from network file reading code. Are you using nfs?
A full log (with debug enabled) when it happens may be useful.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - popcornmix - 2013-08-20

(2013-08-20, 03:45)MilhouseVH Wrote: Edit2: The buffering changes noticeably for the worse between the following two builds (from the openelec-3.2 branch):
Code:
OpenELEC-RPi.arm-devel-20130721181939-r15042 (Jun  6 2013 18:30:04 firmware)
OpenELEC-RPi.arm-devel-20130726174835-r15231 (Jul 22 2013 22:07:37 firmware)

That's a useful piece of information. Can you confirm that top of master is still in the "worse" state?
For my tests top of master is behaving well. I have a test sample (1080p dream sequence from Prometheus with software DTS decode) that failed to play at 1GHz on Frodo.
I've now got it playing at 400MHz on master, so there have been a lot of improvements, but there's probably something special with your file/network that has got worse.
It may be the large amount of audio data (you may not be playing the TrueHD stream, but it still gets read and discarded) that is provoking some different behaviour.

If you were able to narrow it down to a specific commit on master, that would be the most useful piece of information. It is something I would like to fix.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - Milhouse - 2013-08-20

(2013-08-20, 11:58)popcornmix Wrote: That's a useful piece of information. Can you confirm that top of master is still in the "worse" state?

I don't normally build out of master, give me a couple of hours and I'll try and put together a build.

(2013-08-20, 11:58)popcornmix Wrote: If you were able to narrow it down to a specific commit on master, that would be the most useful piece of information. It is something I would like to fix.

I'll see what I can do...


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - spjonez - 2013-08-20

(2013-08-20, 11:47)popcornmix Wrote: Did the stall coincide with one of these messages:
***22:25:53 T:2708468832 ERROR: Read - Error( -1, 22, Invalid argument ) - Retrying
Yes, those lines appear in the section for the file that froze and not in any of the other file sections.

(2013-08-20, 11:47)popcornmix Wrote: I don't actually know where that comes from. It's not from omxplayer, but perhaps from network file reading code. Are you using nfs?
A full log (with debug enabled) when it happens may be useful.
Using SMB. I want to switch to NFS but I don't have enough storage to pull everything from the drives, reformat, etc. I'll try to get a full log.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - popcornmix - 2013-08-20

(2013-08-20, 14:12)spjonez Wrote: Yes, those lines appear in the section for the file that froze and not in any of the other file sections.

If you google: "ERROR: Read - Error( -1, 22, Invalid argument ) - Retrying" site:forum.xbmc.org

you'll see it's quite common. I didn't find the cause, but a couple of posts reported the show up periodically (e.g. with exactly 5 minute intervals).
Yours seems to be separated by exactly one minute.

It feels like a network timeout (keepalive?) or disk spin down type delay, although you are playing a file so you'd expect disk and network to be busy.
Do you ever see it from a local file (e.g. played from USB stick?)


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - Milhouse - 2013-08-20

(2013-08-20, 11:58)popcornmix Wrote: That's a useful piece of information. Can you confirm that top of master is still in the "worse" state?

Not sure if it's good news or not, but top of master is still in the "worse" state, testing with the following settings:

Code:
<network>
    <cachemembuffersize>20971520</cachemembuffersize>
    <readbufferfactor>4.0</readbufferfactor>
<network>

When resuming Blade Runner Final Cut (DD5.1 audio selected), what follows is the codec info for the movie as playback resumes:

Image

I may be interpreting this incorrectly, but my understanding is that "B 0%" represents how full (or empty) the buffer is, with aq and vq similarly representing the audio and video queues. I have no idea what the "vb:" number represents, it tends to be all over the place, anywhere between 0 and 9830400.

Although the movie begins playing OK, after 10-20 seconds it stalls while the buffer fills (which is taking place in the stalled screenshot below):

Image

However, if the movie is started from the beginning (and not resumed) I see quite different results - the buffer will begin to fill from the very beginning which doesn't happen when resuming:

Image

and eventually the buffer will reach 100% (99% in the screenshot below):

Image

So there seems to be a basic difference in buffering behaviour when starting from the beginning and when resuming a movie (some movies, or just this movie) - is this important/relevant?

However, as the bit rate picks up in the "started from beginning" movie, the buffer will eventually run dry and playback stall while the buffer is refilled, so the readbufferfactor doesn't seem to be as effective as hoped, or isn't working for me as the network read rate is pretty much static with no obvious peaking, not even when the movie is stalled and the buffer is being filled. I would have expected to see more network reads as the buffer needs to be filled, and before it runs dry.

In the Jul 21 build, the buffer doesn't run dry and peaking of network traffic is evident (and with no stalling). I'll try and work back through master to see if I can narrow down the relevant commit(s) - it's gonna take a while...


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - popcornmix - 2013-08-20

(2013-08-20, 15:24)MilhouseVH Wrote: Not sure if it's good news or not, but top of master is still in the "worse" state, testing with the following settings:
Useful to know, rather than good/bad.

Quote:I may be interpreting this incorrectly, but my understanding is that "B 0%" represents how full (or empty) the buffer is, with aq and vq similarly representing the audio and video queues. I have no idea what the "vb:" number represents, it tends to be all over the place, anywhere between 0 and 9830400.

vb is space in the video fifo (to GPU). Small numbers are good, meaning it is full.
I think removing that (or replacing with a percentage) and changing aq/vq to report amount of data buffered by gpu in seconds would be more useful.
They are the values used to determine buffering. I'll tidy up the numbers reported.

Quote:However, if the movie is started from the beginning (and not resumed) I see quite different results - the buffer will begin to fill from the very beginning which doesn't happen when resuming:

Interesting, but nothing comes to mind why resuming would behaving differently than starting from beginning.
Does seeking forwards by 10 minutes result in the "resume" behaviour when file was initially started from beginning?
Does seeking to beginning result in the "beginning" behaviour if initially resumed from middle?

Quote:In the Jul 21 build, the buffer doesn't run dry and peaking of network traffic is evident (and with no stalling). I'll try and work back through master to see if I can narrow down the relevant commit(s) - it's gonna take a while...

Would be useful.
Currently I have no idea if this is an omxplayer issue, or if something has changed in generic xbmc code, or even something has changed in OpenELEC (like a library bump).
Finding the OpenELEC commit is the first step to identifying this. (git bisect may be helpful here).


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - Milhouse - 2013-08-20

(2013-08-20, 16:30)popcornmix Wrote: Does seeking forwards by 10 minutes result in the "resume" behaviour when file was initially started from beginning?

Yes - a big step forward (which seeks to about 3 minutes into the movie) results in playback with the codec info showing B 0%/vq: 0%/ vb: 9830400. Then 5-10 seconds afterwards a brief stall (maybe a stutter) occurs but no buffer fill, playback continues for another 5-10 seconds with vb bouncing around between 9830400 and about 7230000, and then a complete stall with vb dropping down to zero while the buffer fills to 100% before playback continues.

(2013-08-20, 16:30)popcornmix Wrote: Does seeking to beginning result in the "beginning" behaviour if initially resumed from middle?

Yes - seeking to 0:00:00 from another resume point results in the buffer filling immediately upon playback from the new seek position.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - popcornmix - 2013-08-20

(2013-08-20, 16:53)MilhouseVH Wrote: Yes - a big step forward (which seeks to about 3 minutes into the movie) results in playback with the codec info showing B 0%/vq: 0%/ vb: 9830400. Then 5-10 seconds afterwards a brief stall (maybe a stutter) occurs but no buffer fill, playback continues for another 5-10 seconds with vb bouncing around between 9830400 and about 7230000, and then a complete stall with vb dropping down to zero while the buffer fills to 100% before playback continues.

In the "bad" case, does the buffering occur once (or a small number of times) and then settle down?
Or does it buffer periodically throughout the movie?

I have tweaked the buffering logic to favour faster start time and seeking.

This deliberately sets the buffering threshold low, but with an exponential backout each time buffering occurs.
Typically you will get a few stutters in the first few seconds, but it should be permanently stable from then on (this is only reset on stopping that video).
The fact your video plays from beginning is probably because it starts with a low bit rate fade from black/static into logos.


RE: OpenELEC Testbuilds for RaspberryPi Part 2 - mike7 - 2013-08-20

(2013-08-20, 17:08)popcornmix Wrote: In the "bad" case, does the buffering occur once (or a small number of times) and then settle down?
Or does it buffer periodically throughout the movie?

I have the similar issue with raspbmc, it buffer periodically throughout the movie. Only files with TrueHD track (for me) are affected.
I post a sample clip test.mkv

Description and log in thread