I'm seeing the Kodi interface freezing (not responding) for a long number of seconds after clicking on a TV recording. It seems to be caused by having "Store resume/watched status on server" enabled, and possibly made worse (could be coincidental) by having BufferCountFilter set higher than the default, but is still pretty bad at the default of 100.
The best way to demonstrate this is to configure the media default select action for videos to "Choose". (this setting is under Settings->Media->Videos) With it set this way, it demonstrates that the interface freezing actually happens *even* when not trying to play the recording, but just bringing up the context menu. To reproduce, just navigate to the TV->Recordings folder and click on a TV recording, and it will cause the Kodi interface to hang for a while before the context menu pops up.
For comparison, if the default select action is set to "Show information", it doesn't freeze when clicking on a TV recording -- the information screen actually comes up quickly. However, on the information screen, once you click on the Play recording button, you will similarly see the interface freeze for a long number of seconds before the recording starts to play. Finally, if the default select action for videos is set to "Play", there will be the same kind of interface freeze after clicking on an item in the TV->Recordings folder before the recording starts to play.
Disabling "Store resume/watched status on server" works around the issue.
I can post a full debug log, but here's an example of what happens after clicking the TV recording:
03:12:03.322 T:15896 DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick
03:12:04.953 T:17384 INFO: Platinum [platinum.core.ctrlpoint]: Device "Wireless Router" expiration time renewed..
03:12:07.370 T:15896 INFO: Previous line repeats 15 times.
03:12:07.370 T:15896 DEBUG: AddOnLog: PVR WMC Client: Socket::GetVector> Send request "GetServiceStatus|1.3.0|windows(10.0)"
03:12:21.492 T:15896 DEBUG: Previous line repeats 1 times.
03:12:21.492 T:15896 DEBUG: AddOnLog: PVR WMC Client: Socket::GetVector> Send request "GetResumePosition|10977524093781562"
03:12:24.296 T:4620 INFO: Platinum [neptune.http]: NPT_CHECK failed, result=-20014 (NPT_ERROR_TIMEOUT) [(result)]
03:12:24.303 T:16060 INFO: Previous line repeats 3 times.
03:12:24.303 T:16060 INFO: Platinum [platinum.core.ctrlpoint]: Device "Wireless Router" expiration time renewed..
03:12:28.506 T:12800 INFO: Previous line repeats 3 times.
03:12:28.506 T:12800 DEBUG: AddOnLog: PVR WMC Client: Socket::GetVector> Send request "GetTimerCount"
Please don't such post log snippets directly onto the forum. One, it kinda unnecessarily burdens our forum server so use a text upload website like Pastebin.com, and two, we'll always ask for a FULL debug-enabled kodi
debug log (wiki) because log snippets never paint the full picture.
In addition, from the ServerWMC side, please restart serverWMC and reproduce the issue. Then upload the full ServerWMC.log file to pastebin or similar and post the link here. We do appreciate the analysis but also want to be able to see the full picture.
Here's the kodi debug log:
https://pastebin.com/ffLnFdaB
(I produced a number of leftclick events, and the unresponsiveness occurs after almost every leftclick that is followed by a GetServiceStatus and GetResumePosition, however, a few of these don't cause the unresponsiveness, but I haven't come up with any rhyme or reason as to why some don't.)
Here's the ServerWMC log:
https://pastebin.com/aJgXaBZx
(The unresponsiveness that I'm seeing on the Kodi side is not evident in the ServerWMC log if looking at the time elapsed on each event, so whatever is happening, it's happening outside the ServerWMC log's time elapsed info)
Btw, the lines with "Device "Wireless Router" expiration time renewed.." can be ignored. That's Kodi detecting my router's UPnP service, and I tried disabling UPnP on my router and it didn't do anything to get rid of the unresponsiveness (it just got rid of those log entries, lol)
Sorry man, I got nothing as to what could be causing the delay. Are Kodi and ServerWMC on the same box? Have you tried that setup? Also, maybe try another client with Kodi installed.
Good luck, sorry can't be more help.
mmortal03,
There are some client requests that swmc doesn't bother to log, so if want to see how long those are taking, change the field in the settings file for LogRequestNone to empty. Like this:
<LogRequestNone />
Then same the settings file and restart serverwmc. With this change, it will be logging every command it gets from kodi.
(2018-01-20, 07:44)sbthomas Wrote: [ -> ]Sorry man, I got nothing as to what could be causing the delay. Are Kodi and ServerWMC on the same box? Have you tried that setup? Also, maybe try another client with Kodi installed.
Good luck, sorry can't be more help.
Thanks. Regarding running both on the same box, that's a good suggestion in that it might help to determine if it's some sort of issue caused by network latency or what have you, but, practically speaking, the whole point here is to be able to run it over the network, and, unfortunately, it's currently not practical for me to try to run it on the same machine. On your other point, yes, I've tried this using more than one machine as the client. Same issue on both.
(2018-01-20, 19:12)krustyreturns Wrote: [ -> ]There are some client requests that swmc doesn't bother to log, so if want to see how long those are taking, change the field in the settings file for LogRequestNone to empty. Like this:
<LogRequestNone />
Then same the settings file and restart serverwmc. With this change, it will be logging every command it gets from kodi.
Ok, cool, let me try that.
(2018-01-20, 19:12)krustyreturns Wrote: [ -> ]mmortal03,
There are some client requests that swmc doesn't bother to log, so if want to see how long those are taking, change the field in the settings file for LogRequestNone to empty. Like this:
<LogRequestNone />
Then same the settings file and restart serverwmc. With this change, it will be logging every command it gets from kodi.
Okay, I've tried that, and I even did a <LogAllRequestFull>true</LogAllRequestFull>.
Looking at the logs myself, my impression is that the issue isn't caused by any of these request commands' *intraprocess* latency, as all of them seem to execute extremely quickly.
What I *am* seeing is some sort of *interprocess* latency (between each request), of about seven seconds each. I don't know enough about how either the Kodi add-on or ServerWMC are programmed to handle the sending and receiving these requests, but I'm going to assume that there's a *queue* of these requests coming in in the background, and some, or all, of them have to happen in succession before, say, a GetResumePosition (or whichever one it is) can actually go through?
Specifically, I'm noticing that if I click on the recording at a specific time and I take note of the time that I clicked (I've tried to sync the system clocks on both machines as much as I can so that I'm pretty sure of the time that I'm actually clicking), comparing that time to the log there may be, say, a GetTimers request going on which will execute quickly, but then there's *a seven second gap* between that and the next request, which is a GetServiceStatus (to get the driveSpace), and then *another* seven second gap between that and yet *another* GetServiceStatus for the driveSpace, and then *another* seven second gap between that and a GetRecordingsAmount, and then *another* seven second gap between that and the GetResumePosition finally going through.
My interpretation is that the Kodi interface is hanging while waiting on the GetResumePosition information, and not even displaying the context menu until it has this information back from the server. What I don't know is *why* there are all of these seven second delays *in between* each of the requests, which is probably contributing to it taking so long for the GetResumePosition request response to finally get back to Kodi.
Serverwmc does the commands from its clients asynchronously, in other words, it runs the commands it receives in multiple threads so it processes them at the same time. There should be no waiting for a command to finish before it can do the next one.
I guess I'm going to have to try more verbosity on the Kodi log side of things, then, because, unless the seven seconds between each request on the ServerWMC side rings any bells as far as a potential cause, there's otherwise nothing to go on in the ServerWMC log.
I've been looking at the more verbose Kodi log, but it's still not obvious which item could be causing the problem. Might there be a way to disable the GetServiceStatus calls for the driveSpace, for debugging purposes? That would help to be able to rule those out.
In swmc there is currently no way to make it ignore getservicestatus. If you are dedicated to figuring this out, I could do a test build of swmc that ignores it that you could test with, but personally doubt it will make a difference.
(2018-02-01, 03:28)krustyreturns Wrote: [ -> ]In swmc there is currently no way to make it ignore getservicestatus. If you are dedicated to figuring this out, I could do a test build of swmc that ignores it that you could test with, but personally doubt it will make a difference.
That would be great, though, for all we know, it could be a bug in Kodi or the client plugin, and not the server software. We won't know until we try it, I guess. Btw, I should send you a donation for your help so far. Is the donation link at the following still the place to do it?:
https://serverwmc.github.io/
I PM'd you a test version of swmc for you to try. GetServiceStatus has not been completely removed, because its main function is to tell kodi that swmc is online. But all the other things that happen in the GetServiceStatus have been gutted.