20+ second delay to before music start playing

Help and Support Vero 4K / Vero 4K +
1

Hi,

I thought I should start by asking this question before I reinstall OSMC on my VERO 4k

I been away from home the last 12 weeks and when I got back I did an system update.
After the upgrade, there is a noticeable delay before the music begins after selecting a song - around 20-25 seconds. During this time the system is locked. It’s the same result if I use Veros own remote or the iPhone remote app.
The delay doesn’t happen between songs if I play an album, but if I switch from one album to the other there is a new delay.
I am reluctant to assume this is a problem with my NAS, I do not get any indication there is buffering going on, and if I start any videos they begin playing more or less immediately. Videos are stored on the same disk/different partition on my NAS as the music files.

Is this a known problem, or is it just me?

/Stefan

2

I would assume it’s just you as otherwise the forum would be full of complains.
So if you want to do some analytics before reinstalling suggest to provide debug logs for us to help.
Also check which Audio Output you have configured.

3

Yep, I had the same feeling too - I did search and only saw a similar problem in Rpi forum several years back.

Here is the recent log: http://paste.osmc.tv/ehifedudad

What I did after enabling the log was:

  1. restart the Vero
  2. navigate to and start playing one song (waiting time ca 25 sec)
  3. start the next song on the same album (no waiting time)
  4. navigate to and start playing a song on another album (about 25 sec waiting time)
    I then went to Settings/System/audio to check the output, but it was the standard one for my TV. I have been using two different USB DAC previously, but with no different results.
4

Might be related to Spotify, try to disable the Addon>

2019-12-19 10:01:33.057 T:3764364000   DEBUG: CDVDDemuxFFmpeg::AddStream ID: 1
2019-12-19 10:01:33.057 T:3764364000  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder alac
2019-12-19 10:01:35.040 T:3852223200   DEBUG: plugin.audio.spotify --> retrieving token...
2019-12-19 10:01:35.041 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: loading setting definitions
2019-12-19 10:01:35.041 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: trying to load setting definitions from old format...
2019-12-19 10:01:35.042 T:3852223200   DEBUG: CSettingsManager: requested setting (connect_username) was not found.
2019-12-19 10:01:36.374 T:3367981792    INFO: CFileCache::Process - Source read didn't return any data! Hit eof(?)
2019-12-19 10:01:40.043 T:3852223200   DEBUG: plugin.audio.spotify --> retrieving token...
2019-12-19 10:01:40.045 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: loading setting definitions
2019-12-19 10:01:40.046 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: trying to load setting definitions from old format...
2019-12-19 10:01:40.046 T:3852223200   DEBUG: CSettingsManager: requested setting (connect_username) was not found.
2019-12-19 10:01:45.047 T:3852223200   DEBUG: plugin.audio.spotify --> retrieving token...
2019-12-19 10:01:45.049 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: loading setting definitions
2019-12-19 10:01:45.049 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: trying to load setting definitions from old format...
2019-12-19 10:01:45.050 T:3852223200   DEBUG: CSettingsManager: requested setting (connect_username) was not found.
2019-12-19 10:01:50.051 T:3852223200   DEBUG: plugin.audio.spotify --> retrieving token...
2019-12-19 10:01:50.052 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: loading setting definitions
2019-12-19 10:01:50.053 T:3852223200   DEBUG: CAddonSettings[plugin.audio.spotify]: trying to load setting definitions from old format...
2019-12-19 10:01:50.053 T:3852223200   DEBUG: CSettingsManager: requested setting (connect_username) was not found.
2019-12-19 10:01:55.055 T:3852223200   DEBUG: plugin.audio.spotify --> retrieving token...
5

Tried it
Disabled Spotify Plugin, Rebooted but the problem persists.

6

New logs would help
Also have you tried without the USB DAC playing via HDMI? just to narrow down the problem!

7

new logs at: paste.osmc.tv/ofanebomav

same steps for testing as last time, but this time spotify plugin disabled and HDMI driver selected.

(the DACs unplugged)

no change in the result

8

The 30 seconds seems to be picked up somewhere in the caching time. Could you try to play the file from the internal drive to test if it might be related to network?

019-12-19 11:06:10.844 T:3922715360   DEBUG: CDVDDemuxFFmpeg::AddStream ID: 1
2019-12-19 11:06:10.844 T:3922715360  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder alac
2019-12-19 11:06:14.169 T:2982204128    INFO: CFileCache::Process - Source read didn't return any data! Hit eof(?)
2019-12-19 11:06:40.790 T:3931108064   DEBUG: Thread JobWorker 3931108064 terminating (autodelete)
2019-12-19 11:06:40.790 T:3958551264   DEBUG: Thread JobWorker 3958551264 terminating (autodelete)
2019-12-19 11:06:40.791 T:3782169312   DEBUG: Thread JobWorker 3782169312 terminating (autodelete)
2019-12-19 11:06:40.854 T:3922715360   DEBUG: SeekTime - unknown position after seek
2019-12-19 11:06:40.855 T:4065173504   DEBUG: Previous line repeats 1 times.
2019-12-19 11:06:40.855 T:4065173504   DEBUG: CPlayerGUIInfo::InitCurrentItem(musicdb://recentlyplayedalbums/1652/57689.m4a?albumid=1652)
2019-12-19 11:06:40.946 T:3922715360    INFO: AudioDecoder: File is queued
2019-12-19 11:06:40.947 T:4023382752   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
9

paste.osmc.tv/nomahojeji

put a few songs in the home/music directory and played.
they played fine, and when i went back to play from the library (networked) it was till the same. I did however notice that sometimes a song would play right away even from the networked volume.

I also never experienced a lag when playing videos.

10

This is really odd. Sorry out of ideas. I would:

  1. Do a longer network test with iperf3
  2. Do a resinstall of OSMC
11 
2019-12-19 11:06:10.844 T:3922715360  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder alac
2019-12-19 11:06:14.169 T:2982204128    INFO: CFileCache::Process - Source read didn't return any data! Hit eof(?)
...
2019-12-19 11:06:40.854 T:3922715360   DEBUG: SeekTime - unknown position after seek
...
2019-12-19 11:06:40.855 T:4065173504   DEBUG: CPlayerGUIInfo::InitCurrentItem(musicdb://recentlyplayedalbums/1652/57689.m4a?albumid=1652)
2019-12-19 11:06:40.946 T:3922715360    INFO: AudioDecoder: File is queued

around 30 seconds delay?

So, what could cause the delay on he NAS?

  • Hibernation?
  • Any indexing service activated on the NAS which analyses the data, first?
13

So, what could cause the delay on the NAS?

  • Hibernation?
  • Any indexing service activated on the NAS which analyses the data, first?

Can’t even say for sure that it is a problem with the NAS, I have run the same setup for at least 6 months with VERO 4k up until the end of September when I had to go away for work, and never had any issues.
Hibernation is hardly an issue neither at the NAS or the VERO, and while the NAS do have indexing services they run at need and have also never affected the playback before.
Also, wouldn’t those issues affect ALL files that I try to play from the NAS? Video files do so far seem to be unaffected.

14

Been spending the last hour trying to install iperf3 on my Synology DS414j NAS, but get error messages no matter what I do. Install on my VERO went fine though.

15

If it is easier to install iperf (instead of iperf3) on the NAS than can also use that.
Anyhow as you mentioned maybe it is not a NAS/Network issue. Then a reinstall might be the fastest way to clarify. Or you first try a clean Kodi install.

Let’s test with Kodi default settings. Enter the following commands with an SSH connection.

systemctl stop mediacenter
mv ~/.kodi ~/kodi.bak
systemctl start mediacenter

If need you can restore:

systemctl stop mediacenter
mv ~/.kodi ~/kodi.bk2
mv ~/kodi.bak ~/.kodi
systemctl start mediacenter

If your original setup was restored as expected and you want get rid of the unneeded clean install you can delete that with the following command.

rm -r ~/kodi.bk2

16

I tried to get back to default settings, but realised i cannot reach the network by browsing so i cant test the music files without editing forgot-the-name-of- the-file-to mount-NAS-drives again, and that will take a while.

17

Regarding iperf on Synology:

Do a “manual install” in your package center and you’re done.

18

already tried this, but i get

synopkg install iperf_comcerto2k-6.2_3.7-1.spk
Failed to install package iperf_comcerto2k-6.2_3.7-1.spk, error = [276]

I have the DS414j, a non-intel processor which might be the problem

19

You used fstab based mounts so they are still there.
Just recover the sources.xml from your backup (~/.kodi.bak/userdata/sources.xml)

Your NAS is mounted as
/mnt/Media_NAS
/mnt/Files_NAS
/mnt/Music_NAS

20

Or just go to file manager in settings and “add source” for “/mnt” and then test files from there.

21

well thats just what I cannot do. i cant access the shares this way. if i could I wouldnt have had to use fstab in the first place.