[Milhouse]

It's creating the playlist part.

Yes, but one album of songs (10-12 tracks) shouldn't take 10-15 seconds before playback commences, nor should the sending of notifications block playback (at least, not while using JSON-RPC).

I've run tests here monitoring JSON-RPC notifications and artificially processing (consuming) notifications very slowly does not delay playback. However Yatse is using the webserver (HTTP not RPC) for JSON which may behave differently, so removing Yatse from the test environment would be beneficial.

Time to play one album (pressing "Play" button on my IR remote while Album is highlited) - 11 tracks, 1 second:

Code:

$ ./texturecache.py monitor
2014-06-11 17:59:30.470417: Playlist.OnClear     : {"playlistid": 0}
2014-06-11 17:59:30.525932: Playlist.OnAdd       : {"item": {"type": "song", "id": 79}, "playlistid": 0, "position": 0} [Electronic Performers (Air)]
2014-06-11 17:59:30.570547: Playlist.OnAdd       : {"item": {"type": "song", "id": 80}, "playlistid": 0, "position": 1} [How Does It Make You Feel? (Air)]
2014-06-11 17:59:30.612745: Playlist.OnAdd       : {"item": {"type": "song", "id": 81}, "playlistid": 0, "position": 2} [Radio #1 (Air)]
2014-06-11 17:59:30.651664: Playlist.OnAdd       : {"item": {"type": "song", "id": 82}, "playlistid": 0, "position": 3} [The Vagabond (Air)]
2014-06-11 17:59:30.695878: Playlist.OnAdd       : {"item": {"type": "song", "id": 83}, "playlistid": 0, "position": 4} [Radian (Air)]
2014-06-11 17:59:30.748107: Playlist.OnAdd       : {"item": {"type": "song", "id": 84}, "playlistid": 0, "position": 5} [Lucky And Unhappy (Air)]
2014-06-11 17:59:30.790414: Playlist.OnAdd       : {"item": {"type": "song", "id": 85}, "playlistid": 0, "position": 6} [Sex Born Poison (Air)]
2014-06-11 17:59:30.838677: Playlist.OnAdd       : {"item": {"type": "song", "id": 86}, "playlistid": 0, "position": 7} [People In The City (Air)]
2014-06-11 17:59:30.896787: Playlist.OnAdd       : {"item": {"type": "song", "id": 87}, "playlistid": 0, "position": 8} [Wonder Milky Bitch (Air)]
2014-06-11 17:59:30.943711: Playlist.OnAdd       : {"item": {"type": "song", "id": 88}, "playlistid": 0, "position": 9} [Don't Be Light (Air)]
2014-06-11 17:59:31.000368: Playlist.OnAdd       : {"item": {"type": "song", "id": 89}, "playlistid": 0, "position": 10} [Caramel Prisoner (Air)]
2014-06-11 17:59:31.438064: Player.OnPlay        : {"item": {"type": "song", "id": 79}, "player": {"playerid": 0, "speed": 1}} [Electronic Performers (Air)]

[da-anda]

I also gave it a try on my PI (950 MHz) and playing an album with ~20 tracks took ~12 seconds to start. I had UPNP, Webserver and "allow local control of XBMC" disabled. Can do a debug session tonight, just tell me what you need (regular debug log or something else)

[Tolriq]

Well since last message on what Yatse did send was not clear a more detailed one

( BTW 40% of Yatse users are rpi ones and no it does not slow rpi bla bla bla despite the defamation )

Anyway here's logs of what Yatse does but with no Yatse running, pure curl queuing 13 songs : near 10 secs.

All that on a medium local database of 1200 albums. But with an overclocked rpi B and a class 10 fast sdcard.
Nothing connected on port 9090 too to consume notifications either.

As you can see in the logs, the first network access to the media location is done when the player start to play and needs access to mp3.
So slowness is 100% related to Xbmc internals / databases access and not to the content of the media directory in this music case.
The test was made when rpi is on the setup screen to activate debug mode.

When debug mode is off, it's 1,5 sec faster.

The query :

[{"jsonrpc":"2.0","id":1,"method":"Playlist.Clear","params":{"playlistid":0}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2944}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2945}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2946}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2947}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2948}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2949}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2950}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2951}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2952}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2953}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2954}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2955}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2956}}},{"jsonrpc":"2.0","id":1,"method":"Player.Open","params":{"item":{"playlistid":0,"position":1}}}]

The pure http / network data :

curl --trace-time --verbose -H "Content-Type: application/json" -d @curl2.txt http //192.168.0.9:80/jsonrpc (Removed : to disable autolinking)

10:16:29.250000 * About to connect() to 192.168.0.9 port 80 (#0)
10:16:29.250000 * Trying 192.168.0.9... connected
10:16:29.265000 > POST /jsonrpc HTTP/1.1
10:16:29.265000 > User-Agent: curl/7.23.1 (x86_64-pc-win32) libcurl/7.23.1 OpenS
SL/0.9.8r zlib/1.2.5
10:16:29.265000 > Host: 192.168.0.9
10:16:29.265000 > Accept: */*
10:16:29.265000 > Content-Type: application/json
10:16:29.265000 > Content-Length: 1448
10:16:29.265000 > Expect: 100-continue
10:16:29.265000 >
10:16:29.281000 < HTTP/1.1 100 Continue
10:16:38.531000 < HTTP/1.1 200 OK
10:16:38.531000 < Content-Length: 586
10:16:38.531000 < Content-Type: application/json
10:16:38.531000 < Date: Thu, 12 Jun 2014 08:16:41 GMT
10:16:38.531000 <
[{"id":1,"jsonrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{
"id":1,"jsonrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{"i
d":1,"jsonrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{"id"
:1,"jsonrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{"id":1
,"jsonrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{"id":1,"
jsonrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{"id":1,"js
onrpc":"2.0","result":"OK"},{"id":1,"jsonrpc":"2.0","result":"OK"},{"id":1,"json
rpc":"2.0","result":"OK"}]
10:16:38.531000 * Connection #0 to host 192.168.0.9 left intact
10:16:38.531000 * Closing connection #0

The Xbmc logs with details on curl / json activated.
There's 2 hours and some sec diff in time since net time did not worked when I setup this test rpi.
Empty lines means not needed logs data, but nothing was removed in the main part to confirm no other access from Yatse or anything

07:04:58 35.154659 T:3058802688 NOTICE: Starting XBMC (14.0-ALPHA1 Git:0efea90). Platform: ARM Linux 32-bit
07:04:58 35.155018 T:3058802688 NOTICE: Using Release XBMC x32 build, compiled May 4 2014 by GCC 4.9.0 for ARM Linux 32-bit 3.14.2
07:04:58 35.173672 T:3058802688 NOTICE: Running on Linux 32-bit (OpenELEC_Helix (Milhouse) - Version: devel-20140503235917-r18335-gb2d3626, 3.14.2 armv6l)


08:16:31 4328.187012 T:2709517392 DEBUG: webserver: request received for /jsonrpc
08:16:31 4328.194824 T:2709517392 DEBUG: JSONRPC: Incoming request: [{"jsonrpc":"2.0","id":1,"method":"Playlist.Clear","params":{"playlistid":0}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2944}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2945}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2946}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2947}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2948}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2949}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2950}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2951}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2952}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2953}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2954}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2955}}},{"jsonrpc":"2.0","id":1,"method":"Playlist.Add","params":{"playlistid":0,"item":{"songid":2956}}},{"jsonrpc":"2.0","id":1,"method":"Player.Open","params":{"item":{"playlistid":0,"position":1}}}]
08:16:31 4328.215820 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnClear from xbmc
08:16:31 4328.216309 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
08:16:32 4328.836914 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:32 4328.837402 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:33 4329.467773 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:33 4329.468750 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:33 4330.073730 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:33 4330.074219 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:34 4330.685059 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:34 4330.685547 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:34 4331.295898 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:34 4331.296875 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:35 4332.009766 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:35 4332.010742 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:36 4332.614746 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:36 4332.615723 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:36 4333.222168 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:36 4333.227051 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:37 4333.845215 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:37 4333.845703 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:38 4334.478027 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:38 4334.478516 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:38 4335.095703 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:38 4335.096680 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:39 4335.708008 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:39 4335.708984 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:40 4336.338379 T:3058802688 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:16:40 4336.338867 T:3058802688 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:16:40 4336.343262 T:3058802688 DEBUG: CPlayerCoreFactory::GetPlayers(nfs://192.168.0.51/volume3/RED/music/Brit Pop/Blur/Albums/[1999] 13/Blur - 13 - 02 - Bugman.mp3)



08:16:40 4336.360840 T:3058802688 DEBUG: SECTION:LoadDLL(libnfs.so.1)
08:16:40 4336.369141 T:3058802688 DEBUG: Loading: libnfs.so.1
08:16:40 4336.542480 T:3058802688 DEBUG: NFS: Context for 192.168.0.51/volume3/RED not open - get a new context.
08:16:40 4336.752441 T:3058802688 DEBUG: NFS: Connected to server 192.168.0.51 and export /volume3/RED

[wingnutkj]

Tolriq, did you get any further with this? I recently upgraded my ATV1200 Android box to Gotham 13.1, and have noticed the same slowness when playing from Yatse (which I'm a big fan of BTW). Log file shows similar pattern with the OnAdd messages for each track coming back slowly. I figure that it's something XBMC internal and therefore not your problem, but was wondering if you knew about anything being done to it (i.e. whether it's worth installing the 13.2 RC)?

Ta!

[Tolriq]

Well as you said it's 100% XBMC side And since this thread was dead I'm not aware of anything being done to it.

If you do not need specific track ordering or filter you can just long press albums/artists/genre to start them, but well this just a workaround.

[CUL8R]

Please reactivate this thread.
I really love Yatse and love XBMC / Kodi, but this is driving me nuts.
Starting a single song takes up to a minute since the upgrade to Gotham or now Helix. Thought this might be improved in this release
Playing the whole album is faster but still at least 10-20 seconds.
Database is quite large, but structure is always : Artist/Album/Song

Please get this fixed, I really think of changing to another MediaCenter or trying Plex because of this.

Using RasperryPi B, Raspbmc with Kodi Helix latest version, Yatse latest update, external NAS as Music storage via WIFI

[Bosse_B]

I also experience long waiting when playing mp4 files. Yesterday I downloaded a 1 GB file from the STV Play service and then navigated to it via XBMC playing files (no library).
Still it took about half a minute with LOADING... displayed and then sound started but no picture.
After some further wait picture appeared but really stuttering.
Finally after a few minutes it all stabilized and played fine.
So the startup is the real annoyance!

My system is a Pi-B with RASPBMC latest version (Gotham 13.2). Wired Ethernet 100 Mbit connection to the Synology DS212j NAS and Internet.

I always put videos from my Win7 PC on this NAS and then navigate to it in XBMC using the Video/File path.

I don't understand all this talk about databases and "scraping", to me it seems simple enough:
There is a video file on a network store disk, which is navigated to via XBMC and then selected for playing.
Seems that there is no database involved in such action so there should be no real delay in starting and yet it is.

[CUL8R]

Tried the same with OpenElec instead of RaspBMC yesterday, let it create a completely fresh database.
Exactly the same results, every start takes forever. If you skip to the next track in same album, it works fast. Everything else takes its time.
So it really might have something to do with the creating of a playlist.

[CUL8R]

Switched back and set up a complete RaspBMC Frodo 12.3 version thats working real fast. Song start takes less than 5 secs which is what I expect.
As long as there´s no bugfix for this I will stay with the old version, although some other parts are not as good as the KODI, but I can live with that.

[CUL8R]

***** BUMP *****
please address this soon !!
I tried to update to OSMC with the latest KODI but still remotely selecting from YATSE or any other XBMC / KODI remote takes forever.