Choppy playback from NAS


#5

Oh yeh, sorry I forgot you had already applied the fix for “Smb connection error 112 host is down” so that makes things easier. Just add the extra option to mount_options in your settings.ini e.g.

mount_options = vers=1.0,cache=none

Then reboot. Once it comes back up, if you login via ssh and run mount it should include that new option in the listing it prints out.

I’m not sure if this particular option is the answer. We might have to play around with a few of them. You can also run the mount command directly (rather than editing settings.ini and rebooting each time) to speed that experimental up. I’m not sure I will be able to replicate the problem but hopefully there’s a benchmark that allows me to measure the effects of these options. e.g. the file transfer speed when copying to from the share to /dev/null.

I’m not sure where else the problem might lie. Wireless connections are often poor and the Zero isn’t that powerful but if it works over DLNA then it should work here too…


#6

Thank you again! I added cache=none to settings.ini, but it’s still not working. No improvement yet.

mount gives the following data:

/dev/root on / type ext4 (rw,noatime,block_validity,delalloc,barrier,user_xattr,acl)
devtmpfs on /dev type devtmpfs (rw,relatime,size=242060k,nr_inodes=60515,mode=755)
tmpfs on /run type tmpfs (rw,nosuid,noexec,relatime,size=49276k,mode=755)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
/dev/sda1 on /music/USB type vfat (rw,nodev,noexec,noatime,nodiratime,sync,fmask=0022,dmask=0022,codepage=437,iocharset=ascii,shortname=mixed,errors=remount-ro)
tmpfs on /run/shm type tmpfs (rw,nosuid,nodev,noexec,relatime,size=98540k)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
/dev/mmcblk0p1 on /boot type vfat (rw,nosuid,nodev,noexec,relatime,fmask=0000,dmask=0000,allow_utime=0022,codepage=437,iocharset=ascii,shortname=mixed,errors=remount-ro)
//192.168.178.1/fritz.nas/Intenso-MicroLine-01/Medien on /music/Network type cifs (ro,relatime,vers=1.0,cache=none,username=musicbox,domain=,uid=0,noforceuid,gid=0,noforcegid,addr=192.168.178.1,soft,unix,posixpaths,mapposix,acl,rsize=61440,wsize=65536,echo_interval=60,actimeo=1)

Wifi signal strength is perfect with the RB. The RB is in the same room as the router.

What I have not mentioned before: Even if the playback bar moves for some seconds before it stops again (sync), there is only milliseconds of sound. So the bar moves but there is no sound.

Something new I realized is, that if I let the problematic playback form NAS sit for some minutes in pause mode, there is some continuous seconds of sound before it stops again. But again the playbar keeps on moving longer than there is actually sound.

I’d love to try a file transport benchmark. Which command do you recommend? I’m a little worried I could harm the installation of musicbox by starting dd into the blue…


#7

What operating system is running on your NAS? And what other services have you enabled on your Musicbox install? Enabling the DLNA streaming functionality did used to cause performance problems (it constantly queries the mpd server for status updates) but I don’t see that anymore.

I can’t reproduce any sort of actual playback problems when playing from a network share (Samba server running on Ubuntu) with any of the below configurations, but I did manage to play with the performance. I also found that by default (i.e. without specifying anything), I was getting rsize=1048576 but I don’t understand why we wouldn’t get the same value. Can you try increasing your rsize value?

These were my tests:

$ apt-get update && apt-get install hdparm pv smbclient

# Hows my general read performance?
$ hdparm -t /dev/root
/dev/root:
 Timing buffered disk reads:  78 MB in  3.06 seconds =  25.48 MB/sec

$ hdparm -T /dev/root               
/dev/root:
 Timing cached reads:   602 MB in  2.00 seconds = 300.46 MB/sec

# Download from a webserver
$ wget http://xps13:80/big.zip  
--2018-05-04 00:23:18--  http://xps13/big.zip
HTTP request sent, awaiting response... 200 OK
Length: 122481788 (117M) [application/zip]
Saving to: `big.zip'
100%[==================================================================================================================>] 122,481,788 3.00M/s   in 49s     
2018-05-04 00:24:07 (2.40 MB/s) - `big.zip' saved [122481788/122481788]

# smbclient uses 127KB blocks
$ time smbclient //xps13/music -c 'get simple.mp3' -N
WARNING: The security=share option is deprecated
Domain=[WORKGROUP] OS=[Windows 6.1] Server=[Samba 4.3.11-Ubuntu]
getting file \simple.mp3 of size 9453560 as simple.mp3 (2031.2 KiloBytes/sec) (average 2031.2 KiloBytes/sec)

real	0m4.660s
user	0m0.162s
sys	0m0.609s

# What version do I have?
$ mount.cifs --version
mount.cifs version: 5.5

# Default mount options
$ mount -t cifs -o ro,vers=1.0,guest //xps13/Music /music/Network/
$ mount
ro,relatime,vers=1.0,sec=none,cache=strict,domain=,uid=0,noforceuid,gid=0,noforcegid,addr=192.168.1.66,soft,unix,posixpaths,serverino,mapposix,acl,rsize=1048576,wsize=65536,echo_interval=60,actimeo=1

# Similar speed to webserver and smbclient
$ dd bs=1M of=/dev/null if=/music/Network/big.zip                               
9+1 records in
9+1 records out
9453560 bytes (9.5 MB) copied, 5.00476 s, 1.9 MB/s

# Different mount options tests:

# rsize=104857,cache=strict (my default)
$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:00:04 [1.82MB/s] [==============================================================================================================>] 100%

# rsize=104857,cache=loose
$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:00:05 [1.56MB/s] [==============================================================================================================>] 100% 

# rsize=104857,cache=none
$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:00:05 [ 1.5MB/s] [==============================================================================================================>] 100%  

# rsize=61440,cache=strict
$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:00:58 [ 157kB/s] [==============================================================================================================>] 100%

# With rsize=61440,cache=loose
$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:01:05 [ 140kB/s] [==============================================================================================================>] 100%

# With rsize=61440,cache=none  <--- WOOO!
$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:00:04 [2.05MB/s] [==============================================================================================================>] 100% 

These experiments indicate that increasing rsize helps, but if you can’t do that (depends on what your file server supports?), cache=none should also help. Can you try these experiments?


#8

Ah OK I figured out that I get a different rsize value since I am making use of the “CIFS Unix extensions” supported by my file server. If I disable that with option nounix it’s mounted using rsize=61440. But I can still get decent performance by setting cache=none (as the last test in my previous post showed):

$ mount -t cifs -o ro,vers=1.0,guest,nounix,cache=none //xps13/Music /music/Network/
$ mount | grep Network
//xps13/Music on /music/Network type cifs (ro,relatime,vers=1.0,sec=none,cache=none,domain=,uid=0,noforceuid,gid=0,noforcegid,addr=192.168.1.66,file_mode=0755,dir_mode=0755,soft,nounix,serverino,mapposix,rsize=61440,wsize=65536,echo_interval=60,actimeo=1)

$ pv < /music/Network/simple.mp3 > /dev/null 
9.02MB 0:00:06 [1.41MB/s] [==============================================================================================================>] 100%

And the reason it’s limited to 61440 (60K) appears to be due to some old WIndows bug.


#9

Hallo and thank you again!

The Fritzbox the NAS is run on are using “Fritz!OS”, which is some kind of linux derivate. But this inner workings are rather closed up to the public. There are some inofficial 3rd party modifications to the OS, but these are quite complicated and not oriented on improvement of network performance but on additional features as far as I know.

It’s late but I managed to replicate some of your test. Some I was able to get to work - some I didn’t. Here are my outputs:

hdparm -t /dev/root
/dev/root:
Timing buffered disk reads: 78 MB in 3.07 seconds = 25.38 MB/sec

hdparm -T /dev/root
/dev/root:
Timing cached reads: 294 MB in 2.00 seconds = 147.01 MB/sec

time smbclient //192.168.178.1/fritz.nas/Intenso-MicroLine-01/Medien/Sonntagshuhn -c Sonntagshuhn_vom_01_10_2017.mp3 -N
WARNING: The security=share option is deprecated
Anonymous login successful
Domain=[WORKGROUP] OS=[Unix] Server=[Samba 3.0.37]
tree connect failed: NT_STATUS_BAD_NETWORK_NAME

real 0m1.066s
user 0m0.041s
sys 0m0.032s

mount.cifs --version
mount.cifs version: 5.5

rsize=61440, cache=none
pv < /music/Network/test.mp3 > /dev/null
10.4MB 0:00:02 [3.68MB/s] [==================================>] 100%

rsize=61440, cache=strict
pv < /music/Network/test.mp3 > /dev/null
10.4MB 0:00:02 [3.84MB/s] [==================================>] 100%

rsize=104857, cache=strict
pv < /music/Network/test.mp3 > /dev/null
10.4MB 0:00:02 [3.79MB/s] [==================================>] 100%

rsize=104857, cache=none
pv < /music/Network/test.mp3 > /dev/null
10.4MB 0:00:02 [3.82MB/s] [==================================>] 100%

To me especially the last benchmarks seem to show, that the network performance is not too bad and is quite independent of rsize and cache settings.

But of course playback from i.e. this testfile is still not working.

BTW: I deactivated all other services such as DLNA but that made no difference either.

Strange. Any ideas left? Once you suspected the performance of the SD-card. To try a faster one I would have to buy one. Would that make sense?


#10

It doesn’t look like this is a problem with the network share. Since you didn’t get the smbclient test to work, and that’s the only one that writes to the SD card, can you try this also:

pv < /music/Network/test.mp3 > /music/

And provide the output of top whilst trying to play music so we can see the cpu usage.


#11

Hi!

pv < /music/Network/test.mp3 > /music

gave error

-bash: /music: Is a directory

so I tried:

root@MusicBox:~# pv < /music/Network/test.mp3 > /music.mp3
10.4MB 0:00:04 [2.38MB/s] [==================================>] 100%

Is that the benchmark you wanted? Doesn’t look so bad either, or does it?!?

top CPU monitoring date is included in my threadstarter post as a Youtube video. Don’t know if you can open it or it is providing enough data. If I should use top differntly please give me the command syntax. Linux is still foreign land for me.

Yours, Roland


#12

Yeh that looks fine. At least we know what it isn’t!

I’ll look at the video when I’m back home. I appreciate the effort in providing it but words and log files are generally easier since I can consume them on my phone. Next step is going to be getting a Mopidy debug log, and maybe even a gstreamer debug log.


#13

I am still ready to cooperate as soon you have the time. Just tell me what you need.


#14

Please enable Mopidy debug logging in websettings, reproduce the problem and then provide the log file at /tmp/mopidy-debug.log.

Ideally can you do that with the DLNA service disabled.


#15

And while we are at it, also a Gstreamer debug log. For this you need to stop Mopidy (and monit)

service monit stop
service mopidy stop

Then, as before, reproduce the problem with the logging enable. This one will generate a huge log file so don’t leave it running too long else you’ll eat up all your memory!

sudo -u mopidy GST_DEBUG=3 GST_DEBUG_FILE=/tmp/gst.log mopidy --config /etc/mopidy/mopidy.conf

The logfile will be in /tmp/gst.log and you might have to upload it somewhere in order to share it.


#16

Dear kingosticks,

even my Mopidy logfile after trying to play the test.mp3 file from NAS is too large to post it here. I uploaded it as “mopidy.debug.log” to the following service:

Logfiles at GMX.net

Next I rebooted the RB, started the playback of the testfile again and stopped ist, suspended the services and “sudoed” the above command and let it run for about 10 seconds.

You find these logfiles also at the above link named “gst.log” and “mopidy.debug2.log”.

I hope I did everything right, because the “gst.log” is much smaller than the “mopidy” logfiles. I chose the above order, because after closing the above services the webinterface was no longer reachable so I could not play the testfile.

Hope, you find something! Yours, Roland


#17

From Saturday on I will be on vacation for one week. I still hope there will be a solution and I am ready to cooperate from May 27th on.


#18

Hi Sorry! Could you briefly describe what you were doing in the first log (mopidy-debug.log)? Did you try and play the same file twice? Did the first time not work at all? There’s really not a lot in the gst log, where is the playback starting? It looks like that’s only initialisation which isn’t interesting.

I also have one more test that should be real quick if you have time before you go.
If you could start playback like normal and then make sure you immediately close all musicbox webclient browser tabs. The webclient tries to query the position multiple times a second at the start of playback, perhaps this is causing an issue here. Is it still choppy?


#19

Thank you again!

As I can’t remember exactly what I did one week ago I produced another mopidy log (mopidy-debug3.log) as follows:

  1. Activate debug logging in the system setting menu
  2. Reboot Raspberry
  3. Go to test.mp3 on NAS via webclient and start playback
  4. Click on “now playing” tab of webclient and wait until playback reaches approximately 0:40 sec. Playback produced no sound at all today. Bar stopped multiple times.
  5. Press pause
  6. Copy mopidy-debug.log

I hope this helps.

It’s a pity, but closing the webclient doesn’t improve playback at all.

I’m going on holidays now so I am away from my wifi-network and not able to make tests. Perhaps you could have a look at the new log in the meantime. Thank you in advance!


#20

OK thanks. I was hoping for a gstreamer debug log of doing those actions. Maybe when you get back.


#21

Considering gstreamer debug: Did I do it the right way (see post 15)? About how long should I let the logger run?


#22

Just set debug level 3 and you need to capture the proem occurring. What you had before didn’t seem to actually start playback.


#23

And please disable the DLNA/UPnp service (or close that MPD client).

2018-05-18 19:58:26,581 INFO [2881:MpdSession-15] mopidy.mpd.session: New MPD connection from [::ffff:127.0.0.1]:54984


#24

Ok, I’m finally back again!

Sorry for taking so long, but I had a broken car and a broken motorbike to take care of!

So: I tried to fabricate to more logs the following way:

  1. Enabled Mopidy debug logging and disable DLNA service in websettings, reboot raspberry.
  2. Started SSH session
  3. Opened Musicbox frontend in browser
  4. Executed service monit stop , service mopidy stop and sudo -u mopidy GST_DEBUG=3 GST_DEBUG_FILE=/tmp/gst.log mopidy --config /etc/mopidy/mopidy.conf on raspberry through SSH
  5. Started playback of test.mp3 from NAS through browser frontend
  6. Stopped playback after about 10 seconds
  7. Stopped the above sudo command by CTRL+C in SSH console
  8. Uploaded the new logfiles named 18-06-14_mopidy-debug.log and 18-06-14_gst.log to Link

I hope, I did everything right now - I’m absolutely not sure…