Advancedsettings.xml not recognized since September update and default video cache inquiry

tonic · 1 October 2022 21:52

Hello OSMC crew. I’m back again with some odd behavior I’m seeing since applying the latest September update to Bullseye. Ever since I got the Vero 4K+ it’s always had some kind of buffering issue with 4K video. To circumvent this, I increased the video cache in the advancedsettings.xml and everything played smoothly, regardless if it was a 4K video from my NAS or youtube. However, with the latest update it seems to have come back again and from what I can tell so far, my advancedsettings.xml doesn’t even seem to be effective anymore. It’s an elusive issue but enough to be annoying and I did happen to capture it live while in debug mode. Basically what’s happening is the video will start to stutter and then freeze completely. A couple minutes go by and it begins to show the buffer icon at 1…2…3 and then starts playing again.

My suspicion is that the Vero is not buffering high res videos enough, hence the need to modify advancedsettings.xml. I am curious to know what the default video cache values are for each video resolution? Is it enough?

Here is my advancedsettings.xml that was working great prior to the update:

<advancedsettings>
  	<cache>
	        <buffermode>1</buffermode>
	        <memorysize>999999999</memorysize>
		<readfactor>20</readfactor>
	</cache>
</advancedsettings>

Now it seems that it’s not honoring the advancedsettings.xml at all. Here’s the weird part though. Prior to the September update, I would always see a significant buffer bar when 1080P video was being played and also a small buffer bar with 4K. Now with the latest update, I see no buffer bar at all. Please see the attached images. Both are the same 1080P video. In the 1080p_without_advanced_settings.jpg you can see a significant buffer bar ahead of playback however in the 1080p_with_advanced_settings.jpg you can see no buffer bar whatsoever. Originally I was thinking, huh, guess I don’t need my advancedsettings.xml anymore, but alas the playback of 4K video is hit or miss.

Below are some interesting snippets from the debug log for a 4K video when the buffering issue occurred without advancedsettings.xml enabled. I can see the audio stream being paused with “packet too big” errors following:

2022-10-01 11:24:04.919 T:2941    DEBUG <general>: ------ Window Deinit (DialogBusy.xml) ------
2022-10-01 11:24:04.941 T:2956    DEBUG <general>: ActiveAE::SyncStream - average error of 37.740417, start adjusting
2022-10-01 11:24:04.941 T:2956    DEBUG <general>: ActiveAE::SyncStream - average error 0.740417 below threshold of 30.000000
2022-10-01 11:24:05.869 T:2959    DEBUG <general>: CEGLNativeTypeAmlogic: Detected HDMI switch
2022-10-01 11:24:05.972 T:7519    DEBUG <general>: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-28811.615209, adjusted:-41708.333333
2022-10-01 11:24:09.696 T:7517    DEBUG <general>: CPtsTracker: detected pattern of length 1: 41708.24, frameduration: 41708.333333
2022-10-01 11:24:34.888 T:7510    DEBUG <general>: Thread JobWorker 3247423744 terminating (autodelete)
2022-10-01 11:24:34.889 T:7511    DEBUG <general>: Thread JobWorker 3227963648 terminating (autodelete)
2022-10-01 11:26:36.546 T:7517    DEBUG <general>: CVideoPlayerVideo - Stillframe detected, switching to forced 23.976024 fps
2022-10-01 11:26:36.546 T:7517    DEBUG <general>: CPtsTracker: pattern lost on diff 208541.666667, number of losses 1
2022-10-01 11:26:36.546 T:7517    DEBUG <general>: CVideoPlayerVideo - Stillframe left, switching to normal playback
2022-10-01 11:26:36.769 T:7519     INFO <general>: CVideoPlayerAudio::Process - stream stalled pts:151.694 clock:151.696 
2022-10-01 11:26:36.852 T:7514    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2022-10-01 11:26:36.853 T:7519    DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2022-10-01 11:26:36.856 T:7517    DEBUG <general>: AMLInsecureVideoCodec::SetSpeed, speed(0)
2022-10-01 11:26:44.260 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:26:54.261 T:7517    ERROR <general>: Skipped 5957 duplicate messages..
2022-10-01 11:26:54.261 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:27:04.262 T:7517    ERROR <general>: Skipped 6025 duplicate messages..
2022-10-01 11:27:04.262 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:27:14.263 T:7517    ERROR <general>: Skipped 5882 duplicate messages..
2022-10-01 11:27:14.263 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:27:24.264 T:7517    ERROR <general>: Skipped 5972 duplicate messages..
2022-10-01 11:27:24.264 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:27:34.264 T:7517    ERROR <general>: Skipped 6058 duplicate messages..
2022-10-01 11:27:34.264 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:27:37.887 T:7514    DEBUG <general>: Skipped 2149 duplicate messages..
2022-10-01 11:27:37.887 T:7514    DEBUG <general>: Readrate 3015000 is too low with 3798049 required
2022-10-01 11:27:37.888 T:7514    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2022-10-01 11:27:37.888 T:7519    DEBUG <general>: Skipped 1 duplicate messages..
2022-10-01 11:27:37.888 T:7519    DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2022-10-01 11:27:37.888 T:7519    DEBUG <general>: CDVDAudio::Resume - resume audio stream
2022-10-01 11:27:37.894 T:2956    DEBUG <general>: ActiveAE - start sync of audio stream
2022-10-01 11:27:37.896 T:2957     INFO <general>: CActiveAESink::OpenSink - initialize sink
2022-10-01 11:27:37.896 T:2957    DEBUG <general>: CActiveAESink::OpenSink - trying to open device ALSA:default
2022-10-01 11:27:37.896 T:2957     INFO <general>: CAESinkALSA::Initialize - Requested layout: FL, FR, FC, LFE, BL, BR, SL, SR
2022-10-01 11:27:37.896 T:2957     INFO <general>: CAESinkALSA::Initialize - set digital_codec 0
2022-10-01 11:27:37.896 T:2957    DEBUG <general>: CAESinkALSA::Initialize -- unmuting HDMI
2022-10-01 11:27:37.897 T:2957     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "default"
2022-10-01 11:27:37.898 T:7514    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2022-10-01 11:27:37.903 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted
2022-10-01 11:27:37.903 T:7517    DEBUG <general>: AMLInsecureVideoCodec::SetSpeed, speed(1000)
2022-10-01 11:27:37.903 T:7517    ERROR <general>: AMLInsecureVideoCodec::addData: packet too big: 212337, probably corrupted

Additionally, here are iperf results from my NAS to the vero:

***Vero iperf***

osmc@vero:~$ iperf -s -w 2m
------------------------------------------------------------
Server listening on TCP port 5001
TCP window size:  416 KByte (WARNING: requested 1.91 MByte)
------------------------------------------------------------
[  4] local 192.168.2.72 port 5001 connected with 192.168.2.37 port 19501
[ ID] Interval       Transfer     Bandwidth
[  4]  0.0-30.0 sec   463 MBytes   129 Mbits/sec



***TrueNAS iperf***


root@truenas[~]# iperf -c 192.168.2.72 -w 2m -t 30s -i 1s
Invalid value of '1s' for -i interval
------------------------------------------------------------
Client connecting to 192.168.2.72, TCP port 5001
TCP window size: 96.8 KByte (WARNING: requested 1.91 MByte)
------------------------------------------------------------
[  3] local 192.168.2.37 port 35448 connected with 192.168.2.72 port 5001
[ ID] Interval       Transfer     Bandwidth
[  3]  0.0- 1.0 sec  15.9 MBytes   133 Mbits/sec
[  3]  1.0- 2.0 sec  14.1 MBytes   118 Mbits/sec
[  3]  2.0- 3.0 sec  15.0 MBytes   126 Mbits/sec
[  3]  3.0- 4.0 sec  13.8 MBytes   115 Mbits/sec
[  3]  4.0- 5.0 sec  15.4 MBytes   129 Mbits/sec
[  3]  5.0- 6.0 sec  14.1 MBytes   118 Mbits/sec
[  3]  6.0- 7.0 sec  14.6 MBytes   123 Mbits/sec
[  3]  7.0- 8.0 sec  13.4 MBytes   112 Mbits/sec
[  3]  8.0- 9.0 sec  13.0 MBytes   109 Mbits/sec
[  3]  9.0-10.0 sec  13.5 MBytes   113 Mbits/sec
[  3] 10.0-11.0 sec  12.8 MBytes   107 Mbits/sec
[  3] 11.0-12.0 sec  12.0 MBytes   101 Mbits/sec
[  3] 12.0-13.0 sec  14.2 MBytes   120 Mbits/sec
[  3] 13.0-14.0 sec  12.8 MBytes   107 Mbits/sec
[  3] 14.0-15.0 sec  14.9 MBytes   125 Mbits/sec
[  3] 15.0-16.0 sec  12.8 MBytes   107 Mbits/sec
[  3] 16.0-17.0 sec  13.0 MBytes   109 Mbits/sec
[  3] 17.0-18.0 sec  14.0 MBytes   117 Mbits/sec
[  3] 18.0-19.0 sec  13.8 MBytes   115 Mbits/sec
[  3] 19.0-20.0 sec  13.4 MBytes   112 Mbits/sec
[  3] 20.0-21.0 sec  15.0 MBytes   126 Mbits/sec
[  3] 21.0-22.0 sec  14.0 MBytes   117 Mbits/sec
[  3] 22.0-23.0 sec  15.1 MBytes   127 Mbits/sec
[  3] 23.0-24.0 sec  14.0 MBytes   117 Mbits/sec
[  3] 24.0-25.0 sec  14.9 MBytes   125 Mbits/sec
[  3] 25.0-26.0 sec  13.9 MBytes   116 Mbits/sec
[  3] 26.0-27.0 sec  15.2 MBytes   128 Mbits/sec
[  3] 27.0-28.0 sec  14.0 MBytes   117 Mbits/sec
[  3] 28.0-29.0 sec  15.4 MBytes   129 Mbits/sec
[  3] 29.0-30.0 sec  13.9 MBytes   116 Mbits/sec

Hopefully this is enough info to investigate! Thanks OSMC team!

sam_nazarko · 2 October 2022 00:54

Hi,

I need some more information. How is your Vero connected to the network? Is it a 4K or 4K+?

Full logs would help, but to me it looks like a WiFi connected device which is causing your issue. Have you tried with Ethernet connected directly?

There shouldn’t be any need to adjust advancedsettings.xml. Have you tried without adjustments?

Which version of OSMC did you upgrade from?
What protocol are you using to stream a file?

darwindesign · 2 October 2022 04:08

I think that setting the size with a bunch of 9’s got broken or depreciated in Kodi quite some time back and makes it not work at all. The default size set on the Vero is actually quite large (the Vero’s use custom cache settings) and though testing that was previously done by myself and others found a cache setting larger than stock has a negative effect. Additionally a large read factor can cause negative performance impact as well. To compound the problem testing is actually quite tricky as some settings may help with one file but have a negative effect in others. Playing the same file back to back sometimes gives different results. IMO if someone was able to find more optimized settings for their particular configuration it will much more likely be by setting it lower, maybe even all the way back to Kodi stock if your using a system mount by using…

<advancedsettings>
  	<cache>
		<memorysize/>
		<readfactor/>
	</cache>
</advancedsettings>

tonic · 2 October 2022 23:02

Hey Sam!

I am connected to a Ubiquiti U6-lite wireless AP, 5 GHz, WiFi 5. This is a 4K+.

I tried uploading the full debug capture of kodi.log but it exceeded the character limit. Regardless, I uploaded all logs here - https://paste.osmc.tv/agudijelov

I unfortunately don’t have the luxury of connecting directly as the router is in the adjacent room and I don’t want to run a 50+ foot cable. This brings up a more important question. Is the vero not capable of handling UHD local network streaming via WiFi? Even with my current bandwidth reported by iperf? If so, that’s a deal breaker for me but as mentioned in my original post, everything was working flawless prior to the September update.

Yes, per my original post I provided examples with and without the advancedsettings.xml. The freezing/buffering occurs primarily with 4K content with or without advancedsettings.xml.

Whatever the latest version was prior to the September update, I’m not exactly sure. I do have auto updates enabled. I am using the NFS protocol to stream content from a NAS.

Thanks

sam_nazarko · 2 October 2022 23:22

It is, but with Unifi AC Lite, I see 200Mbps in each direction. 110Mbits is a bit slow and just under the UHD BD spec.

Can you ping the router from OSMC and see if the ping fluctuates?

We don’t have automatic updating – but I’ll assume you’ve been pressing OK to install them when prompted.

Are those NFS shares mounted via Kodi? You’ll get a bit more performance with autofs or a kernel based (fstab) mount.

tonic · 3 October 2022 14:08

Just to clarify Sam, I do not have an AC Lite access point. I have a U6 Lite which is significantly better than the AC series - Access Point WiFi 6 Lite - Ubiquiti Store United States

Regardless, I would think that 110Mbps would be more than sufficient for an x265 encoded video. And my iperf stats are exceeding this.

I sent 200 ping packets to the router and the results are below. Please note this is during high traffic hours when the whole family is on the network. This is not the case at night when watching a movie:

200 packets transmitted, 200 packets received, 0% packet loss
round-trip min/avg/max = 1.641/2.096/3.977 ms

That’s correct

NFS is mounted via fstab with the following config:

192.168.2.37:/mnt/NAS_tank/NFS	/mnt/NFS_mount	nfs	noauto,x-systemd.automount  0  0

Thanks

sam_nazarko · 3 October 2022 23:05

That’s my point – I can get double your throughput… So something isn’t quite right there.

It would be good to see full logs.

Sam

tonic · 3 October 2022 23:42

Understood. Can you please clarify what you mean by full logs? I’ve already posted the link created by OSMC (https://paste.osmc.tv/agudijelov). Are you wanting my kodi.log debug capture when the issue occurred? If so, I’ll need another medium to upload as it exceeds the character limit.

Thanks

sam_nazarko · 4 October 2022 01:16

Please enable debugging, reboot the system, and once the problem is reproduced, upload the logs. If you do this on a fresh boot, it shouldn’t exceed the limit.

tonic · 4 October 2022 15:35

@sam_nazarko,

I changed the 5 Ghz channel width to 80 Mhz and set the transmit power to high. This doubled my iperf results. I will leave as is and let you know if I encounter anymore issues.

Thanks!

sam_nazarko · 4 October 2022 15:43

Glad to hear. Keep me posted.