v16 Frequent buffering, high bitrate video playback from SMB share to RPi3 with OSMC
#1
Question 
Hi,

I posted over on the OSMC forum to get ideas for what may be causing the issues I've experienced. I've found a way around it, by mounting the SMB share instead of adding it in Kodi. I would prefer if playing directly from an SMB share in Kodi would also work satisfactory. This is a cross-post, as it appears to be a Kodi issue more so than related to OSMC.
https://discourse.osmc.tv/t/freezing-stu...work/18160

Hardware: Raspberry Pi 3, with 2.4 A power supply.
Software: OSMC 2016.06-02 (Kodi 16.0)

Freshly installed, yesterday, on a SanDisk Mobile Ultra microSDHC 16 GB UHS-I (Class 10).

I'm having issues while playing certain movie files with very high variable bit rate video and audio via SMB. One particular file (http://paste.osmc.io/kuxikiyetu.tex) I attempt to play has (according to MediaInfo1 0.7.87) roughly 5 Mbps audio (TrueHD) (although OSMC overlay says closer to 9 Mbps), and h264 (x264, AVC) video at an average 20.1 Mbps (max 30 according to encoding parameters). I've enabled hardware decoding, which when there is data in the buffer makes the video and audio flow perfectly. (With software decoding it's not working as well, but that's another issue I may address in a separate post.)

The issue is that the buffer is not refilled fast enough. Slowly it is depleted (vq and aq drop down to 0%), video freezes, buffer starts to refill (vq and aq increase), and only once the buffer has refilled to 90+% (vq and aq) playback starts again.

The buffering happens with varying frequency. To me it appears to vary somewhat depending on the current measured bit rate of the video file. Often playback stops for buffering with between 30-90 second intervals.

Using bcmstat.sh (https://github.com/MilhouseVH/bcmstat) I see the RX rate is between 1.5-3.5 MB/s, with the occasional rare spike close to 5 MB/s. Testing file transfer independently from the servers on my network, I was able to saturate the 100 Mbps line to the RPi, so it's not a network issue. It is also not an issue with the share providing the video, as I am able to stream the same file to my Windows PC with no impact on the concurrent behavior on the Raspberry Pi. It continues to get stuck buffering as often as before.

I attempted to change readbufferfactor in the advancedsettings.xml, to no avail. This seem to be described also in other threads (https://discourse.osmc.tv/t/buffering-ev...onds/10758). I experience the same buffering freezes with readbufferfactor=4.0, readbufferfactor=8.0, and even readbufferfactor=80.0, and I believe this is to be expected when buffermode is not set explicitly to 1.
http://paste.osmc.io/enahusixof

I did further tests with buffermode=1 together with an increased cachemembuffersize (between 30-100 MB) and high readbufferfactor (between 4-16). Playback generally takes slightly longer to start, but buffers better and only stutter once in a while. bcmstat.sh shows spikes of 5-9 MB/s (depending somewhat on readbufferfactor). It still seem to be too slow sometimes, especially during first start of playback, or during seek, where it can take many seconds before playback gets going. And with these settings I also sometimes receive "cache full" popups, which according to some research (http://forum.kodi.tv/showthread.php?tid=216835) is more of an annoyance than a real problem itself.

Issue is circumvented by mounting the SMB share in the file system and adding the local folder to Kodi.
https://discourse.osmc.tv/t/freezing-stu...rk/18160/8


Is there a way to tune the speed at which Kodi loads data over an SMB share when the share is added via the Kodi interface?
Reply
#2
Thread moved to the Pi section
|Banned add-ons (wiki)|Forum rules (wiki)|VPN policy (wiki)|First time user (wiki)|FAQs (wiki) Troubleshooting (wiki)|Add-ons (wiki)|Free content (wiki)|Debug Log (wiki)|

Kodi Blog Posts
Reply
#3
(2016-08-02, 22:38)logan893 Wrote: Hi,

I posted over on the OSMC forum to get ideas for what may be causing the issues I've experienced. I've found a way around it, by mounting the SMB share instead of adding it in Kodi. I would prefer if playing directly from an SMB share in Kodi would also work satisfactory. This is a cross-post, as it appears to be a Kodi issue more so than related to OSMC.
https://discourse.osmc.tv/t/freezing-stu...work/18160

Hardware: Raspberry Pi 3, with 2.4 A power supply.
Software: OSMC 2016.06-02 (Kodi 16.0)

Freshly installed, yesterday, on a SanDisk Mobile Ultra microSDHC 16 GB UHS-I (Class 10).

I'm having issues while playing certain movie files with very high variable bit rate video and audio via SMB. One particular file (http://paste.osmc.io/kuxikiyetu.tex) I attempt to play has (according to MediaInfo1 0.7.87) roughly 5 Mbps audio (TrueHD) (although OSMC overlay says closer to 9 Mbps), and h264 (x264, AVC) video at an average 20.1 Mbps (max 30 according to encoding parameters). I've enabled hardware decoding, which when there is data in the buffer makes the video and audio flow perfectly. (With software decoding it's not working as well, but that's another issue I may address in a separate post.)

The issue is that the buffer is not refilled fast enough. Slowly it is depleted (vq and aq drop down to 0%), video freezes, buffer starts to refill (vq and aq increase), and only once the buffer has refilled to 90+% (vq and aq) playback starts again.

The buffering happens with varying frequency. To me it appears to vary somewhat depending on the current measured bit rate of the video file. Often playback stops for buffering with between 30-90 second intervals.

Using bcmstat.sh (https://github.com/MilhouseVH/bcmstat) I see the RX rate is between 1.5-3.5 MB/s, with the occasional rare spike close to 5 MB/s. Testing file transfer independently from the servers on my network, I was able to saturate the 100 Mbps line to the RPi, so it's not a network issue. It is also not an issue with the share providing the video, as I am able to stream the same file to my Windows PC with no impact on the concurrent behavior on the Raspberry Pi. It continues to get stuck buffering as often as before.

I attempted to change readbufferfactor in the advancedsettings.xml, to no avail. This seem to be described also in other threads (https://discourse.osmc.tv/t/buffering-ev...onds/10758). I experience the same buffering freezes with readbufferfactor=4.0, readbufferfactor=8.0, and even readbufferfactor=80.0, and I believe this is to be expected when buffermode is not set explicitly to 1.
http://paste.osmc.io/enahusixof

I did further tests with buffermode=1 together with an increased cachemembuffersize (between 30-100 MB) and high readbufferfactor (between 4-16). Playback generally takes slightly longer to start, but buffers better and only stutter once in a while. bcmstat.sh shows spikes of 5-9 MB/s (depending somewhat on readbufferfactor). It still seem to be too slow sometimes, especially during first start of playback, or during seek, where it can take many seconds before playback gets going. And with these settings I also sometimes receive "cache full" popups, which according to some research (http://forum.kodi.tv/showthread.php?tid=216835) is more of an annoyance than a real problem itself.

Issue is circumvented by mounting the SMB share in the file system and adding the local folder to Kodi.
https://discourse.osmc.tv/t/freezing-stu...rk/18160/8


Is there a way to tune the speed at which Kodi loads data over an SMB share when the share is added via the Kodi interface?

Well done on taking the time to test mounting outside of Kodi.

SMB has a lot of protocol overhead, NFS is a lot more lightweight. SMB in Kodi uses libsmbclient (a userspace implementation of SMB/CIFS). A kernel based fstab mount will yield more performance. Similarly, if you use NFS, libnfs (the user space implementation) often yields lower throughput than the kernel implementation counterpart. This is particularly notable on lower powered platforms, although for Pi, it's certainly not as bad as it was many years ago.

You can tweak buffering values in Kodi with advancedsettings.xml. But you could also mount the shares via fstab which will be more reliable and give you better performance. But this isn't really a Kodi problem, nor an OSMC one. The performance of your network shares will depend on how they are mounted on the system. This is also the same for USB disks (whether they run through FUSE or they're handled by a kernel module).
Reply
#4
With default network buffering settings in OSMC (including advancedsettings.xml), Kodi does not use this additional buffer for playback via SMB.

Also, I do not buy that this is a performance issue with RPi3 and SMB. I can consistently download files over SMB via command line tool smbclient at 11 MB/s, stressing no more than a single core at 30% CPU usage. top reports system at above 80% idle. Video playback of this test material, even with software rendering, does not consume much CPU, and this is including the CPU used by the internal libsmbclient transfer.

When I do enable the additional network buffering for SMB via buffermode=1 in advancedsettings.xml, I can also tweak the readbufferfactor parameter but this still does not result in acceptable performance. Perhaps this is due to the variable bit rate of the video. I've not found any way to tweak a setting such as this without enabling this additional buffering for SMB. CPU usage is still low in this scenario.

Code:
Time         ARM    Core    H264 Core Temp (Max)  IRQ/s     RX B/s     TX B/s
======== ======= ======= ======= =============== ====== ========== ==========
10:29:21 1200Mhz  400Mhz  300Mhz 61.76C (62.84C) 12,644 12,186,760    378,845
10:29:23 1199Mhz  400Mhz  300Mhz 62.30C (62.84C) 12,645 12,184,496    368,696
10:29:25 1200Mhz  400Mhz  300Mhz 62.30C (62.84C) 12,716 12,178,938    373,771
10:29:27 1199Mhz  400Mhz  300Mhz 62.30C (62.84C) 12,663 12,183,483    369,366
10:29:29 1200Mhz  400Mhz  300Mhz 62.30C (62.84C) 11,835 11,390,472    343,754
10:29:31 1200Mhz  400Mhz  300Mhz 62.30C (62.84C) 12,662 12,177,827    369,024

Code:
smb: \tcpdump\> get tcpdump.0018.pcap
getting file \tcpdump\tcpdump.0018.pcap of size 3129995694 as tcpdump.0018.pcap (11057.0 KiloBytes/sec) (average 11058.6 KiloBytes/sec)

An additional issue I ran into when testing this using software rendering instead of hardware rendering is that when the buffer empties and playback stops momentarily, I see one CPU core spike at 100% (with the other three remaining close to 0%), and playback begins to slow down and stutter extremely, and never recovers. I really should record a short video to demonstrate this. It does not happen this way when hardware rendering is enabled. (I have not yet collected debug log output from this scenario.)
Reply
#5
I have not yet found my way around the Kodi source code, but I ran across the SMBFile.cpp code which limits reads to 65534 (64k-2) bytes per CSMBFile::Read request. Depending on how this is called when additional caching is not used it may introduce quite a lot of overhead, and could be the cause of my buffering issues.


Would it be possible to enhance the CSMBFile::Read function to honor the uiBufSize parameter more by issuing multiple smbc_read requests, for the sake of SMB performance? Up to 2-4 sequential calls to smbc_read (if allowed by the size of the uiBufSize parameter) would possibly sufficiently enhance the video buffering, without introducing adverse side effects.
Reply
#6
It looks like this buffer size is set for compatibility reasons with some SMB servers.

You could patch this and see if it improves the situation.

Create a diff,
git clone https://github.com/osmc/osmc.
Drop the patch in as all-099-change-smb-buffer.patch in package/mediacenter-osmc/patches.
cd package/mediacenter-osmc
type 'make rbp2' and Kodi will build with this patch.
dpkg -i rbp2-mediacenter-osmc.deb afterwards and reboot
Reply
#7
Thanks for the quick walk-through, Sam.

I built a crude patch to call smbc_read up to 2 times, for a maximum of 131068 bytes (128k-4) per call to CSMBFile::Read. Patch applied successfully and it's configuring now, compiling soon. It'll take a while as I am running this from the RPi3 itself.

Code:
Applying patch all-099-change-smb-buffer.patch
(Stripping trailing CRs from patch; use --binary to disable.)
patching file xbmc/filesystem/SMBFile.cpp

Contents of all-099-change-smb-buffer.patch:
http://paste.osmc.io/lasehibeqa.diff
Reply
#8
It just compiled the file without errors, but with a warning. Still some time to go.
Code:
CPP     xbmc/filesystem/SMBFile.o
CPP     xbmc/music/MusicInfoLoader.o
CPP     xbmc/music/tags/MusicInfoTagLoaderDatabase.o
SMBFile.cpp: In member function 'virtual ssize_t XFILE::CSMBFile::Read(void*, size_t)':
SMBFile.cpp:538:13: warning: pointer of type 'void *' used in arithmetic [-Wpointer-arith]
       lpBuf += bytesRead;
             ^

There's for sure a better way to do this. My C++ is rusty. Smile

Would this be preferable?
Code:
lpBuf = static_cast<char *>(lpBuf) + bytesRead;
Reply
#9
(2016-08-03, 17:27)logan893 Wrote: Would this be preferable?

Yes. Arithmetic on (void *) pointers in undefined, but gcc is quite tolerant and its behaviour is the one you would expect.
No guarantees that a different compiler would accept this code.

Casting to (char *) or using an additional (char *) pointer to do the arithmetic on are valid options.
Reply
#10
Updated "read 64k-2 twice" patch with static_cast<char *>: http://paste.osmc.io/ahizumujof.diff

Unfortunately the slow data pull situation has not changed, and video keeps freezing and buffering. If anything it is behaving worse.

I'll try again, this time removing the loop and 64k limit altogether.

Patch removing "64k-2" read limit: http://paste.osmc.io/awepenoyes.avrasm

I hope this works better. Compiling will take a while.

On the off chance that it still does not work, is there a way I can tune the video queue read-ahead (which I believe is based on the bit rate in some way), similar to what readbufferfactor does for the optional memory cache?
Reply
#11
I think that is dead code to an extent. I was digging in to CSMBFile with Samba 4.x changes recently. I'd remove the read limit, and tweak:

fprintf(f, "\tsocket options = TCP_NODELAY IPTOS_LOWDELAY SO_RCVBUF=65536 SO_SNDBUF=65536\n");

When you recompile, be sure to sudo systemctl stop mediacenter and rm -rf ~./kodi/.smb.

We use ccache in OSMC build system, and I made a few improvements on that front lately, so compiles shouldn't be too painful. About an hour with a good SD card on a Pi 3. Use CLog::Log(LOGINFO, ....) to print any useful info, perhaps uiBufSize. The function is variadic so treat it like printf. The output will go to ~/.kodi/temp/kodi.log
Reply
#12
How would you tweak it in addition to the current settings? My line already contains the same data as you posted.
fprintf(f, "\tsocket options = TCP_NODELAY IPTOS_LOWDELAY SO_RCVBUF=65536 SO_SNDBUF=65536\n");

Increase receive buffer to 131072? Anything in addition to this?

Patch to read the full uiBufSize, printing the size of uiBufSize as INFO log, and increase send and receive buffer parameters by factor 2: http://paste.osmc.io/ajazetetas.tex
Reply
#13
Yes, I would tweak those values. I think 1MB would be a good value to try.

+1 for using our pastebin.
Reply
#14
Unfortunately it did not help to remove the limit. Video is still buffering a lot. And logging shows calls to the function are almost always below the 64k mark, so this patch has little effect.

Instead the Read function is called in bursts, often with 1-2 seconds in between.
Debug logs: http://paste.osmc.io/kepifejesa

In the log, I play both from SMB, and at 07:35:35 I switch to the the same file via fstab mounted SMB share (which plays perfectly as always).
I also noticed that start of playback of file via SMB was not in the log, so I did a quick one for that. See 07:47:37.

Code:
07:24:35 548.694153 T:1521480688    INFO: Read - reading 59925 bytes (uiBufSize)
07:24:35 548.700928 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 548.705078 T:1521480688    INFO: Read - reading 39159 bytes (uiBufSize)
07:24:35 548.709778 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 548.713806 T:1521480688    INFO: Read - reading 41420 bytes (uiBufSize)
07:24:35 548.718811 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 548.722778 T:1521480688    INFO: Read - reading 42759 bytes (uiBufSize)
07:24:35 548.770142 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:35 548.771423 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 548.800903 T:1956303792   DEBUG: CMMALRenderer::FlipPage - not configured: source:1
07:24:35 548.801025 T:1956303792   DEBUG: CMMALRenderer::ReleaseBuffer - bypass: source:2
07:24:35 548.801147 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 548.966797 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:35 548.968201 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 548.991150 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 548.995300 T:1521480688    INFO: Read - reading 42644 bytes (uiBufSize)
07:24:35 549.000183 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.024658 T:1521480688    INFO: Previous line repeats 2 times.
07:24:35 549.024963 T:1521480688    INFO: Read - reading 97988 bytes (uiBufSize)
07:24:35 549.034790 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.038940 T:1521480688    INFO: Read - reading 67348 bytes (uiBufSize)
07:24:35 549.070374 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:35 549.071716 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 549.174316 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:35 549.175842 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 549.278137 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:35 549.279663 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 549.309875 T:1956303792   DEBUG: CMMALRenderer::FlipPage - not configured: source:0
07:24:35 549.309998 T:1956303792   DEBUG: CMMALRenderer::ReleaseBuffer - bypass: source:1
07:24:35 549.310181 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:35 549.311646 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.316101 T:1521480688    INFO: Read - reading 44976 bytes (uiBufSize)
07:24:35 549.321411 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.325256 T:1521480688    INFO: Read - reading 45792 bytes (uiBufSize)
07:24:35 549.330322 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.334229 T:1521480688    INFO: Read - reading 53493 bytes (uiBufSize)
07:24:35 549.340332 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.344177 T:1521480688    INFO: Read - reading 43586 bytes (uiBufSize)
07:24:35 549.349243 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.355530 T:1521480688    INFO: Read - reading 90507 bytes (uiBufSize)
07:24:35 549.364929 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.371277 T:1521480688    INFO: Read - reading 209479 bytes (uiBufSize)
07:24:35 549.390625 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.412964 T:1521480688    INFO: Previous line repeats 2 times.
07:24:35 549.413147 T:1521480688    INFO: Read - reading 82865 bytes (uiBufSize)
07:24:35 549.421692 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:35 549.429016 T:1521480688    INFO: Previous line repeats 1 times.
07:24:35 549.429199 T:1521480688    INFO: Read - reading 47773 bytes (uiBufSize)
07:24:36 549.434326 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:36 549.458679 T:1521480688    INFO: Previous line repeats 3 times.
07:24:36 549.458923 T:1521480688    INFO: Read - reading 78150 bytes (uiBufSize)
07:24:36 549.466919 T:1521480688    INFO: Read - reading 32768 bytes (uiBufSize)
07:24:36 549.474487 T:1521480688    INFO: Previous line repeats 1 times.
07:24:36 549.474792 T:1521480688    INFO: Read - reading 37337 bytes (uiBufSize)
07:24:36 549.501831 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:36 549.503174 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:36 549.605042 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:36 549.606262 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0
07:24:36 549.707947 T:1956303792   DEBUG: CMMALRenderer::Update
07:24:36 549.709167 T:1956303792   DEBUG: CMMALRenderer::RenderUpdate - bypass: clear:0 flags:0 alpha:255 source:0

Basically then what it comes down to is that the render isn't requesting or pulling data fast enough. It's acting too conservative compared with when playing from "local storage" (SMB share mounted via fstab entry).

Are there any other ways to boost the rate at which the render pulls data via SMB?
Reply
#15
I think the real difference is OS mounts will read ahead.
E.g. if read buffer size is set to 64K, and application reads 1K at a time, then on first read it will read 64K, and next 63 reads will just get cached data without any network traffic.
That is obviously more efficient. I'm guessing libsmb doesn't do that.
Reply

Logout Mark Read Team Forum Stats Members Help
Frequent buffering, high bitrate video playback from SMB share to RPi3 with OSMC0