Long delays processing events

[eric.bosch@…]

Currently running SVN 19864, there seems to be something preventing remote events (skip forward/back, channel changes, etc) and same with keyboard, from being processed in a timely fashion. I have two backends running, sharing NFS filesystems. It seems to work fine if everything is idle, ie no recordings, other frontend idle), but when a recording is in process on either of the backends, there is up to a 15-60 second delay from when the keystroke is performed to when it actually processes it. Additionally, when this behavior is occurring, I can open a webpage, which initial screen comes up quickly, however if I go to check backend, there is a 2 minute delay, and also, recordings page comes back blank. The following errors are shown in the log at this time:

2009-01-28 20:28:57.518 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.561 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.605 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.646 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.668 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.711 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.754 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.801 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.846 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.867 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.909 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.952 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:57.995 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.038 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.081 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.125 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.146 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.189 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.231 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.274 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.317 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.359 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.404 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.426 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.469 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.511 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.554 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.597 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.639 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.684 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.705 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.748 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.790 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.833 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.876 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.919 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:58.962 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:59.006 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:59.027 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:59.070 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:59.112 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:59.155 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 2009-01-28 20:28:59.198 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0

[eric.bosch@…]

The only way to return to normal speed processing is apparently to restart both the master and slave backend, at which time operation seems to normalize.

[eric.bosch@…]

From what I have been able to determine, the backend is getting slammed with query's approximately every 50ms, thus causing the delays in handling keyboard/remote events. I don't understand what all the code is doing in this area (TVRec::HandlePendingRecordings?(void)), the contents of 'timeuntil' variable never changes. The next show that is scheduled to record is nearly 10 hours from current time, so there appears to be a fault in calculation of this value. The backend is currently using 33% of CPU. The following line in tv_rec.cpp:

int timeuntil = ((*it).doNotAsk) ? -1: QDateTime::currentDateTime().secsTo((*it).recordingStart);

appears to be the culprit, but I'm not sure how to handle the issue. I will try a couple things and see if I can affect a change, but if somebody who understands this part of the code could help direct me, it would be immensely appreciated.

[eric.bosch@…]

I believe possibly the pointer to 'it' is getting corrupted somewhere. While debugging the code, I was getting massive bursts of queries to the backend every 50ms. Once I restarted the master backend followed by the slave, the queries stopped immediately, thus everything at the moment is working perfectly. It seems that the event is getting triggered by something, possibly commercial flagging,

[eric.bosch@…]

Is anybody else at all seeing this same behaviour, or am I possibly chasing a hardware problem???????

[Shane Shrybman]

Hi Eric, I feel your pain :)

I encountered this problem the other night, so I don't think it is a hardware issue.

I don't know exactly what the problem is and unfortunately I can't seem to reproduce it in order to do further debugging.

But you could try this debugging patch and see if the VERBOSE message is printed in your backend log.

[Shane Shrybman]

Debugging patch

[eric.bosch@…]

Thanks, Gnome42, I will apply that and see what happens. It could be today or tomorrow, as this one is really unpredictable when it happens. I've had it happen several times a day, and sometimes it'll go days without it, but it always eventually gets me!

[eric.bosch@…]

Just had one glitch, where I lost about 4 seconds of video/sound, but this time, only one occurrence of 2009-02-04 20:59:29.918 TV: ASK_RECORDING 3 29 0 0 hasrec: 0 haslater: 0 message. Did not see message indicated from the patch, then some discarded busy frames, and then it recovered. Will continue to test.

[eric.bosch@…]

Strangely, after this patch, I've gone two days without an occurrence of this issue. I will continue to wait and see what happens.

[eric.bosch@…]

Well, it has been 3 days now. I suspect that this patch has inadvertently fixed the issue, whether you expected that or not. I see a slight change in the logic that could be responsible. Any chance of committing this into trunk?

[Shane Shrybman]

Replying to eric.bosch@comcast.net:

Well, it has been 3 days now. I suspect that this patch has inadvertently fixed the issue, whether you expected that or not. I see a slight change in the logic that could be responsible. Any chance of committing this into trunk?

No, the patch won't be committed. It is a debugging patch meant to help determine where the bug is.

Are you seeing the VERBOSE message from the patch in your backend logs? That would indicate the patch is actually having an effect. If you don't see the message in the log, the patch isn't doing anything.

[Shane Shrybman]

Chris Pinkham has committed a similar patch in -fixes [19960] and trunk [19962].

Removing this debugging patch and updating to the latest sources should fix the problem.

[eric.bosch@…]

Fantastic. I'll upgrade to latest and see how things look, but from description of the patch, and looking at it, it sure sounds like the solution! Thanks a million!