Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[Mr. Odd]

I've been using the JRiver MC / BubbleUPnP Server & remote combo for years. I reboot my server overnight automatically. BubbleUPnP remote on Android loads my artist list instantly (about 1000 entries) ONLY the first time each day and then subsequently there's a delay - it loads the first 10, then the first half after about 15s then the rest after another 15s. I've never understood what causes the delay, clearly it's not cached.

Do other Android remotes allow access to your MC library outside of your home wifi (ie on a cellular connection)? The last time I looked at MO4Media, it didn't support that function.

I still use EOS occasionally when I want to look up play stats remotely, it's the only remote I know of that lets me review the "Last Played" field.

[Awesome Donkey]

BubbleUPnP remote on Android loads my artist list instantly (about 1000 entries) ONLY the first time and then subsequently there's a delay - it loads the first 10, then the first half after about 15s then the rest after another 15s. I've never understood what causes the delay, clearly it's not cached.

This. THIS. This same exact thing happens to me too, as I noted above, and I have no idea why it does this (and I've tried multiple things to try to workaround it and nada). This is the main reason I can't use BubbleUPnP at all. Well, this and the whole mess with how it deals with adding entire albums (it only adds the track you select and the sequential tracks, and not all previous tracks too) to now playing annoys the living hell out of me with no option to set it the way I'd like.

Do other Android remotes allow access to your MC library outside of your home wifi (ie on a cellular connection)? The last time I looked at MO4Media, it didn't support that function.

Yes, you have to forward and open specific ports (52199-52200) and use an access key. I can access my library with JRemote2, MO 4Media, etc. outside my network using mobile data just fine.

[stanger89]

Have you tried updating JRiver for Android?  It's been less rocky recently.

I missed this reply, I guess I didn't subscribe to this topic.

I just checked and as of right now I'm using 32.0.03, and still having the same issues, documented here:
https://yabb.jriver.com/interact/index.php/topic,137690.0.html
https://yabb.jriver.com/interact/index.php/topic,137429.0.html

Namely, if the Bluetooth connection is broken, I have to force stop and restart Jr4A to get playback to work again.  And today playback is just "glitchy" just slight pauses in playback somewhat frequently (at least once/song I'd guess).

[markf2748]

... and the whole mess with how it deals with adding entire albums (it only adds the track you select and the sequential tracks, and not all previous tracks too) to now playing annoys the living hell out of me with no option to set it the way I'd like.

See attachment for one way to add an entire album to an empty Android BubbleUPnP Playlist.  "Add+" button in Step 5 is key; the confirmation popup at the bottom vanishes after about 2 seconds.  However you can also do it straight from Step 3 (possibly multiple albums) and Step 4, in both cases using the 3 dot menu > Enqueue.  There are also other "Enqueue" options, depending on your selection.  It's all pretty straightforward and works well for me.

Some of my settings are shown in the second attachment.  Note I have Audio Cast turned off in my use case.  I am also running BubbleUPnP Server on the MC PC Server computer to create DLNA zones in MC and transcode for Chromecast Audio renderers.   I have not fully tested whether that server impacts the Android Player performance in any other way, but I am inclined to think it does not.

Aside:  It is possible to have Android BubbleUPnP connect directly to BubbleUPnP Server, including from outside the home network, but that is not the subject here. https://www.bubblesoftapps.com/bubbleupnpserver2/docs/connect_with_bubbleupnp.html

I can't reproduce your loading problem.  Bubblesoft has E-mail tech support and an active forum if you are inclined to pursue this issue.

[markf2748]

... Bubble Device Discovery beats MC Device Discovery (and hence all apps that depend on it) hands down in my home wi-fi network....

Recently, in Version 32.0.21 (2/27/2024), JRiver addressed issues related to their server performance and blocking error messages which could cause network device zones to "randomly vanish" or never appear under MC Playing Now.  Since these fixes, the MC server has effectively become much more reliable.   

[bubbleguuum]

I mean, I can understand where you're coming from. Though to be honest my experience with BubbleUPnP has been a bit... annoying to deal with.

My main issues with BubbleUPnP on Android are 1) it is very slow at loading the list of my music library's artists (which is over 1,200) compared to JRemote2, MO 4Media and Panel with BubbleUPnP taking up to 30 seconds to load the entire list from A to Z. The remote apps on the other hand must cache this or handle it differently or something, because it loads the entire list near instantly. Same for albums (over 10,000) too, it's not just the artists list that's slow to load in BubbleUPnP. 2) is with how it handles now playing, you can select a track (e.g. track 2 of a 10 track album) and have it play the selected track and add the remaining tracks of the album to the now playing playlist. The problem with that is a) it doesn't add tracks before it like you'd expect it to do if it was playing back an entire album and b) it removes played tracks from the playlist. I don't think there's any options to play a certain song and add all tracks (including preceding tracks) to the now playing list. This one is almost a dealbreaker for me, it's quite annoying.

BubbleUPnP dev here.

1. Using MC 32.0.20, I cannot reproduce the slow loading 'Artist' folder you describe. Assuming it is the root 'Artist' folder.
It loads nearly instantly in less than 2s every time for me for about 500 artists. I have no explanation why it would be slow.
If you want to send me a log file, let me know for instructions.

2. There are many ways to play/enqueue tracks in BubbleUPnP as described in a detailed post above.
If you wish, you can change the default tap action on an item in More > Settings > Library > Item tap action. There are also various play/enqueue choices in the 3 dot menu of a track.

[Awesome Donkey]

The latest BubbleUPnP seems to addressed my second issue, with the Play all items, playback starts at tapped item option (which if this was an option before and I didn't see it even after going through all tap item options, I really must be going blind).

But the slow loading still happens, and yes it's with Artist (specifically with the view set to Album Artist (auto) and then Album, which should be typical for Artist). Sure, what's the log instructions?

[bubbleguuum]

The latest BubbleUPnP seems to addressed my second issue, with the Play all items, playback starts at tapped item option (which if this was an option before and I didn't see it even after going through all tap item options, I really must be going blind).

Yes this choice is new and I added it in the latest version as another user made me notice it was lacking.

But the slow loading still happens, and yes it's with Artist (specifically with the view set to Album Artist (auto) and then Album, which should be typical for Artist). Sure, what's the log instructions?

Send me (at bubblesoftproducts@gmail.com) a log file, loading that Artist folder that takes forever to load (let it load completely):

- launch the app
- go into More > Settings > Control
- Enable "logging to file" (at the end of the page).
- IMPORTANT: Exit the app (More > Exit)
- restart the app
- load that Artist folder that takes forever to load (let it load completely)
- exit the app (More > Exit)
- email me the files found on internal storage:

On Android 10 and below:

/Android/data/com.bubblesoft.android.bubbleupnp/log.txt
/Android/data/com.bubblesoft.android.bubbleupnp/prev_log.txt (if present)

On Android 11 and higher:

/Downloads/com.bubblesoft.android.bubbleupnp_log.txt
/Downloads/prev_com.bubblesoft.android.bubbleupnp_log.txt (if present)

You can access them with a file manager app and share them to your email app for sending them.

IMPORTANT: Make sure to not restart BubbleUPnP until you have sent or saved the log file as it is overwritten on app startup.

[Awesome Donkey]

Groovy, sent! Hopefully it helps.

[markf2748]

One thing I notice is that @AD refers to views which I assume are in his MC Library, such as "Album Artist (auto)", when choosing a library within Bubble.

The library views which I see in Bubble (first attachment) are apparently its defaults for a Generic DLNA library, which is what I get with BubbleUPnP Server transcoding for my Chromecast Audio renderers in MC.  I don't see my named MC Audio Views (2nd attachment) in Android BubbleUPnP.  However, the contents (albums) of the Bubble generic library views agree in full with my MC media library views:  all load quickly, are ordered as expected, and play fine.

On the other hand, MO 4Media, JRemote2, Gizmo, and JRiver Panel all show six library view names which exactly match the six selected in:
**  MC Options > Media Network > Advanced > Customize views for JRemote, Gizmo, & Panel... (third attachment).

I point out this difference in Library view names between Bubble (as I use it) and the other Android apps, just in case it's relevant.

Bubble appears to be less dependent on the MC Tree than the other apps.  But with JRiver's recent improvements, I speculate equivalence between Bubble and the other apps wrt network device discovery.

3/9/2024 Update:  Android BubbleUPnP displays exactly the same named library views as the other players when I select the views in:

**  MC Options > Media Network > Add or configure DLNA servers > Generic DLNA > Customize views > Add > Library item from Standard View > Audio\.......

I then find it necessary to select and edit each view under "... > Generic DLNA > Customize views... > Edit > Expression to display" to remove my custom formatting which is not interpreted by BubbleUPnP and hence appears as literal text in its library listings.

Apologies for the confusion around this subject.  Maybe the post will help someone else.

[bubbleguuum]

Groovy, sent! Hopefully it helps.

Thanks for the log.

It shows that MC is super slow handling http Browse UPnP action requests emitted by BubbleUPnP:

Code: [Select]

[AsyncTask #1 (72)                       ] INFO     - 0:00:04.923    - BrowseTask.doInBackground(): loading container 'Artist'
...
[cling-62 (Browse) (188)                 ] INFO     - 0:00:23.368    - HTTP request took a long time: http://192.168.1.131:52100/ContentDirectory/control took: 17801 ms
...
[cling-27 (Browse) (131)                 ] INFO     - 0:00:46.203    - HTTP request took a long time: http://192.168.1.131:52100/ContentDirectory/control took: 22811 ms


First Browse action to get the first 16 items takes 17 seconds. Second action to get the rest takes 22s.
This is not normal: MC is slow to respond to these requests for an unknown reason.
Does it happen only on this 'Artist' folder ?

[Awesome Donkey]

No, it happens with 'Album' too, which has over 10,000 entries so it takes much, much longer to load.

Worth noting that with my MC32 server and using BubbleUPnP on my network I do 1) indeed have UPnP enabled on my router and 2) have ports forwarded (52100-52200 for MC and with 58050 and 58051 for BubbleUPnP) so *hopefully* the issue isn't there and finally 3) MC is granted full firewall access for both inbound and outbound connections. The Intel N305 NUC running the MC32 server is connected via 1G ethernet directly to my router (which is a WiFi 6 Netgear Nighthawk router) but it's likely not related to the NUC itself as this issue has existed for years at least and did happen when the MC server was on both a Raspberry Pi 4B and Orange Pi 5B. I mean, I could change/upgrade networking and see if that changes anything (and I do plan on doing that soon actually as fiber is coming to my area and I'd like to have WiFi 7 and 10G networking). Any ideas to try as workarounds or is it something JRiver will have to look into?

Strange regardless though that it's responding slow like that, even though it *shouldn't*.

[markf2748]

Re network aspects and possible interference by other devices (I may be preaching to the choir here, but I'll put it out anyway):

As a test, can you simplify your network to the bare minimum?  Turn off other computers and unnecessary network appliances like switches.  If things improve, then turn other stuff on one at a time.

Simplify your router settings.  You should not need UPnP turned on if you pare it down to testing just local wi-fi, and you should not need port forwarding either.  MC networking ports must be open/allowed, but do not need to be forwarded for local connections.  Same if you are running BubbleUPnP Server. 

Bubble does not need to create any OpenHome renderers if you are dealing only with DLNA.

Is your router firmware up to date?  Log into router and check for updates.

You may also learn something by watching MC's server traffic, using Tree > Services & Plug-ins > Media network.  Watch the Activity Log for each of the 5 servers individually, maybe with and without Bubble running.  There's not a lot of message info revealed (I've requested that be improved, more than once), but you can at least see IP addresses and their basic DLNA headers.

Of course there is always Wireshark, very revealing, but that's considerably more work.

Re library size:  Create a small library of just a few albums and load that into MC.  If Bubble is OK with it (obviously it should be very fast), then incrementally increase the size, maybe 500 albums, 1000, etc. looking for a threshold that ignites the problem.  Your library is unusually large, so it's hard for most users to simulate it.

[bubbleguuum]

UPnP IGD settings on routers have nothing to do with UPnP AV used by MC and BubbleUPnP.
UPnP IGD is for programs (often games) to automatically add NAT rules to open ports for networking.

Other than that, MC is taking a long time to respond to these http Browse requests, which is very unusual.
I cannot reproduce it, so cannot investigate further.
Maybe it is caused by some combination of settings in MC.

[Awesome Donkey]

I split this discussion from the remotes topic and moved it to the Media Network section, as I feel it's likely something to investigate further here and I feel it deserves its own topic.

Bob, if you're reading this, any ideas why MC would be responding very slowly to the UPnP HTTP browse requests in this instance?

[Awesome Donkey]

Mr. Odd, would you happen to be using Audio Only Mode? If so, what happens if you disable it and re-enable Images, TV and Video support in MC?

The reason I ask is, once I disabled Audio Only Mode and restarted MC, for whatever reason it seems to be responding much quicker to BubbleUPnP's requests and loading the lists faster. I have no idea why that could be the case though, and it does still respond slowly sometimes though not nearly all the time like before, so it could be a fluke but something to maybe try.

[Mr. Odd]

As a matter of fact, yes, I'm running Audio Only mode. I switched it off and rebooted and, yes, suddenly the Artist list populates immediately whenever I go into BubbleUPnP on my Android phone. However, I noticed why: BubbleUPnP Server is adding a new instance of my MC server each time! The extraneous entries disappear when I reboot my Windows machine but it starts again whenever I access MC via BubbleUPnP.

[Awesome Donkey]

Interesting. I've also re-enabled all of Media Center's features I disabled previously and will do more testing.

Also I noticed when the issue does eventually happen (it takes 3 or 4 or so loads of the Artists list in BubbleUPnP before it does a slow load) I noticed MC's CPU usage spike while it's loading (slowly) in BubbleUPnP then it goes back to normal once it finally loads.

[markf2748]

As a matter of fact, yes, I'm running Audio Only mode. I switched it off and rebooted and, yes, suddenly the Artist list populates immediately whenever I go into BubbleUPnP on my Android phone. However, I noticed why: BubbleUPnP Server is adding a new instance of my MC server each time! The extraneous entries disappear when I reboot my Windows machine but it starts again whenever I access MC via BubbleUPnP.

@Mr Odd:  I have no idea what is going on here, but please clarify what you mean by "MC server", assuming you are running MC as a PC Network Server.  Here is what I find (presumably "normal"):

1) Windows Services: a single instance of  "JRiver Media Center 32 Service".

2) Windows Task Manager: one instance of "Media Center 32" and one of "Media Center Service (JRService.exe)".

3) MC "Tree > Services & Plug-ins > Media Network > Server"[/i]:  5 different types of MC Servers indicated as running simultaneously (selected options:  Authentication, DLNA Server, DLNA Renderer, and DLNA Controller).
Note:  Tab "SSDP (Device Discovery)" also lists other servers and renderers detected by MC on the network along with their IP addresses.  After hitting the "Rescan" button to update the tab I find it accurately depicts the network.  The list of renderers usually, but not always, carries over to MC's list under Playing Now. 

4) Windows File Explorer > Network:  MC PC is listed twice in Media Devices (as Generic DLNA and as Player) and once in Other Devices as a Library Server.

In 1) it is possible to see other older instances, like "JRiver Media Center 31 Service", ...30.., etc. running simultaneously if they have not been fully uninstalled or disabled here by Startup Type: Disabled.

I have looked at 1) and 2) in the past well over a hundred times, including during remote testing, and don't recall ever finding more than one instance of any of those processes per MC version.

In 3), I have never ever seen more than the normal 5 servers - it's always all 5 or none.  I just tried playing music simultaneously on my MC server's local Player and on a remote renderer using Android BubbleUPnP controller playing from the PC server.  Still only single instances.

I kind'a guess you were watching 4) - I don't think I've ever seen extra MC instances here, but I don't look at it much.  In the past I've seen other network applications generate many multiple instances here that had to be manually deleted.  Old Netgear Genie software did this.  I've also seen HP Printer drivers interact with Windows 11 to create multiple instances of networked printers - they have a special fix for this.

In the Tree I primarily use Audio views, along with some Images views to show sidecar album artwork.  I typically have "View > Audio Only Mode" deselected, though I have selected it occasionally in prior versions without adverse effect AFAIR.

3/14/2024 List selected options in 3).
3/18/2024 Updated Note in 3) re SSDP Rescan.

[Mr. Odd]

@Mr Odd:  I have no idea what is going on here, but please clarify what you mean by "MC server", assuming you are running MC as a PC Network Server.  Here is what I find (presumably "normal"):

I am using BubbleUPnP Server (https://bubblesoftapps.com/bubbleupnpserver2/) on Windows to access my MC server. It keeps track of multiple media servers if you have them, but I have just the one. For some reason, turning Audio Only mode off and then loading the Artist list from BubbleUPnP on my Android phone was creating duplicate entries in the BubbleUPnP Server listing. This behavior doesn't happen when using Audio Only mode.

[markf2748]

I am using BubbleUPnP Server (https://bubblesoftapps.com/bubbleupnpserver2/) on Windows to access my MC server. It keeps track of multiple media servers if you have them, but I have just the one. For some reason, turning Audio Only mode off and then loading the Artist list from BubbleUPnP on my Android phone was creating duplicate entries in the BubbleUPnP Server listing. This behavior doesn't happen when using Audio Only mode.

I run BubbleUPnP Server (currently ver. 0.9-update49) on the PC Server all the time as a service, for years.  When I open Android BubbleUPnP player, I see one instance of the phone show up on the BubbleUPnP Server configurator web page under the Media Servers tab (attached).  I see the same thing whether or not MC Audio Only Mode is on or off (relaunched MC between trials for extra assurance), and always get a fast load of the MC library on Android BubbleUPnP.  I don't recall ever seeing multiple instances of Android BubbleUPnP here.

When I have Android BubbleUPnP play to a chromecast (DLNA) renderer or to the phone, they show up under the configurator's Media Renderers tab, as expected.

The Bubble Configurator page is something I look at occasionally - it's especially valuable when troubleshooting the media network - but otherwise I have no need to view it.

[Awesome Donkey]

Interesting, I haven't seen that happen (yet) but I'll keep watching. Still seeing inconsistent results with it loading lists quickly more times than not in BubbleUPnP, but it still does indeed happen. The only correlation I can make here is that pretty large libraries are being used, and it may not be something that's explicitly tested for and it may be some obscure issue. I did enable logging in MC and reproduced the slow load, but looking at the log long load entries do appear but it doesn't say why.

I got foobar2000 with foo_upnp loaded up and importing my library now to do comparison tests, maybe the same thing will happen with it? I have tried using it with and without BubbleUPnP Server (along with the proxy option enabled and disabled for MC) and it doesn't seem to make a difference there.

[Awesome Donkey]

An update.

Yes, still experiencing the slow load issue with MC and BubbleUPnP. It's rather strange because it happens with MC at random, but with foobar2000 (with foo_upnp) it loads up instantly every time in BubbleUPnP. I decided to pull the trigger and start from scratch with my entire network. I bought a new router (TP-Link tri-band router with WiFi 7, 2X 10G and 4X 2.5G), a new NAS (QNAP 2-bay with SSD cache drive), a new 2.5G switch and a lot of new UGREEN Cat 8 cables and it all should arrive today. Once I get everything set up and moved over to the new NAS I'll be performing new tests but I have a sneaking suspicion the issue will remain. >.> On the bright side, upgrade from 1G to 2.5G networking (and 10G networking once I get a 10G switch and more devices that can use it).

EDIT: As expected, the slow issue still remains with a whole new, much faster network. Likely an MC issue unfortunately, which is a bit of a bummer. =\

[Awesome Donkey]

So there's a problem in MC when it comes to UPnP sometimes being slow responding to HTTP action requests, which a discussion has been ongoing here: https://yabb.jriver.com/interact/index.php/topic,138392.0.html

The main symptom of this is when using an app like BubbleUPnP to connect to the MC server, and have it try to load very large lists of Artists (1,246 in my case) and Albums (10,768 in my case) which the mass majority are in FLAC with some DSF content. Sometimes it loads very quickly (near instantly really), whereas other times it loads slowly with it loading parts of the list slowly in chunks, taking 7+ seconds each time for each chunk it's loading.

In the screenshot example, MC takes over 7 seconds to respond with 156 KB of data. And as mentioned it'll do this multiple times as it's loading the large lists of Artists and Albums in chunks.



This is with a brand new network setup from scratch with a WiFi 7 router which all wired devices (including the MC server) are connected with 2.5GbE LAN along with 5GbE to the NAS, which is also brand new and fast. All ports are forwarded and are confirmed to be open. However I noticed this for years now with my previous two network setups, and I assumed it was a BubbleUPnP issue until the dev responded to me after I mentioned it and the dev looked at a log and saw MC was responding to UPnP HTTP action requests slowly.

I've been able to come to a few conclusions;

1. I'm not the only one experiencing it, Mr. Odd in the topic also is. It's likely pretty rare that requires certain conditions like a large library.

2. It doesn't always happen. Once I disabled Audio Only Mode, it seems to work (as in load near instantly) more than not, but it still happens. Also tried the new Error Free Mode button too, doesn't make a difference.

3. I've reset MC to all default settings including default Media Network settings, still does it.

4. I've tried every advanced DLNA server setting, no difference.

5. Happens on multiple devices, not just my Android 14 phone with BubbleUPnP. Haven't tried any other apps yet, not sure of any good ones besides BubbleUPnP.

6. I've enabled logging on the MC32 server and reproduced the issue and looked at the logs. It does indeed show slow responses taking multiple seconds, but doesn't really give any reason why.

7. Obviously in JRemote2, MO 4Media, Panel, etc. the lists load very quickly, but then again those likely don't use UPnP there.

8. I did setup foobar2000 with foo_upnp as a test to see if it does it too, but it doesn't. It loads the lists near instantly though I don't like how it arranges the lists at all, MC's way of arranging the list is perfection.

9. I installed the BubbleUPnP Server app and enabled the proxy settings to see if it could help... as expected, it doesn't.

Any thoughts?

[bob]

UPnP ALWAYS loads in chunks. You specify a number of records to return when you make a request.
The default is usually around 1000.

There haven't been any changes in this area for as long as I can remember.
Hanging like that makes it sound like something else is going on.
Perhaps simplify the situation. Turn off any auto-imports of there are any enabled to see if that makes a difference.

[Awesome Donkey]

Turn off any auto-imports of there are any enabled to see if that makes a difference.

I keep auto-import disabled, as I prefer to run it manually myself when I make library changes using the run auto-import button on the bottom left in the screenshot. Just so strange that it just seems to hang like that.

There haven't been any changes in this area for as long as I can remember.

Yeah, it's been around for at least 6 years now, but I always thought it was on BubbleUPnP's end, hence why I never looked into it further.

UPnP ALWAYS loads in chunks. You specify a number of records to return when you make a request.
The default is usually around 1000.

Is there a way to change this? Hmmm, this could be helpful in testing if there is. Like would a larger number, maybe like 15000, work? Or would a lower number?

[bob]

I keep auto-import disabled, as I prefer to run it manually myself when I make library changes using the run auto-import button on the bottom left in the screenshot. Just so strange that it just seems to hang like that.

Yeah, it's been around for at least 6 years now, but I always thought it was on BubbleUPnP's end, hence why I never looked into it further.

Is there a way to change this? Hmmm, this could be helpful in testing if there is. Like would a larger number, maybe like 15000, work? Or would a lower number?

I don't see in your screen shot above an indication that it's taking 7 seconds. Are you saying that's from log entries?
If you are looking at the log entries, what call is the bubble making? Browse? Browse Children? Search?

[Awesome Donkey]

I don't see in your screen shot above an indication that it's taking 7 seconds. Are you saying that's from log entries?
If you are looking at the log entries, what call is the bubble making? Browse? Browse Children? Search?

I believe it's HTTP UPnP browse action requests (and I do see Browse BrowseDirectChildren in the log too, maybe it's either one). On the BubbleUPnP side its log (which this is an old log from days ago that the Bubble dev looked at and commented on) it indicated it took 17 seconds to load the first 16 items, and so on and so forth. I'll have to re-enable logging in BubbleUPnP and log at the same time as MC does on its side.

Code: [Select]

[AsyncTask #1 (72)                       ] INFO     - 0:00:04.923    - BrowseTask.doInBackground(): loading container 'Artist'
...
[cling-62 (Browse) (188)                 ] INFO     - 0:00:23.368    - HTTP request took a long time: http://192.168.1.131:52100/ContentDirectory/control took: 17801 ms
...
[cling-27 (Browse) (131)                 ] INFO     - 0:00:46.203    - HTTP request took a long time: http://192.168.1.131:52100/ContentDirectory/control took: 22811 ms
There's a fresh MC log taken while the slow loading was occurring in BubbleUPnP. I do see some read failed unknown error messages in the log but not sure if that has anything to do with it.

Anything interesting?

[markf2748]

Anything interesting?

I don't pretend to know anything about MC logs, but a quick scan through your log file shows most operations in the 25-32 ms range.

However, there are what seem to be long time entries, all associated with "Sharing Plugins: ... Uknown error" (first underlined integer is the line number in Notepad++):

2267    0032776: 2060: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 4544)
2268    0032776: 2060: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30009 ms)

2420     0037655: 14044: Sharing Plugins: CContentDirectoryService::HandleControlFunction: Finish (15893 ms)
2421     0037663: 14044: Sharing Plugins: CDLNADeviceServerWorker::ProcessPost: Finish (15901 ms)

2545    0041029: 13044: Sharing Plugins: CUDPSocketReader::Accept: Finish (12026 ms)
2661   0042718: 4676: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 4160)
2662   0042718: 4676: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30477 ms)

2676-2680
0042923: 2012: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 2024)
0042923: 2012: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30679 ms)
0042923: 2012: General: CReferenceCountedSocket::Close: SOCKET_DEBUG: closesocket() closing 2024
0042939: 11376: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 4136)
0042940: 11376: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30698 ms)

ahhh... maybe those are just elapsed times from some t=0, not time intervals, in which case they are of order 10-20 ms?  But maybe there is some sort of plug-in issue here.

[bob]

I don't pretend to know anything about MC logs, but a quick scan through your log file shows most operations in the 25-32 ms range.

However, there are what seem to be long time entries, all associated with "Sharing Plugins: ... Unknown error" (first underlined integer is the line number in Notepad++):

2267    0032776: 2060: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 4544)
2268    0032776: 2060: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30009 ms)

2420     0037655: 14044: Sharing Plugins: CContentDirectoryService::HandleControlFunction: Finish (15893 ms)
2421     0037663: 14044: Sharing Plugins: CDLNADeviceServerWorker::ProcessPost: Finish (15901 ms)

2545    0041029: 13044: Sharing Plugins: CUDPSocketReader::Accept: Finish (12026 ms)
2661   0042718: 4676: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 4160)
2662   0042718: 4676: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30477 ms)

2676-2680
0042923: 2012: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 2024)
0042923: 2012: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30679 ms)
0042923: 2012: General: CReferenceCountedSocket::Close: SOCKET_DEBUG: closesocket() closing 2024
0042939: 11376: Sharing Plugins: CTCPSocketReader::Read: Read failed: Unknown error (10060) (socket: 4136)
0042940: 11376: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (30698 ms)

ahhh... maybe those are just elapsed times from some t=0, not time intervals, in which case they are of order 10-20 ms?  But maybe there is some sort of plug-in issue here.

The timings in parentheses are the time the function took to run.
Those usually indicate a hung DLNA device on the network.
But these could indicate an issue with Bubble not closing a socket after the browse command
2420     0037655: 14044: Sharing Plugins: CContentDirectoryService::HandleControlFunction: Finish (15893 ms)
2421     0037663: 14044: Sharing Plugins: CDLNADeviceServerWorker::ProcessPost: Finish (15901 ms)

[Awesome Donkey]

Hmmm, any other good app recommendations besides BubbleUPnP to test this more?

[bob]

So here appears to be the deal. Bubble is specifying search terms on the browse. Each one causes a database search.
0011146: 14044: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Con Funk Shun] [Media Type]=[Audio]; Elapsed ms: 28.166
If each one takes 28 ms and there are 1000 per batch, that's 28 seconds.

It also appears that bubble is doing overlapping (threaded) searches.

It might help to reduce the allowed batch size to 100. but I'm not sure how that would work with the overlapping searches.

The behavior I've seen from other implementations is to simply specify * as the browse and do the sort on the client side. Not sure why bubble is sending the filters for each item.

Another option would be for bubble to load the DB with a search command instead of browse. Then it loads all at once. That's what MC does when it loads a DLNA database from another server.

[markf2748]

FWIW, I read the log.txt file into excel and added an entry-to-entry time-interval column on the left.  Longer interval lines are highlighted in yellow.

I also highlighted longer reported function durations in orange (Column H).  Quite a few exceed 500 ms.  But even those in the 100-500 ms range still add up to multiple seconds, another indicator that the whole process is slow.

The attached pdf version is best read by zooming in single-page view.

[Awesome Donkey]

Interesting, and that PDF helps a lot, thanks for that! Might be worth posting the search info Bubble is doing in the topic so the dev can see it.

[bob]

If you follow the beginning of a thread, like 7208

Code: [Select]

0013154: 7208: Sharing Plugins: CHTTPListenerWorker::HandleRequest: TCP: 192.168.1.144: POST: http://192.168.1.131:52100/ContentDirectory/control
0013154: 7208: Sharing Plugins: CDLNADeviceServerWorker::ProcessPost: Start
0013154: 7208: Sharing Plugins: CContentDirectoryService::HandleControlFunction: Start
0013154: 7208: Sharing Plugins: CContentDirectoryService::HandleControlFunction: Action: Browse
0013154: 7208: Sharing Plugins: CContentDirectoryService::Browse: Start
0013154: 7208: Sharing Plugins: CContentDirectoryService::Browse: Browse BrowseDirectChildren for 1000
And follow it to the end:

Code: [Select]

0021660: 7208: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Jay/-Z & Metallica] [Media Type]=[Audio]; Elapsed ms: 27.200
0021688: 7208: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Jay/-Z & The Beatles] [Media Type]=[Audio]; Elapsed ms: 27.549
0021689: 7208: Sharing Plugins: CContentDirectoryService::Browse: Finish (8534 ms)
You'll see that one for example took 8.5 seconds. Specifying [Album Artist (auto)] as part of the browse filter appears to take twice as long per item.
You can also see in the log that the first few queries are relatively short then they get longer hitting the maximum per query I believe.


The long UDP queries are associated with the SSDP search and probably refer to a problematic device.

[Awesome Donkey]

Other than that, MC is taking a long time to respond to these http Browse requests, which is very unusual.
I cannot reproduce it, so cannot investigate further.
Maybe it is caused by some combination of settings in MC.

I would be very interested in your opinion on what Bob posted above, especially the part about loading the database with a search command instead of browse, if that's feasible in BubbleUPnP as a tweak option or not.

[bubbleguuum]

Hi,

I just caught up on this topic from my latest post as I did not get notification of replies (thought I had them enabled but apparently not).

When browsing MC folders in the Library tab, BubbleUPnP only emits Browse UPnP actions (BrowseDirectChildren) with no filter (ie with the Filter argument set to "*").

The only case when it emits Search UPnP actions is when you use the Search Library functionality (magnifying glass icon) where it starts 6 or 7 concurrent search requests with various filters. It also uses it to populate "Random Tracks" and "Random Album" folders.

What I observed in the BubbleUPnP log I analyzed, is slow BrowseDirectChildren requests on the 'Audio > artist' folder, as in MC taking a while to reply to these requests, which I could not reproduce.

For browsing a folder, BubbleUPnP emits an initial BrowseDirectChildren request to get the first 16 items (to have something to display immediately), then gets the remaining items with subsequent BrowseDirectChildren requests of 500 items each.

Here is the analyzing of the BubbleUPnP log (with timestamps) for the slow load of the 'Audio > Artist' folder (list of all artists folder, ObjectID = 1000), with my comments after //:

 [AsyncTask #1 (72)                       ] INFO     - 0:00:04.922    - BrowseTask.doInBackground(): enter
[AsyncTask #1 (72)                       ] INFO     - 0:00:04.923    - BrowseTask.doInBackground(): loading container 'Artist'  // Browse UPnP action emitted to MC for the first 16 items
[cling-62 (Browse) (188)                 ] INFO     - 0:00:23.368    - HTTP request took a long time: http://192.168.1.131:52100/ContentDirectory/control took: 17801 ms // MC replied with the first 16 items but it took 17s. Why ? A new Browse request is emitted to ask for the next 500 items
[cling-27 (Browse) (131)                 ] INFO     - 0:00:46.203    - HTTP request took a long time: http://192.168.1.131:52100/ContentDirectory/control took: 22811 ms // MC replied with the next 500 items but it took 22s. Why ? A new Browse request is emitted to ask for the next 500 items
[main (2)                                ] INFO     - 0:00:48.595    - BrowseTask::cancel(): cancelling...  // User cancels the browsing (using the back button) as it takes a loooong time

The question is why MC takes so long to send the response to these benign Browse UPnP action ? And it is not something that happens all the time since I cannot reproduce it (on my 7000 tracks library).

[Awesome Donkey]

The notifications might've changed when I split the original thread into this one, d'oh! Apologies if that was the case.

Mr. Odd, since you also have the issue, how many tracks are in your music library? My music library is currently at 144,793 tracks (1249 artists, 10,796 albums). Maybe it's not the number of tracks but the number of artists and albums? Hmmm, regardless I suppose if someone has enough tracks and/or artists/albums the issue can appear, hence why it seems to be rare. Maybe the solution is to downsize? Nah!

Seriously though if you guys on either side need new logs or specific things tested (e.g. different settings, sideloaded APKs, etc.) please let me know. Happy to help however I can.

[bubbleguuum]

The notifications might've changed when I split the original thread into this one, d'oh! Apologies if that was the case.

Mr. Odd, since you also have the issue, how many tracks are in your music library? My music library is currently at 144,793 tracks (1249 artists, 10,796 albums). Maybe it's not the number of tracks but the number of artists and albums? Hmmm, regardless I suppose if someone has enough tracks and/or artists/albums the issue can appear, hence why it seems to be rare. Maybe the solution is to downsize? Nah!

Seriously though if you guys on either side need new logs or specific things tested (e.g. different settings, sideloaded APKs, etc.) please let me know. Happy to help however I can.

I would not be surprised the slowness is caused by the gigantic size of your library in MC.

[Awesome Donkey]

Just in case I did some new logs from both sides at the same time, this is on my new (faster) network too. What's interesting is the first several times it loaded fast in BubbleUPnP so I attached a fast load log separately along with a slow load log. On the MC side the log will contain several fast loads and a slow load. I wonder why it loads fast those first few times? Interesting regardless.

[bubbleguuum]

The MC log shows this for a slow Browse request or the "Audio > Artist" folder (ObjectID 1000):

Code: [Select]

0222276: 15776: Sharing Plugins: CContentDirectoryService::Browse: Browse BrowseDirectChildren for 1000
0222305: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[††† /(Crosses/)] [Media Type]=[Audio]; Elapsed ms: 28.407
0222333: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[A Flock Of Seagulls] [Media Type]=[Audio]; Elapsed ms: 27.536
0222361: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[A Perfect Circle] [Media Type]=[Audio]; Elapsed ms: 27.289
0222363: 12092: Sharing Plugins: VHTTPMessage::Write: Wrote 0 bytes
0222363: 12092: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (837 ms)
0222363: 6100: Sharing Plugins: CUDPSocketReader::Accept: Start
0222363: 6100: Sharing Plugins: CUDPSocketReader::Accept: Description: CListenerBase::CListenerBase [UDP]
0222363: 6100: Sharing Plugins: CUDPSocketReader::Accept: Finish (0 ms)
0222363: 9400: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
0222363: 9400: Sharing Plugins: CHTTPListenerWorker::HandleRequest: UDP: 192.168.1.144: M-SEARCH: http://239.255.255.250:1900*
0222397: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[A/-ha] [Media Type]=[Audio]; Elapsed ms: 27.389
0222426: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Aaliyah] [Media Type]=[Audio]; Elapsed ms: 27.497
0222454: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Aaron Lewis] [Media Type]=[Audio]; Elapsed ms: 27.311
0222483: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[ABBA] [Media Type]=[Audio]; Elapsed ms: 27.911
0222511: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Abigail's Ghost] [Media Type]=[Audio]; Elapsed ms: 27.499
0222540: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[AC//DC] [Media Type]=[Audio]; Elapsed ms: 27.616
...
repeat for each of the remaining artists

It is slow because MC is making a CSearchFilesHelper::GetResults function call per artist (!) that take 27ms each. It does not do that when the loading of that folder is fast in BubbleUPnP. BubbleUPnP is not sending an UPnP Search action per artist for sure ! And anyway these CSearchFilesHelper::GetResults calls happen in the same thread than the UPnP Browse (BrowseDirectChildren) action thread (assuming 15776 is the thread id).
So the question is why sometimes MC make these CSearchFilesHelper::GetResults call per artist in a Browse UPnP action for the Artist folder.

[Mr. Odd]

Mr. Odd, since you also have the issue, how many tracks are in your music library? My music library is currently at 144,793 tracks (1249 artists, 10,796 albums). Maybe it's not the number of tracks but the number of artists and albums? Hmmm, regardless I suppose if someone has enough tracks and/or artists/albums the issue can appear, hence why it seems to be rare. Maybe the solution is to downsize? Nah!

I have 1060 artists, 4902 albums and 82791 tracks in my library.

What I also wonder is why some other apps like EOS have no delay but BubbleUPnP does. It's got to be something in that particular interaction.

[Awesome Donkey]

In simple terms the remote apps like JRemote, Gizmo, MO 4Media, eos, Panel use MCWS (basically MC's own protocol) whereas an app like BubbleUPnP uses standard DLNA/UPnP instead. So unfortunately the apps like JRemote function differently (and are unique to MC) and BubbleUPnP is more universal as long as the server supports DLNA/UPnP which MC does.

The issue appears to be on the DLNA/UPnP side of things and is rare as we're the only two who have reported it thus far. Since you have over 1,000 artists like me I'm going to guess that's the magic number to get it to manifest.

[JimH]

In simple terms the remote apps like JRemote, Gizmo, MO 4Media, eos, Panel use MCWS (basically MC's own protocol) whereas an app like BubbleUPnP uses standard DLNA/UPnP instead. So unfortunately the apps like JRemote function differently (and are unique to MC) and BubbleUPnP is more universal as long as the server supports DLNA/UPnP which MC does.

As you surely know, MC does support UPnP/DLNA, and it's about as solid as it gets.  The implementation is widely used to test other applications against.

[Mr. Odd]

For browsing a folder, BubbleUPnP emits an initial BrowseDirectChildren request to get the first 16 items (to have something to display immediately), then gets the remaining items with subsequent BrowseDirectChildren requests of 500 items each.

So could you perform this task without breaking it into chunks? That's what I see and appears to result in delays displaying the lists.

[Awesome Donkey]

UPnP always loads in chunks so it could be unavoidable. That said, any type of workaround (even if it's a "hacky" workaround) on either side would be much appreciated. Just getting it to work however way consistently would be well worth it to me.

[bob]

The MC log shows this for a slow Browse request or the "Audio > Artist" folder (ObjectID 1000):

Code: [Select]

0222276: 15776: Sharing Plugins: CContentDirectoryService::Browse: Browse BrowseDirectChildren for 1000
0222305: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[††† /(Crosses/)] [Media Type]=[Audio]; Elapsed ms: 28.407
0222333: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[A Flock Of Seagulls] [Media Type]=[Audio]; Elapsed ms: 27.536
0222361: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[A Perfect Circle] [Media Type]=[Audio]; Elapsed ms: 27.289
0222363: 12092: Sharing Plugins: VHTTPMessage::Write: Wrote 0 bytes
0222363: 12092: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Finish (837 ms)
0222363: 6100: Sharing Plugins: CUDPSocketReader::Accept: Start
0222363: 6100: Sharing Plugins: CUDPSocketReader::Accept: Description: CListenerBase::CListenerBase [UDP]
0222363: 6100: Sharing Plugins: CUDPSocketReader::Accept: Finish (0 ms)
0222363: 9400: Sharing Plugins: CHTTPListenerWorker::HandleConnection: Start
0222363: 9400: Sharing Plugins: CHTTPListenerWorker::HandleRequest: UDP: 192.168.1.144: M-SEARCH: http://239.255.255.250:1900*
0222397: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[A/-ha] [Media Type]=[Audio]; Elapsed ms: 27.389
0222426: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Aaliyah] [Media Type]=[Audio]; Elapsed ms: 27.497
0222454: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Aaron Lewis] [Media Type]=[Audio]; Elapsed ms: 27.311
0222483: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[ABBA] [Media Type]=[Audio]; Elapsed ms: 27.911
0222511: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[Abigail's Ghost] [Media Type]=[Audio]; Elapsed ms: 27.499
0222540: 15776: Database: CSearchFilesHelper::GetResults: Search: [Album Artist (auto)]=[AC//DC] [Media Type]=[Audio]; Elapsed ms: 27.616
...
repeat for each of the remaining artists

It is slow because MC is making a CSearchFilesHelper::GetResults function call per artist (!) that take 27ms each. It does not do that when the loading of that folder is fast in BubbleUPnP. BubbleUPnP is not sending an UPnP Search action per artist for sure ! And anyway these CSearchFilesHelper::GetResults calls happen in the same thread than the UPnP Browse (BrowseDirectChildren) action thread (assuming 15776 is the thread id).
So the question is why sometimes MC make these CSearchFilesHelper::GetResults call per artist in a Browse UPnP action for the Artist folder.

From what I can see MC is applying the filters provided with the browse command. That causes an internal "search" which means applying the filters to the browse. The fast replies are when the browse is with * which means don't apply any filters.

[bubbleguuum]

I double checked again and BubbleUPnP only emits "Browse" UPnP actions (BrowseMetadata) with the "Filter" parameter set to "*".

[markf2748]

I am beginning to wonder if the problem may be related to @AD's definition of his remote Artist View.  MC's remote Artist View for DLNA is defined in:

Options > Media Network > Add or configure DLNA Servers... > DLNA Servers > Generic DLNA >  Customize views... > Items to show > Click on Artist under Audio > Details for Audio > Edit...

Do you have any extra formatting, function calls, special sorting, restrictions on items to display, etc. within the view definition, beyond just:

Expression to group by: [Album Artist]

If so, you might try simplifying the view to bare bones as a test.

Do other remote views exhibit the same slowness issues?

Just a thought.

[Awesome Donkey]

Hmmm, interesting. If I recall correctly, this is the default artist view, correct?





Anything specific I should try?