delay in opening emby classic

[tjmcd.314 4]

I seem to be getting a 10-20 second delay when opening emby classic from WMC. I saw a previous thread where someone was having this problem and the solution was to change how emby classic was looking for the server (i.e. changing the setting from a set ip address to detect automatically or something like that).

 

What's weird is that I can't get that setting to stick. As soon as I leave the configuration page it changes back. Although in my case the fixed ip address is the correct one. Other settings act normally and can be set. I even tried changing the setting in the xml file manually and as soon as I opened emby classic it rewrote the xml file back to having a fixed ip address for the server. Also I have logging turned on in emby classic but it doesn't appear to be generating any log files (looking in %appdata%\mediabrowser-classic there is only the configuration folder).

 

I've tried with antivirus off, so I don't think that's the issue. I saw another thread where ebr mentioned changing HDD's fixed that issue. I don't have another HDD on hand so I'm not sure if I can test that, but there's still something weird going on with not being able to set the server ip address to automatic and not having any log files.

 

For what it's worth I attached a server file for a delayed logon. Tried twice around 12:50am on 6/5. First time was ok (maybe 6-7 seconds), second time was long (maybe around 20 seconds).

 

setup details:

Windows 7 (server and client are on the same machine)

SSD for OS, and HDD for media

emby classic ver: 3.0.269.0

server ver: 3.0.5621.4

 

server-63569059200.txt

MBCommonXml.config.txt

[ebr 14904]

Logs are in ProgramData\MediaBrowser-Classic.

[tjmcd.314 4]

Indeed they are in programdata. Just tested it again and it was fairly long. Attached the corresponding log.

 

These appear to be the lines around the longest delay, but it doesn't appear to be very illuminating.

2015-06-05 11:19:02.4013,Debug,,GetMediaExperienceUsingReflection was unsuccessful,1,Application
2015-06-05 11:19:02.5313,Info,,Sending Http Get to http://10.20.30.104:8096/mediabrowser/System/Info/Public?format=Json,1,Application
2015-06-05 11:19:16.4063,Info,,Sending Http Get to http://10.20.30.104:8096/mediabrowser/Users/Public?isDisabled=False&format=Json,1,Application
2015-06-05 11:19:16.5263,Info,,Connected to server TJ-HTPC at http://10.20.30.104:8096,1,Application

Let me know if there's some way to up the verbosity of the log files, in case that would help.

 

edit - In case the log file records anything about setting changes I tried again and went through the steps to set the server ip address to get automatically. Login the second time was much quicker, but I'm still unable to change that setting. Logging out and back in, the third time (log not included) again had a long delay, in the same spot as the first.

MBClassic-56201540f08b54aff849709630d4ee9839e2f5.log

MBClassic-5620154adc3d93fba544668fd450077c01c55a.log

Edited June 5, 2015 by tjmcd.314

[ebr 14904]

It looks like it is taking your server up to 15 seconds to respond to that request - but only sometimes.  Smells like a hard drive sleeping delay or something similar...

[tjmcd.314 4]

Well both the client and the server are installed on an always on SSD (hibernate is turned off). The media files are on a secondary HDD, but the request doesn't seem to be looking for media but just trying to communicate with the server. 

 

Any ideas about ways to troubleshoot solutions to this? Are there sleep settings I can turn off? Maybe backup/format/restore for either the ssd or the HDD? Some sort of disk check for bad sectors?

 

Also, any idea why I can't get the setting for detect server automatically to stay?

[ebr 14904]

Do you have it configured to automatically log in as a particular user?  If so, that implies a particular server connection.

 

As for the other issue.  Can you reproduce the problem and then find that request in the server log and see what the response time is?  You will need to enable debug logging on your server which it doesn't look like is the case right now.

[tjmcd.314 4]

I'm at work now so I'll have to report back tonight.

 

I do have it set to automatically log in, so I suppose that answers why I can't change the server IP setting. Although it still seems like I should be able to set it to automatically connect in the rare instances that I change ip addresses for my sub network and the server's ip address changes.

[tjmcd.314 4]

Ok, I turned on server debugging, and restarted the computer to make sure everything was fresh. Replicated the delay and it doesn't look like the server log is anymore helpful.

 

This is from the client logs around the time of the large delay:

2015-06-06 10:44:58.9504,Info,,Startup parameters: ,1,Application
2015-06-06 10:44:58.9704,Debug,,Having to get media experience by reflection due to bug in Windows 7,1,Application
2015-06-06 10:44:58.9704,Debug,,GetMediaExperienceUsingReflection was unsuccessful,1,Application
2015-06-06 10:44:59.4104,Info,,Sending Http Get to http://10.20.30.104:8096/mediabrowser/System/Info/Public?format=Json,1,Application
2015-06-06 10:45:12.9364,Info,,Sending Http Get to http://10.20.30.104:8096/mediabrowser/Users/Public?isDisabled=False&format=Json,1,Application
2015-06-06 10:45:13.0564,Info,,Connected to server TJ-HTPC at http://10.20.30.104:8096,1,Application
2015-06-06 10:45:13.0564,Info,,Server version: 3.0.5621.4,1,Application

and this is from the server logs at the same time:

2015-06-06 10:41:48.8350 Info - App: Executing Convert media
2015-06-06 10:41:48.8550 Info - App: Convert media Completed after 0 minute(s) and 0 seconds
2015-06-06 10:44:59.0504 Info - App: Udp message sent to 10.20.30.104:52644
2015-06-06 10:45:12.8364 Debug - HttpServer: HTTP GET http://10.20.30.104:8096/mediabrowser/System/Info/Public?format=Json
	Ip: 10.20.30.104:52690. Headers: Authorization=MediaBrowser Client="MB-Classic", Version="3.0.269.0", DeviceId="c5b929d7c70e48058e8923c585b38b17", Device="TJ-HTPC/TVuser",X-MediaBrowser-Token=,Host=10.20.30.104:8096,Connection=Keep-Alive
2015-06-06 10:45:12.9164 Debug - HttpServer: HTTP Response 200 to 10.20.30.104. Response time: 80.0001 ms.
	Url: http://10.20.30.104:8096/mediabrowser/System/Info/Public?format=Json
2015-06-06 10:45:12.9364 Debug - HttpServer: HTTP GET http://10.20.30.104:8096/mediabrowser/Users/Public?isDisabled=False&format=Json
	Ip: 10.20.30.104:52690. Headers: Authorization=MediaBrowser Client="MB-Classic", Version="3.0.269.0", DeviceId="c5b929d7c70e48058e8923c585b38b17", Device="TJ-HTPC/TVuser",X-MediaBrowser-Token=,Host=10.20.30.104:8096
2015-06-06 10:45:12.9364 Debug - HttpServer: HTTP Response 200 to 10.20.30.104. Response time: 0 ms.
	Url: http://10.20.30.104:8096/mediabrowser/Users/Public?isDisabled=False&format=Json
2015-06-06 10:45:13.1864 Debug - HttpServer: HTTP POST http://10.20.30.104:8096/mediabrowser/Users/78ee3c81-9269-8ab5-3354-b66650dc8201/Authenticate?format=Json
	Ip: 10.20.30.104:52690. Headers: Authorization=MediaBrowser UserId="78ee3c81-9269-8ab5-3354-b66650dc8201", Client="MB-Classic", Version="3.0.269.0", DeviceId="c5b929d7c70e48058e8923c585b38b17", Device="TJ-HTPC/TVuser",X-MediaBrowser-Token=,Content-Type=application/x-www-form-urlencoded,Host=10.20.30.104:8096,Content-Length=49,Expect=100-continue
2015-06-06 10:45:13.1864 Info - UserManager: Authentication request for TVuser has succeeded.

MBClassic-6620150cb8e8fbf7dd471293cf4d42a617236a.log

server-63569183799.txt

[DGMayor 88]

I've started to randomly see this as well.  On the latest dev release of classic.  Classic and server on same machine, also an SSD.   Just started with latest Dev.  I'll try to pull a log next time it happens. 

[tjmcd.314 4]

I can't tell from the logs if it's a network issue or a disk IO issue, but I thought I'd try a few things.

 

Turning off windows firewall has no effect. I don't have any QOS or network shaping turned on in my router, but just in case is it possible to change the client and server to use the loopback (127.0.0.1) ip address for the time being? Could also be something with my network adapters since I have sort of a convoluted setup, but I'm not sure how to troubleshoot that at the moment.

 

Another thing I noticed is that if I log in, exit, and then immediately log in again the delay is almost entirely gone. It takes about 3-5 seconds on the repeat log in, and the http get delay is down to 2 seconds. This makes me think it could be a disk IO issue, as it could be that if I log in immediately the information is still stored in memory, but if I wait a few minutes it gets dumped.

Edited June 6, 2015 by tjmcd.314

[ebr 14904]

How close are the times on the two machines?  It looks like the delay is actually occurring at the network level before getting to the server.

 

The client reports sending the request at 10:44:59.4104  and the server doesn't receive it until 10:45:12.8364.

[tjmcd.314 4]

It's only one machine. A HTPC running windows 7.

[ebr 14904]

Okay, then yeah, there is a delay happening at the network level as it tries to loop back I think.  Try configuring EMC to connect to "localhost" instead.

[tjmcd.314 4]

Setting emby classic to use localhost seems to have resolved this issue.

 

It must be an issue with my router setup. I don't have any other clients so I can't test to see if it was only a problem with a client trying to loopback or if it will also be a problem with a client trying to connect from a different local IP address, but at least I know what's causing the problem.

 

There's still a 2ish second delay in between the client sending the first http get request and the server responding, which seems long given that I'm using the localhost now, but it never gets above 3-4 seconds to open emby classic which is perfectly acceptable for me.

[tjmcd.314 4]

For anyone who might stumble across this it wasn't immediately obvious to me how to set emby classic to use localhost so this is what I did:

 

1) In emby classic I went to settings and under the general tab I changed the log in behavior from use "log in current user" to "show profile screen". I found that if I didn't change this setting first, then I couldn't change the server IP setting without it automatically reverting.

 

2) Next, when I went to the advanced tab there wasn't an option for "localhost" in the server connection options, so instead I closed emby classic, and opened the file MBCommonXml.config (located in %appdata%\MediaBrowser-Classic\Configurations) and changed these lines to read like I have shown them below:

<ServerAddress>localhost</ServerAddress>
<LogonAutomatically>True</LogonAutomatically>

Edited June 7, 2015 by tjmcd.314