Sleepy web-service?

[bgowland]

This isn't really a major issue but I'm curious...

When I set/cancel a recording from my phone using nDroid and haven't done so for a while, it seems like the NEWA web-service takes a while to 'wake up' and it takes a while before the nDroid service gets a result to pass back to my phone. If I then submit another schedule / cancel request the response is pretty much immediate.

Example for two episodes of Scrubs...

This is the nDroid service HTTP listener receiving a record requestfor the first...

Code:

[B]18/02/2012 01:12:53.328[/B] hrhkey.Key: x-ndroid-action hrhkey.Value: record

This is the nDroid service helper getting the data to pass to the NEWA webservice and the point where the result is returned...

Code:

18/02/2012 01:12:55.468 GetRequestedRecordingOid - sbQueryString: SELECT oid,channel_oid,start_time,title FROM EPG_EVENT WHERE EPG_EVENT.channel_oid = 7969 AND EPG_EVENT.start_time = '2012-02-18 01:50:00' AND EPG_EVENT.title = 'Scrubs'
18/02/2012 01:12:55.703 GetRequestedRecordingOid - oidString: 7589020
18/02/2012 01:12:55.765 GetRequestedRecordingOid - startString: 18/02/2012 01:50:00
[B]18/02/2012 01:12:55.843[/B] GetRequestedRecordingOid - weekdayString: Saturday
[B]18/02/2012 01:13:18.078[/B] Result.webServiceEPGEventObjects:
18/02/2012 01:13:18.078 schedOid: 13204

So it takes ~2.5 seconds of processing from the time the listener receives the request until the helper makes the request to the webservice. However, it then takes the webservice just over 22 seconds to set the recording and return a result.

If I look at the second record request though I see a much faster response from the webservice...

Listener receives request...

Code:

[B]18/02/2012 01:13:28.765[/B] hrhkey.Key: x-ndroid-action hrhkey.Value: record

Helper performs the request and gets a result...

Code:

18/02/2012 01:13:28.781 GetRequestedRecordingOid - sbQueryString: SELECT oid,channel_oid,start_time,title FROM EPG_EVENT WHERE EPG_EVENT.channel_oid = 7969 AND EPG_EVENT.start_time = '2012-02-18 02:20:00' AND EPG_EVENT.title = 'Scrubs'
18/02/2012 01:13:28.812 GetRequestedRecordingOid - oidString: 7589021
18/02/2012 01:13:28.812 GetRequestedRecordingOid - startString: 18/02/2012 02:20:00
[B]18/02/2012 01:13:28.812[/B] GetRequestedRecordingOid - weekdayString: Saturday
[B]18/02/2012 01:13:29.203[/B] Result.webServiceEPGEventObjects:
18/02/2012 01:13:29.203 schedOid: 13205

OK so that shows the nDroid service was also a bit sleepy the first time as it only takes 47ms between the listener receiving the request and and the helper performing the request. The big difference, however, is that it takes the web-service less than 400ms to set the recording and return a result.

As I said, it's not a major issue, I'm just trying to work out why the first request took so long.

Cheers,
Brian

[mvallevand]

After a resume I see the same thing with SearchLite, I don't what causes it to need a reload and not just resume. NEWA is slow to start with each resume. Perhaps calling NEWA in wake.bat could help?

Martin

[bgowland]

Thanks for the suggestion but not applicable in my case - my npvr rig runs 24/7 with no standby or hibernate.

Cheers,
Brian

[UncleJohnsBand]

post the times from the web.log that shows when the request came in.....there is overhead in client apps to manage the SOAP Web Service requests.......you may actually be seeing a lag in your own app as it starts up the various helper classes within the .Net framework to manage the SOAP calls......seeing the web.log entries which will show exactly when the request comes in will help narrow where that lag is actually occurring and if it is in NEWA somewhere the logging in web.log should show where......it may also be the web server itself.....not sure if sub has "sleep" logic in there or not......if the web server rests it too has to fire up the .Net classes for managing the web service calls.

[bgowland]

I will do tomorrow - I went to check the web logs after I'd posted but they had been overwritten before I thought of it. I'll also add some extra logging to the nDroid service code to help pin-point it further.

[mvallevand]

.it may also be the web server itself.....not sure if sub has "sleep" logic in there or not......if the web server rests it too has to fire up the .Net classes for managing the web service calls.

It might not be sleep, there might be some JIT compiling going on. Something does keep track of NEWA code changes and force a recompile when a .cs file is updated without re-starting the web service.

Martin

[HarryH3]

Here's another clue... Does the PC Client also use NEWA? If I try to schedule a recording from a PC Client, the first one takes over 20 seconds to "finish" and go back to the TV Guide. If I schedule another one right away, I'm back at the TV guide screen almost instantly. If the PC Client doesn't use NEWA, then I think this points back to the main NPVR code. (My NPVR server also is on 24/7).

[mvallevand]

I think for SearchLite anyway there was problem in my code, because I was calling cred.createCredential() two extra times, taking the original NEWAServiceTest\form1.cs sample too literally. Reducing it to one per call certainly saves a few seconds.

The only real one time "cost" for NEWA for me are now, after the recording service restarts is a few seconds at startup

Code:

2012-02-18 18:44:43.021    [DEBUG][4]    Got Web Request (127.0.0.1): /public/services/searchservice.asmx
2012-02-18 18:44:43.125    [INFO][4]    RecorderHelperConfig: LoadFromFile()
2012-02-18 18:44:43.143    [INFO][4]    RecorderHelperConfig: SaveToFile()
2012-02-18 18:44:43.195    [INFO][4]    **********************************************
2012-02-18 18:44:43.195    [INFO][4]    *                                            *
2012-02-18 18:44:43.195    [INFO][4]    *                                            *
2012-02-18 18:44:43.195    [INFO][4]    *  NEWA Application Starting......Opening DB *
2012-02-18 18:44:43.195    [INFO][4]    *                                            *
2012-02-18 18:44:43.195    [INFO][4]    *                                            *
2012-02-18 18:44:43.195    [INFO][4]    **********************************************
2012-02-18 18:44:43.365    [INFO][4]    RecorderHelperConfig: SaveToFile()
2012-02-18 18:44:45.912    [INFO][4]    webServiceAuthentication credential found

Martin

[cncb]

Here's another clue... Does the PC Client also use NEWA? If I try to schedule a recording from a PC Client, the first one takes over 20 seconds to "finish" and go back to the TV Guide. If I schedule another one right away, I'm back at the TV guide screen almost instantly. If the PC Client doesn't use NEWA, then I think this points back to the main NPVR code. (My NPVR server also is on 24/7).

I had this problem with my PC clients too until I changed the "Server Name" on the clients to be the server's IP address instead of the name. It apparently took some time to resolve the name which using the IP address avoids.

[bgowland]

So a new test with a little extra logging at the nDroid service end and web.log extract included...

nDroid service listener receives request and takes 16ms to do a preliminary authentication check and call the nDroid service helper...

Code:

19/02/2012 00:17:36.015 hrhkey.Key: x-ndroid-action hrhkey.Value: record
...
19/02/2012 00:17:36.031 User authenticated

nDroid service helper processes the request and calls the NEWA service...

Code:

19/02/2012 00:17:36.031 oid: 7520341
...
19/02/2012 00:17:36.140 ScheduleNpvrRecording() - creating ScheduleService...
19/02/2012 00:17:39.578 ScheduleNpvrRecording() - creating webServiceScheduleSettings...
19/02/2012 00:17:39.578 ScheduleNpvrRecording() - creating webServiceAuthentication_Schedule_NPVR...
19/02/2012 00:17:39.578 ScheduleNpvrRecording() - creating CreateCredential...
[B]19/02/2012 00:17:39.718[/B] ScheduleNpvrRecording() - calling scheduleRecording()...
[B]19/02/2012 00:17:52.312[/B] Result.webServiceEPGEventObjects:
19/02/2012 00:17:52.312 schedOid: 13217

In the above, it takes ~3.6 seconds for the helper to do the SOAP stuff and then ~12.6 seconds for the web service to return a result.

web.log...

Code:

2012-02-19 00:17:41.109    [DEBUG][4]    Got Web Request (127.0.0.1): /public/services/ScheduleService.asmx
2012-02-19 00:17:41.406    [INFO][4]    RecorderHelperConfig: LoadFromFile()
2012-02-19 00:17:41.453    [INFO][4]    RecorderHelperConfig: SaveToFile()
2012-02-19 00:17:41.609    [INFO][4]    **********************************************
2012-02-19 00:17:41.609    [INFO][4]    *                                            *
2012-02-19 00:17:41.609    [INFO][4]    *                                            *
2012-02-19 00:17:41.609    [INFO][4]    *  NEWA Application Starting......Opening DB *
2012-02-19 00:17:41.609    [INFO][4]    *                                            *
2012-02-19 00:17:41.609    [INFO][4]    *                                            *
2012-02-19 00:17:41.609    [INFO][4]    **********************************************
2012-02-19 00:17:42.828    [INFO][4]    RecorderHelperConfig: SaveToFile()
2012-02-19 00:17:48.812    [INFO][4]    webServiceAuthentication credential found
2012-02-19 00:17:48.875    [INFO][4]    
2012-02-19 00:17:48.875    [INFO][4]    
2012-02-19 00:17:48.875    [INFO][4]    *********************
2012-02-19 00:17:48.875    [INFO][4]    * Validating Incomming Web Service
2012-02-19 00:17:48.875    [INFO][4]    *
2012-02-19 00:17:48.890    [INFO][4]    *
2012-02-19 00:17:48.890    [INFO][4]    *
2012-02-19 00:17:48.890    [INFO][4]    Checking Server time....
2012-02-19 00:17:48.890    [INFO][4]    nowTime (Server-Local) = 19/02/2012 00:17:48
2012-02-19 00:17:48.890    [INFO][4]    nowTime (Server-UTC) = 19/02/2012 00:17:48
2012-02-19 00:17:48.890    [INFO][4]    Credential time string (from request) = 19/02/2012 00:17:39
2012-02-19 00:17:48.890    [INFO][4]    Credential time converted (Local) = 19/02/2012 00:17:39
2012-02-19 00:17:48.890    [INFO][4]    Credential time converted to DateObject = 19/02/2012 00:17:39
2012-02-19 00:17:48.890    [INFO][4]    Span time seconds (calc = server-utc - credential-utc) = 9
2012-02-19 00:17:48.890    [INFO][4]    User verified
2012-02-19 00:17:48.890    [INFO][4]    nowTime (Server) = 19/02/2012 00:17:48
2012-02-19 00:17:48.890    [INFO][4]    *
2012-02-19 00:17:48.890    [INFO][4]    *
2012-02-19 00:17:48.890    [INFO][4]    *********************
2012-02-19 00:17:48.890    [INFO][4]    
2012-02-19 00:17:48.890    [INFO][4]    
2012-02-19 00:17:49.187    [INFO][4]    About to connect to remote recording service
2012-02-19 00:17:49.312    [DEBUG][4]    RecordingServiceProxy@exit
2012-02-19 00:17:51.828    [INFO][4]    @@@@@
2012-02-19 00:17:51.828    [INFO][4]    Found matching recording
2012-02-19 00:17:51.828    [INFO][4]    @@@@@

Assuming the the line which says "About to connect to remote recording service" is the point that the web server is actually calls, it suggests there's only ~2.6 seconds for the recording to be set.

So all in all, this one wasn't quite as severe as the near 25 seconds it took for the one in my first post but ~16 seconds is still quite significant especially as subsequent recording requests take only a second or so.

Cheers,
Brian