Occassional caching and buffering, Pi4, 1080p source, 1080p output, 1Gbit ethernet, confused.

Does anyone smart people have any idea how to identify the cause?

I have mounted a folder on my NAS and copied 300MB of files on to the /tmp directory. It did it in under 10 seconds, easily 30MB/s

I also copied back at the same speed.

The file which caused it this time is the following: (it's not even 265! it's 264)

2flZtng.png

(10.8GB, 95 minutes, approximately 113MB per minute or as little as 2MBytes per second needed!)

I'm also a lowly 1080p user, 1080p files, 1080p television so I dunno!

Here is some random pics of top while it's playing back:

GdrTFgK.png

bu72WFa.png

JP5ITh8.png

So I'm not sure what the problem is, it's very random!

I use subtitles always, not hardcoded, so I guess that might introduce a small amount of processing.

This problem is wildly random by the way.

I will consider loading files to USB stick and testing but the problem is, you can watch a movie or tv show for 20+ minutes before it does it. (so this is particularly awkward to do!)

Anyone got some tips? I mean maybe it's just my NAS being busy at the time but I don't think it is (I've tried reducing that and SURELY video playback doesn't need more than 5 or 10MB/s)

Can I incease the network buffer significantly? I have a 4GB Pi, happy to blow 500MB memory on it!

Thank you all.

One more thing for the super smart folks who actually make LibreElec (??) is there a way to LOG 'caching events' somehow? So I can play a video back, walk away and check the log, so I don't have to watch the thing, to know if it occurred? It would help a lot.

Final pics - I feel like it's the Pi - or my config, not the network, not the NAS - but would love the smarter people to help (Chewitt?)

Note the processor usage on a Pi3B+

4vk3bmh.png

vs a Pi 4

Ww1BCUM.png

I gotta fix this, it's taken years of work to make the wife not hate Kodi!!

This is in the kodi.log file for the Pi4

Quote

2021-07-04 11:39:27.400 T:2418008944 NOTICE: Creating InputStream

2021-07-04 11:39:27.515 T:2418008944 NOTICE: Creating Demuxer

2021-07-04 11:39:27.765 T:2418008944 NOTICE: Opening stream: 0 source: 256

2021-07-04 11:39:27.766 T:2418008944 NOTICE: Whitelist search for: width: 1920, height: 1040, fps: 23.976, 3D: false

2021-07-04 11:39:27.766 T:2418008944 NOTICE: Display resolution ADJUST : 1920x1080 @ 23.976025 Hz (21) (BANNEDWORDWAIT: 0.000)

2021-07-04 11:39:27.928 T:3011351136 NOTICE: VideoPlayer: OnLostDisplay received

2021-07-04 11:39:27.928 T:3011351136 WARNING: CDVDMessageQueue(audio)::Put MSGQ_NOT_INITIALIZED

2021-07-04 11:39:27.928 T:3011351136 WARNING: CDVDMessageQueue(video)::Put MSGQ_NOT_INITIALIZED

2021-07-04 11:39:27.957 T:3011351136 NOTICE: VideoPlayer: OnResetDisplay received

2021-07-04 11:39:27.957 T:3011351136 WARNING: CDVDMessageQueue(audio)::Put MSGQ_NOT_INITIALIZED

2021-07-04 11:39:27.957 T:3011351136 WARNING: CDVDMessageQueue(video)::Put MSGQ_NOT_INITIALIZED

2021-07-04 11:39:27.959 T:2418008944 NOTICE: Creating video codec with codec id: 27

2021-07-04 11:39:27.978 T:2418008944 NOTICE: Creating video thread

2021-07-04 11:39:27.979 T:2418008944 NOTICE: Opening stream: 2 source: 256

2021-07-04 11:39:27.979 T:2418008944 NOTICE: Finding audio codec for: 86056

2021-07-04 11:39:27.980 T:2418008944 NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder eac3

2021-07-04 11:39:27.981 T:2418008944 NOTICE: Creating audio thread

2021-07-04 11:39:27.981 T:2392830832 NOTICE: running thread: CVideoPlayerAudio::Process()

2021-07-04 11:39:27.981 T:2418008944 NOTICE: Opening stream: 0 source: 1024

2021-07-04 11:39:27.983 T:2459689840 NOTICE: running thread: video_thread

2021-07-04 11:39:28.128 T:2392830832 NOTICE: Creating audio stream (codec id: 86056, channels: 6, sample rate: 48000, no pass-through)

2021-07-04 11:39:28.433 T:3011351136 NOTICE: Whitelist search for: width: 1920, height: 1040, fps: 23.976, 3D: false

2021-07-04 11:39:28.433 T:3011351136 NOTICE: Display resolution ADJUST : 1920x1080 @ 23.976025 Hz (21) (BANNEDWORDWAIT: 0.000)

2021-07-04 11:39:28.887 T:2459689840 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

2021-07-04 11:57:41.931 T:2459689840 WARNING: Previous line repeats 180 times.

2021-07-04 11:57:41.931 T:2459689840 WARNING: CMMALVideo::GetPicture - ret(0) pics(0) inputs(0) slept(500) queued(0.29) (997.41:997.12) >

2021-07-04 11:57:43.965 T:2459689840 WARNING: Previous line repeats 3 times.

2021-07-04 11:57:43.965 T:2459689840 WARNING: CMMALVideo::GetPicture - ret(0) pics(0) inputs(0) slept(500) queued(0.50) (997.62:997.12) >

2021-07-04 11:57:49.756 T:2392830832 WARNING: Previous line repeats 11 times.

2021-07-04 11:57:49.757 T:2392830832 NOTICE: CVideoPlayerAudio::Process - stream stalled

2021-07-04 11:57:49.980 T:2459689840 WARNING: CMMALVideo::GetPicture - ret(0) pics(0) inputs(0) slept(500) queued(0.50) (997.62:997.12) >

2021-07-04 11:57:58.946 T:2459689840 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

2021-07-04 11:58:28.239 T:2459689840 WARNING: Previous line repeats 19 times.

2021-07-04 11:58:28.239 T:2459689840 WARNING: CRenderManager::AddVideoPicture - timeout waiting for render

2021-07-04 11:58:28.686 T:2459689840 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

2021-07-04 11:58:29.744 T:2459689840 WARNING: Previous line repeats 1 times.

2021-07-04 11:58:29.744 T:2459689840 WARNING: CRenderManager::AddVideoPicture - timeout waiting for render

2021-07-04 11:58:30.106 T:2459689840 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

2021-07-04 11:58:31.274 T:2459689840 WARNING: CRenderManager::AddVideoPicture - timeout waiting for render

2021-07-04 11:58:34.939 T:2459689840 WARNING: Previous line repeats 3 times.

2021-07-04 11:58:34.939 T:2459689840 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

2021-07-04 11:58:40.212 T:2988364656 WARNING: Previous line repeats 1 times.

2021-07-04 11:58:40.212 T:2988364656 WARNING: ActiveAE - large audio sync error: -89402.073884

Display More

and here's the Pi3 for the same duration

Quote

2021-07-04 11:40:58.684 T:1310729088 NOTICE: Creating InputStream

2021-07-04 11:40:58.737 T:1310729088 NOTICE: Creating Demuxer

2021-07-04 11:40:59.108 T:1310729088 NOTICE: Opening stream: 0 source: 256

2021-07-04 11:40:59.108 T:1310729088 NOTICE: Creating video codec with codec id: 27

2021-07-04 11:40:59.120 T:1310729088 NOTICE: Creating video thread

2021-07-04 11:40:59.121 T:1398797184 NOTICE: running thread: video_thread

2021-07-04 11:40:59.122 T:1310729088 NOTICE: Opening stream: 2 source: 256

2021-07-04 11:40:59.122 T:1310729088 NOTICE: Finding audio codec for: 86056

2021-07-04 11:40:59.123 T:1310729088 NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder eac3

2021-07-04 11:40:59.123 T:1310729088 NOTICE: Creating audio thread

2021-07-04 11:40:59.123 T:1294459776 NOTICE: running thread: CVideoPlayerAudio::Process()

2021-07-04 11:40:59.124 T:1310729088 NOTICE: Opening stream: 0 source: 1024

2021-07-04 11:40:59.432 T:1294459776 NOTICE: Creating audio stream (codec id: 86056, channels: 6, sample rate: 48000, no pass-through)

2021-07-04 11:41:01.748 T:1398797184 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

Display More

Apologies for the bombardment of information, hopefully the super smart people can make sense of it!.

So I've tested again

"CRenderManager::WaitForBuffer - timeout waiting for buffer"

This occurs a total of 18 times, on RPi3b+ playing back file.

It occurs in excess of 200 times, on RPi4, same file

Also lots of

"NOTICE: CVideoPlayerAudio::Process - stream stalled"

(only on Pi4, *none* on Pi3B+)

Furthermore

"CMMALVideo::GetPicture - ret(0) pics(0) inputs(0) slept(500) queued(0.21) (982.56:982.36) full(0) flags(0) preroll(0) eos(0 2>"

(only on Pi4, *none* on Pi3B+)

Finally

"WARNING: ActiveAE - large audio sync error: -89435.153837"

(only on Pi4, *none* on Pi3B+)

Quote from stuckinthehouse

What do the below commands tell you? You have H264 enabled? How much memory do you have allocated to the GPU (second command)?

v4l2-ctl -d 10 --list-formats-out

vcgencmd get_mem gpu

Did this - thank you!

Quote

Kodi:~/.kodi/temp # v4l2-ctl -d 10 --list-formats-out

ioctl: VIDIOC_ENUM_FMT

Index : 0

Type : Video Output Multiplanar

Pixel Format: 'H264' (compressed)

Name : H.264

Index : 1

Type : Video Output Multiplanar

Pixel Format: 'MJPG' (compressed)

Name : Motion-JPEG

Index : 2

Type : Video Output Multiplanar

Pixel Format: 'VP80' (compressed)

Name : VP8

Display More

GPU = 320M (it's a 4GB, Pi4)

Quote from chewitt

I see mention of MMAL so this must be LE 9.2. Go test LE10. Kodi 19 includes lots of feature/bug fixes, and RPi has an entirely different kernel driver stack. From our side of the fence there is no point (and thus not much interest) in investigating issues on LE 9.2 .. it's an effectively dead codebase now.

Sure but I (think) this used to be fine for me and I don't want to use LE10 for a very long time. I use the Aura Skin on Kodi and love the hell out of it, I need that skin fully functioning.

Besides, a Pi3B+ is beating a Pi4, I'm pretty sure this is, somehow, my fault.

Tonight, I build a perfectly fresh, 0 addons, raw Pi4 with stock 9.2.7 and attempt to play back the same file again.

Also of note, in case this helps - the only difference I can think of, from my Pi3 to my Pi4 is the Pi4 is forcing display refresh rate to match video? Maybe that?

Quote from CvH

Project Aura - Kodi Matrix Skin Release! : Addons4Kodi

Well that's a good start!

Let me check what I'm currently using, which is critical to me.

Critical:

Opensubtitles

LibreElec VNC (Tiger?)

Library, auto update

Not critical, wanted:

Trakt

Picture Slideshow Screensaver

That being said, I can't recall my previous favourite skin, but I distinctly recall, it worked on Kodi 15, when they released it for 16 or 17 or whatever, despite the same name, it was vastly inferior I'd hope Aura is near identical.

.

.

.

I also didn't get time last night to re-cook an SD card and try a raw, fresh Pi4 9.2.7 build, with no addons just to see if that addressed the issue, so I will try that in the next 48 hours to see if this is a fundamental issue with 9.2 that I haven't noticed before or if it's just me 'breaking' something on my setup.

I've done a 9.2.7 build now - I'll be able to test tomorrow morning.

Thank you - I'll also try 10, too.

P.S I assume the logs I provided indicate the install is ok?

I ran a fresh build of 9.2.7 and noticed no errors in the log, playing back the incriminating file on the Pi4.

I am now running it on my old install, with MANY addons disabled.

Getting this one only as a fault.

2021-07-07 09:48:55.192 T:2433688432 WARNING: CMMALVideo::GetPicture - ret(0) pics(0) inputs(0) slept(500) queued(0.33) (484.44:484.11) full(0) flag>

2021-07-07 09:48:57.851 T:2433688432 WARNING: Previous line repeats 4 times.