Opened 11 years ago

Closed 11 years ago

Last modified 11 years ago

#6192 closed defect (fixed)

Long delays processing events

Reported by: eric.bosch@… Owned by: Isaac Richards
Priority: major Milestone: 0.22
Component: MythTV - General Version: head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

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

Attachments (1)

mythsocket-endless-loop2.diff (1.1 KB) - added by Shane Shrybman 11 years ago.
Debugging patch

Download all attachments as: .zip

Change History (13)

comment:1 Changed 11 years ago by 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.

comment:2 Changed 11 years ago by 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.

comment:3 Changed 11 years ago by 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,

comment:4 Changed 11 years ago by eric.bosch@…

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

comment:5 Changed 11 years ago by 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.

Changed 11 years ago by Shane Shrybman

Debugging patch

comment:6 Changed 11 years ago by 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!

comment:7 Changed 11 years ago by 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.

comment:8 Changed 11 years ago by 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.

comment:9 Changed 11 years ago by 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?

comment:10 in reply to:  9 Changed 11 years ago by 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.

comment:11 Changed 11 years ago by Shane Shrybman

Resolution: fixed
Status: newclosed

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.

comment:12 Changed 11 years ago by 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!

Note: See TracTickets for help on using tickets.