Login at Kodi Home

stevellion · 2011-10-24, 16:56

On my ATV2 (sorry, 4.4 firmware) - I'm seeing significant delays when I go to access a folder I've shared with SMB, from a NAS.

This is before it shows any of the contents, it just sits at "working" for a good 60 seconds, then eventually displays the contents.

Accessing a UpNp share does not have this delay at all..
(But, I don't seem to be able to stack UpNp files nicely)

PS - Should NFS from XBMC work on ATV2?

The log seems to point to it doing this?

15:43:37 T:119115776 DEBUG: Thread Jobworker 119115776 terminating (autodelete)
15:43:37 T:107433984 DEBUG: Thread Jobworker 107433984 terminating (autodelete)
15:43:46 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/1111111_cd1.rar, fd=10000
15:43:46 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:46 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/22222222_cd2.rar, fd=10000
15:43:47 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:47 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/33333333.rar, fd=10000
15:43:47 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:47 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/4444444.rar, fd=10000
15:43:47 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:47 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/aaaaCD1.rar, fd=10000
15:43:48 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:48 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/bbbbbcd1.rar, fd=10000
15:43:50 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:50 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/cccccccd1.rar, fd=10000
15:43:50 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:50 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/ddddddcd2.rar, fd=10000
15:43:51 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:51 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/eeeeeee.rar, fd=10000
15:43:51 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:51 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/fffffff.rar, fd=10000
15:43:52 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:52 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/gggggggg.rar, fd=10000
15:43:52 T:103608320 DEBUG: CFileSMB::Close closing fd 10000
15:43:52 T:103608320 DEBUG: CFileSMB::Open - opened VIDEO/movies/hhhhhh.rar, fd=10000
(cut excerpts only..)
15:44:09 T:103608320 DEBUG: Saving fileitems [smb://user:pass@ns4600/VIDEO/movies/]
15:44:09 T:103608320 DEBUG: -- items: 426, sort method: 0, ascending: false
15:44:10 T:103608320 DEBUG: RunQuery took 206 ms for 281 items query: select * from movieview where c23=2
15:44:10 T:103608320 DEBUG: RunQuery took 14 ms for 281 items query: select strFilename,playCount from files where idPath=2
15:44:10 T:103608320 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:ViewModes4.db
15:44:11 T:84660224 DEBUG: Previous line repeats 2 times.
15:44:11 T:84660224 DEBUG: Thread Background Loader start, auto delete: 0
15:44:11 T:84660224 DEBUG: OpenDir - Using authentication url smb://user:pass@ns4600/VIDEO/movies/Bond
15:44:11 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:11 T:107433984 DEBUG: Previous line repeats 2 times.
15:44:11 T:107433984 DEBUG: Thread Jobworker start, auto delete: 1
15:44:11 T:84660224 DEBUG: Previous line repeats 2 times.
15:44:11 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:11 T:107433984 DEBUG: DoWork - took 171 ms to load special://masterprofile/Thumbnails/Video/d/d3a407d4.tbn
15:44:11 T:116551680 DEBUG: DoWork - took 202 ms to load special://masterprofile/Thumbnails/Video/c/c229b84a.tbn
15:44:11 T:116019200 DEBUG: DoWork - took 206 ms to load special://masterprofile/Thumbnails/Video/1/15b09899.tbn
15:44:11 T:119115776 DEBUG: DoWork - took 214 ms to load special://masterprofile/Thumbnails/Video/6/66094d8a.tbn
15:44:11 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:11 T:116551680 DEBUG: DoWork - took 211 ms to load special://masterprofile/Thumbnails/Video/b/be44bce7.tbn
15:44:11 T:119115776 DEBUG: DoWork - took 195 ms to load special://masterprofile/Thumbnails/Video/a/ab73cc5f.tbn
15:44:11 T:107433984 DEBUG: DoWork - took 295 ms to load special://masterprofile/Thumbnails/Video/a/a576ece7.tbn
15:44:11 T:116019200 DEBUG: DoWork - took 255 ms to load special://masterprofile/Thumbnails/Video/1/1af71135.tbn
15:44:11 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:11 T:103608320 DEBUG: SECTION:UnloadDll(libcurl.4.dylib)
15:44:11 T:103608320 DEBUG: Unloading: libcurl.4.dylib
15:44:11 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:12 T:103608320 DEBUG: Previous line repeats 1 times.
15:44:12 T:103608320 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
15:44:12 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:19 T:84660224 DEBUG: Previous line repeats 52 times.
15:44:19 T:84660224 INFO: Caching image from: smb://user:pass@ns4600/VIDEO/movies/aaaaaa.tbn to special://masterprofile/Thumbnails/Video/4/47a1573c.tbn with width 512 and height 512
15:44:19 T:84660224 DEBUG: SECTION:LoadDLL(special://xbmcbin/system/ImageLib-arm-osx.so)
15:44:19 T:84660224 DEBUG: Loading: /private/var/Applications/XBMC.frappliance/XBMCData/XBMCHome/system/ImageLib-arm-osx.so
15:44:19 T:84660224 DEBUG: CFileSMB::Open - opened VIDEO/movies/aaaaaaa.tbn, fd=10000
15:44:20 T:84660224 DEBUG: CFileSMB::Close closing fd 10000
15:44:20 T:84660224 DEBUG: CFileSMB::Open - opened VIDEO/movies/aaaaaa.tbn, fd=10000
15:44:21 T:84660224 DEBUG: CFileSMB::Close closing fd 10000
15:44:22 T:84660224 DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos56.db
15:44:30 T:84660224 DEBUG: Previous line repeats 56 times.
15:44:30 T:84660224 INFO: Caching image from: smb://user:pass@ns4600/VIDEO/movies/aaaaa.tbn to special://masterprofile/Thumbnails/Video/a/adb788ba.tbn with width 512 and height 512

gbandit · 2011-10-24, 18:38

The same thing happens on mine, pretty sure it's just inspecting the .rars for subtitles.

~~Ned Scott~~ · 2011-10-24, 19:36

rar's slow things down in a lot of ways. Unless you are still sharing/seeding those files out to the internet, there's no need to keep them rar'ed.

stevellion · 2011-10-24, 21:08

OK, They are just subtitles.

I'll move them and see what happens.

The strange thing is though - this is not an issue on my HTPC box, or was it an issue on my xbox's that have only been retired as I purchased the ATV2.

Therefore, I think something is not right about this.

stevellion · 2011-10-25, 13:37

Nope, it's not the RAR's. still taking an age to access an SMB folder.

See log.

I am wondering if it's a sqlite issue - could point to mysql on another machine and see what happens.

Anyone else got any comments?

Code:
23:33 T:28594176  NOTICE: -----------------------------------------------------------------------

23:33 T:28594176  NOTICE: Starting XBMC, Platform: Darwin iOS (11.0.0 AppleTV2,1). Built on Oct 24 2011 (Git:20111023-0e8168e)

23:33 T:28594176  NOTICE: special://xbmc/ is mapped to: /private/var/Applications/XBMC.frappliance/XBMCData/XBMCHome

23:33 T:28594176  NOTICE: special://xbmcbin/ is mapped to: /private/var/Applications/XBMC.frappliance/XBMCData/XBMCHome

23:33 T:28594176  NOTICE: special://masterprofile/ is mapped to: /var/mobile/Library/Preferences/XBMC/userdata

23:33 T:28594176  NOTICE: special://home/ is mapped to: /var/mobile/Library/Preferences/XBMC

23:33 T:28594176  NOTICE: special://temp/ is mapped to: /var/mobile/Library/Preferences/XBMC/temp

23:33 T:28594176  NOTICE: special://frameworks/ is mapped to: /var/Applications/XBMC.frappliance/Frameworks

23:33 T:28594176  NOTICE: The executable running is: /var/Applications/XBMC.frappliance/XBMC

23:33 T:28594176  NOTICE: Log File is located: /var/mobile/Library/Preferences/xbmc.log

23:33 T:28594176  NOTICE: -----------------------------------------------------------------------

23:33 T:28594176  NOTICE: load settings...

23:33 T:28594176  NOTICE: special://profile/ is mapped to: special://masterprofile/

23:33 T:28594176  NOTICE: loading special://masterprofile/guisettings.xml

23:33 T:28594176  NOTICE: Getting hardware information now...

23:33 T:28594176    INFO: Using digital output

23:33 T:28594176    INFO: AC3 pass through is disabled

23:33 T:28594176    INFO: DTS pass through is disabled

23:33 T:28594176    INFO: AAC pass through is disabled

23:33 T:28594176    INFO: MP1 pass through is disabled

23:33 T:28594176    INFO: MP2 pass through is disabled

23:33 T:28594176    INFO: MP3 pass through is disabled

23:33 T:28594176   DEBUG: Error: Requested setting (videoscreen.screenmode) was not found.  It must be case-sensitive

23:33 T:28594176  NOTICE: Checking resolution 12

23:33 T:28594176  NOTICE: Loading player core factory settings from special://xbmc/system/playercorefactory.xml.

---- cut----

23:42 T:28594176   DEBUG: CGUIMediaWindow::GetDirectory (smb://user:pass@ns4600/VIDEO/movies/)

23:42 T:28594176   DEBUG:   ParentPath = [sources://video/]

23:42 T:105345024   DEBUG: OpenDir - Using authentication url smb://user:pass@ns4600/VIDEO/movies

23:42 T:28594176   DEBUG: ------ Window Init (DialogBusy.xml) ------

24:04 T:28594176   DEBUG: SECTION:UnloadDelayed(DLL: special://xbmcbin/system/ImageLib-arm-osx.so)

24:04 T:28594176   DEBUG: Unloading: ImageLib-arm-osx.so

24:07 T:28594176    INFO: CheckIdle - Closing session to http://feeds.feedburner.com (easy=0x73f3000, multi=0xfc5a3c0)

24:09 T:28594176    INFO: CheckIdle - Closing session to http://xoap.weather.com (easy=0x6c26000, multi=0x118e2f50)

24:12 T:114061312   DEBUG: Thread Jobworker 114061312 terminating (autodelete)

24:12 T:114593792   DEBUG: Thread Jobworker 114593792 terminating (autodelete)

24:12 T:117211136   DEBUG: Thread Jobworker 117211136 terminating (autodelete)

24:30 T:28594176   DEBUG: Saving fileitems [smb://user:pass@ns4600/VIDEO/movies/]

24:30 T:28594176   DEBUG:   -- items: 426, sort method: 0, ascending: false

24:31 T:28594176   DEBUG: RunQuery took 207 ms for 281 items query: select * from movieview where c23=2

24:31 T:28594176   DEBUG: RunQuery took 13 ms for 281 items query: select strFilename,playCount from files where idPath=2

24:32 T:28594176   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:ViewModes4.db

24:32 T:805109760   DEBUG: Previous line repeats 2 times.

24:32 T:805109760   DEBUG: Thread Background Loader start, auto delete: 0

24:32 T:805109760   DEBUG: OpenDir - Using authentication url smb://user:pass@ns4600/VIDEO/movies/Bond

24:32 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

24:32 T:109563904   DEBUG: Previous line repeats 2 times.

24:32 T:109563904   DEBUG: Thread Jobworker start, auto delete: 1

24:33 T:105345024   DEBUG: Previous line repeats 1 times.

24:33 T:105345024   DEBUG: DoWork - took 257 ms to load special://masterprofile/Thumbnails/Video/d/d3a407d4.tbn

24:33 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

24:33 T:109563904   DEBUG: DoWork - took 277 ms to load special://masterprofile/Thumbnails/Video/6/66094d8a.tbn

24:33 T:121495552   DEBUG: DoWork - took 212 ms to load special://masterprofile/Thumbnails/Video/b/be44bce7.tbn

24:33 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

24:33 T:105345024   DEBUG: DoWork - took 229 ms to load special://masterprofile/Thumbnails/Video/1/1af71135.tbn

24:33 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

24:33 T:109563904   DEBUG: DoWork - took 167 ms to load special://masterprofile/Thumbnails/Video/a/ab73cc5f.tbn

24:33 T:28594176   DEBUG: ------ Window Deinit (DialogBusy.xml) ------

24:33 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

24:39 T:28594176   DEBUG: Previous line repeats 51 times.

24:39 T:28594176   DEBUG: SECTION:UnloadDll(libcurl.4.dylib)

24:39 T:28594176   DEBUG: Unloading: libcurl.4.dylib

24:40 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

25:03 T:121495552   DEBUG: Previous line repeats 156 times.

25:03 T:121495552   DEBUG: Thread Jobworker 121495552 terminating (autodelete)

25:03 T:105345024   DEBUG: Thread Jobworker 105345024 terminating (autodelete)

25:03 T:109563904   DEBUG: Thread Jobworker 109563904 terminating (autodelete)

25:03 T:805109760   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:MyVideos57.db

25:09 T:805109760   DEBUG: Previous line repeats 64 times.

25:09 T:805109760   DEBUG: Thread Background Loader 805109760 terminating

**Memphiz** · 2011-10-25, 15:19

Give some more infos about your setup please. How many files/folders are in the samba share, what os is the server on (windows sharing, linux samba, or macosx?, or nas), what is your network (wifi or ethernet, router in between?) ... something like that ...

stevellion · 2011-10-25, 16:12

Thanks Memphiz,

How many files/folders are in the samba share: 738
What os is the server on: NAS, Linux ns4600 2.6.32.14,
----- Domain=[xxxx] OS=[Unix] Server=[Samba 3.5.4]

What is your network: Gigabit Linksys WRT-350N, with Gigabit ethernet to the NAS and Wireless to the Apple-TV.

(I used to run my Xbox with a crappy old D-Link wireless access point, (configured as a client) and had no issues with this at all.

To confirm - gone back to iOS 4.3 now (thanks to your other tip) and same problem exists. (although not quite so bad..)

It's still taking 20 seconds to just open a share..?? never seen those sort of delays before.

Big difference with this build, is currently, there is no sql library of any kind....

Log here...

Code:
08:44 T:98254848  NOTICE: Starting XBMC, Platform: Darwin iOS (11.0.0 AppleTV2,1). Built on Oct 25 2011 (Git:20111024-c5758bf)

--- cut---

08:56 T:98254848   DEBUG: CGUIMediaWindow::GetDirectory (smb://user:pass@ns4600/VIDEO/movies/)

08:56 T:98254848   DEBUG:   ParentPath = [sources://video/]

08:56 T:109006848   DEBUG: OpenDir - Using authentication url smb://user:pass@ns4600/VIDEO/movies

08:56 T:98254848   DEBUG: ------ Window Init (DialogBusy.xml) ------

09:12 T:98254848   DEBUG: Saving fileitems [smb://user:pass@ns4600/VIDEO/movies/]

09:12 T:98254848   DEBUG:   -- items: 426, sort method: 0, ascending: false

09:13 T:98254848   DEBUG: Connecting to sqlite:/var/mobile/Library/Preferences/XBMC/userdata/Database/:ViewModes4.db

09:14 T:804360192   DEBUG: Previous line repeats 2 times.

09:14 T:804360192   DEBUG: Thread Background Loader start, auto delete: 0

09:14 T:804360192   DEBUG: OpenDir - Using authentication url smb://stevemu:secretc0de@ns4600/VIDEO/movies/Bond

09:14 T:98254848   DEBUG: ------ Window Deinit (DialogBusy.xml) ------

09:15 T:98254848   DEBUG: SECTION:UnloadDelayed(DLL: special://xbmcbin/system/ImageLib-arm-osx.so)

09:15 T:98254848   DEBUG: Unloading: ImageLib-arm-osx.so

09:19 T:98254848    INFO: CheckIdle - Closing session to http://feeds.feedburner.com (easy=0x6281000, multi=0x1dad0770)

09:23 T:98254848    INFO: CheckIdle - Closing session to http://xoap.weather.com (easy=0x5ff8000, multi=0x201dd600)

09:26 T:100290560   DEBUG: Thread Jobworker 100290560 terminating (autodelete)

09:26 T:109539328   DEBUG: Thread Jobworker 109539328 terminating (autodelete)

09:41 T:109006848   DEBUG: Thread Jobworker 109006848 terminating (autodelete)

**Memphiz** · 2011-10-25, 18:46

4 things:

1. Don't compare any WIFI with the ATV2 WIFI. The used wifi part in the ATV2 is crap. Its truncated to 65mb/s (violating the 80211n standard imho) and it has a poor performance mostly. There are exceptions from that - but the experience confirms that its crap Wink

2. Try ethernet to boost ther performance
3. The folder seems to be a bit big. If its still slow with ethernet you can bump the performance by doing this: http://wiki.xbmc.org/index.php?title=Adv...3Csamba.3E
Disable the samba stat. You will lose the file sizes with that but it should get faster on iterating the folder.

4. Try to reduce the files per folder by splitting your content into categories or something like that

And last tip. Don't cut logs. Please just paste full logs next time to pastebin.com and put the link into the thread. I don't see any sql stuff in your latest log snipped though.

stevellion · 2011-10-25, 19:50

Mephiz - Thanks.

Turning stat off for Samba has resolved the delay...
But it still irks me that it was never a problem on my trusty xbox and a crappy old access point.. Actually, I might try using the access point to deliver Ethernet to the ATV and see if it's better. Might well be..
(But no easy way to run a cable - I've thought of that many times...)

I'll be quite surprised if my old AP could provide better Wi-Fi.. but it does have a sicky-out aerial at the back, maybe that makes all the difference.

Splitting out the folders more, would be a regression against older kit.. - it's already split into movies, kids-movies, tv-shows and asian-moves... :-)

I'm also going to compare performance connecting to MySQL on the NAS, see if that is a big difference, compared to sqlite connection. - My guess is it'll probably suck!

stevellion · 2011-10-25, 20:22

Right.. I've now also re-animated my old D-link AP and connected it to a new vwlan on my network (it'll only do client mode with WEP..)

Next test.. see just how sucky the ATV wi-fi is, compared to an old Wireless G+ AP.

**Memphiz** · 2011-10-25, 21:58

stevellion Wrote:Right.. I've now also re-animated my old D-link AP and connected it to a new vwlan on my network (it'll only do client mode with WEP..)

Next test.. see just how sucky the ATV wi-fi is, compared to an old Wireless G+ AP.

Throw a cable trough your rooms and test ethernet. You won't ever play with wifi again on atv2 if you tasted the speed ... and after that you will find a solution on how to get it wired cleanly Wink

stevellion · 2011-10-26, 18:00

Cable - I wish I could.. Thought about it many times, but not nice.

I'd need to go up between the walls on two floors and back down through the ceiling.. nasty. Or out through the wall, into the roof and down through the ceiling.

(The ATV is in the top of a fitted wardrobe, that the TV's mounted in front of)

But.. now I've got NFS working, it's not a problem anymore.

I've even switched off the old AP again, as it was slower that the ATV wi-fi I think.

SMB is the problem IMHO.

fly2thesun · 2011-10-29, 06:33

I was having the same issue of slow access to an SMB share. Related thread here:

http://forum.xbmc.org/showthread.php?tid=108773

After reading your post, I tried NFS, and the startup delay has reduced to 3~4 secs. With SMB share, it was about 10 secs with statfiles=on. With AFP, about 8 seconds. All this with WD MyBook World edition, and about 1200 files in the directory in question. Nightly build from Oct 8. ( I wasn't trying NFS, because NFS seemed even slower than SMB when I first tried NFS a few months ago.. )

I'd like to add that the connection quality matters a lot too. I originally had the ATV2 and the NAS connected across a powerline connection, which caused about 20sec delay with SMB shares. When I moved the NAS to another port on the same router as the ATV2 is connected to, the delay reduced to half.