Opened 14 years ago

Closed 14 years ago

#942 closed defect (fixed)

Prebuffer pauses in LiveTV with SVN 8479

Reported by: bobnvic@… Owned by: Isaac Richards
Priority: minor Milestone: 0.19
Component: mythtv Version: head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

In LiveTV with a PVR-250 and ivtv-0.4.0 I get prebuffer wait pauses at file changes due to one show completing and another starting (no channel changes). There is almost always a one second or so pause in the video at file change and occasionally it remains frozen until the next show starts or you exit LiveTV. I have had this issue since the time LiveTV was changed to being file-based. Attached is a copy of the log for mythfrontend -v playback from 10 seconds before a file change that resulted in unending wait for prebuffer messages. Please let me know if there is anything else I can provide to help track this down.

Attachments (21)

mythfrontend.log (9.0 KB) - added by bobnvic@… 14 years ago.
mythfrontend -v playback
mythfrontendlog.txt (17.2 KB) - added by adeffs@… 14 years ago.
my log from similar occurence using firewire
mythfrontendlog-piers.txt (36.6 KB) - added by mythtv@… 14 years ago.
used "mythfrontend -v playback"
mythbackendlog-20060110.txt (31.2 KB) - added by mythtv@… 14 years ago.
mythfrontendlog-20060110.txt (38.1 KB) - added by mythtv@… 14 years ago.
mythbackend.log (1.5 KB) - added by bobnvic@… 14 years ago.
mythfrontend log 1-30-2006.txt (4.6 KB) - added by bobnvic@… 14 years ago.
mythbackend log 1-30-2006.txt (3.0 KB) - added by bobnvic@… 14 years ago.
mythfrontend log 1-31-2006.txt (6.4 KB) - added by bobnvic@… 14 years ago.
mythbackend log 1-31-2006.txt (16.1 KB) - added by bobnvic@… 14 years ago.
mythfrontend-prebuffer.log (9.6 KB) - added by bobnvic@… 14 years ago.
mythbackend-prebuffer.log (1.1 KB) - added by bobnvic@… 14 years ago.
mythfrontend.feb03.log (24.9 KB) - added by derek@… 14 years ago.
Output of mythfrontend -v playback
mythbackend.feb03.log (2.7 KB) - added by derek@… 14 years ago.
Output of mythbackend -v record
mythbackend.L8R.log.gz (66.6 KB) - added by mythtv.cvs@… 14 years ago.
mythfrontend.L8R.log.gz (96.8 KB) - added by mythtv.cvs@… 14 years ago.
gdb.backtrace.log (6.3 KB) - added by mythtv.cvs@… 14 years ago.
mythfrontend backtrace as requested
backtrace.feb04.out (8.9 KB) - added by derek@… 14 years ago.
backtrace of prebuffer pause
gdb.log (18.1 KB) - added by FiveNines 14 years ago.
frontend.log.bz2 (34.6 KB) - added by FiveNines 14 years ago.
svn8873.5feb.mythfrontend.txt (22.0 KB) - added by anonymous 14 years ago.

Download all attachments as: .zip

Change History (54)

Changed 14 years ago by bobnvic@…

Attachment: mythfrontend.log added

mythfrontend -v playback

comment:1 Changed 14 years ago by adeffs@…

Well, after about 4 hours of watching Live TV today (same channel, no channel changes, battlestar galactica reruns), this finally happened to me, except I'm using SVN8501 and it was from the firewire input. Could be a seperate issue, if so I'll open a new ticket.

log attached.

Changed 14 years ago by adeffs@…

Attachment: mythfrontendlog.txt added

my log from similar occurence using firewire

comment:2 Changed 14 years ago by mythtv@…

I get a similar problem with my 2 x DVB-T cards - when I start LiveTV it shows a black screen for a very long time. It's shown in the log I've attached between the time stamps 2006-01-09 16:07:23.005 and 2006-01-09 16:07:33.700 (10 seconds!). Then it shows the info bar with the DVB details, and a purple box on the bottom right with a few white lines in for several more seconds - in the logs it shows the prebuffer pauses between timestamps 2006-01-09 16:07:34.681 and 2006-01-09 16:07:39.840 - it takes 15 seconds from selecting "Live TV" to acutally watching it.

Then, it runs at a higher speed, maybe 1.5x or 1.8x but as it's at the end of the buffer, it pauses then runs faster, pauses and so on. In the logs it shows:

2006-01-09 16:07:40.715 NVP: Audio is 3.21135 frames ahead of video,

doubling video frame interval.

many times. It only happens once on the first time I start using LiveTV and then goes away if I change channels or change timestretch to something other than 1.0 then 1.0 again. Once that's done, it doesn't show the NVP error message at all, only shows the subtitle error message (not important).

I'm not sure if I'm even supposed to post this here, but the problems seemed very similar so posted it here hopefully it will help someone to find the bug and fix it. If there's anything I can do to help someone track this bug, let me know.

Changed 14 years ago by mythtv@…

Attachment: mythfrontendlog-piers.txt added

used "mythfrontend -v playback"

comment:3 Changed 14 years ago by Isaac Richards

Resolution: invalid
Status: newclosed

Need backend logs from the same time period as well.

comment:4 Changed 14 years ago by mythtv@…

Resolution: invalid
Status: closedreopened

Here you go. Logs as requested. Cheers!

Changed 14 years ago by mythtv@…

Attachment: mythbackendlog-20060110.txt added

Changed 14 years ago by mythtv@…

comment:5 Changed 14 years ago by bobnvic@…

Here is my backend log from the same time period.

Changed 14 years ago by bobnvic@…

Attachment: mythbackend.log added

comment:6 Changed 14 years ago by danielk

Milestone: 0.19

comment:7 Changed 14 years ago by danielk

bob, can you test the latest SVN?

comment:8 Changed 14 years ago by mythtv@…

Can't speak for Bob, but I tried the latest SVN this morning and still got the same problem.

comment:9 Changed 14 years ago by adeffs@…

still happens to me with 8788, I'll try and get a backend and frontend log tomorrow. Usually it just freezes and one has to escape to the menu and re-enter live tv, occasionally it starts the next show within a couple second pause.

comment:10 Changed 14 years ago by bobnvic@…

I updated to 8788 and put it on LiveTV. At file change I got a screen stating that there was an error with the video. Selecting the OK button simply left a black screen, but escaping got out of it. I've attached the logs (dated 1-29-2006), however I see that in the backend log there was a database error at the time of the file change so I don't know if anything can be done about that. MYSQL is local and worked fine on the next try. I then set it to LiveTV and went to bed. When I woke up I discovered that I had gotten another screen stating there was an error with the video. This time the backend logs showed IOBOUND messages at 2am on file change, logs attached (dated 1-30-2006). I hadn't seen these errors associated with my prebuffering pauses previously, though I have occasionally seen those errors come up. I will try running LiveTV again today and see what happens.

comment:11 Changed 14 years ago by bobnvic@…

Sorry, replace the 1-29-2006 date with 1-30-2006 and 1-30-2006 date with 1-31-2006 in the previous message.

Changed 14 years ago by bobnvic@…

Changed 14 years ago by bobnvic@…

Changed 14 years ago by bobnvic@…

Changed 14 years ago by bobnvic@…

comment:12 Changed 14 years ago by bobnvic@…

I got the prebuffering pause again (picture frozen, didn't get the "Error encountered while displaying video", which I now see is ticket #1153). I am attaching frontend and backend logs. I don't see anything special in the backend logs (backend was not run with any extra verbose settings).

Changed 14 years ago by bobnvic@…

Attachment: mythfrontend-prebuffer.log added

Changed 14 years ago by bobnvic@…

Attachment: mythbackend-prebuffer.log added

comment:13 Changed 14 years ago by danielk

Is this happening with SVN > [8844] ?

If so please attach new logs with '-v record' and '-v playback' resp.

BTW What is the filesystem on the video volume ?

comment:14 Changed 14 years ago by bobnvic@…

I will update tonight and test. This is using XFS for the storage volume.

comment:15 Changed 14 years ago by (none)

Cc: derek@… added

Changed 14 years ago by derek@…

Attachment: mythfrontend.feb03.log added

Output of mythfrontend -v playback

Changed 14 years ago by derek@…

Attachment: mythbackend.feb03.log added

Output of mythbackend -v record

comment:16 Changed 14 years ago by derek@…

The logs I attached (*feb03.log) are from the latest SVN. When the program changes at 2:00pm the frontend playback freezes until I hit escape, which then returns me to the main menu. I can then restart live tv and everything restarts and plays fine.

comment:17 Changed 14 years ago by mythtv.cvs@…

Priority: minorblocker

I can confirm this behaviour. At the end of the latest TV show I watched, it happened (it did a few times before, but as I was monkeying with various things, I did not attribute this to a Myth bug, directly).

The interesting thing here is, that it doesn't even seem to be trying to move on to the next program. I was able to fast forward into the next program (while in that session of liveTV), but I could not go beyond 0:00 minutes into it. Exiting and re-entering LiveTV fixed the problem...

I checked the LiveTV recordings in the Media Library, and the program does seem to be fine. All five minutes of the program, that I let record (just in case Myth would somehow unpause itself) were perfectly fine.

So, it's recording definitely.. and Myth will let you review that in the "Watch Recordings" screen. It's just somehow not skipping into that recording for some reason...

I've upped the priority of this to a blocker, since it severely impacts the usability of Myth. Someone can always correct that, if they think I'm insane. ;P

I anyone thinks logs from an additional source will help, I can easily do so. Let me know.

comment:18 Changed 14 years ago by Isaac Richards

Priority: blockerminor

comment:19 Changed 14 years ago by mythtv.cvs@…

Well, I do fine MythTV unusable, in that every half an hour you have to quit LiveTV, then re-enter, missing parts of your program.

No matter, although I don't think it is a minor issue. :(

Anyhow, still monkeying about with this. Same problem happened here again, but I was able to pause the frozen video.. then make it play, but now Myth believes it is paused.. yet video is playing!

I am unable to manipulate anything now, and will likely have to kill mythfrontend to regain control. Video is playing, studdering at about 1/2 speed, and with no sound.

I've attached my logs. Look for strangeness starting at the half hour...

Changed 14 years ago by mythtv.cvs@…

Attachment: mythbackend.L8R.log.gz added

Changed 14 years ago by mythtv.cvs@…

Attachment: mythfrontend.L8R.log.gz added

comment:20 Changed 14 years ago by Isaac Richards

Stop using trac as a chat room. Unless you have new information, which at this point means a patch fixing the issue, or more in-depth debugging than just logs, you're not helping anything.

comment:21 Changed 14 years ago by mythtv.cvs@…

Chat room? I was simply giving reasons as to why I felt this bug was more critical than marked, and providing detailed information on the problem. There is new information above, as well.

There is little need for you to react in such a brisk manner to this. I am, after all, only trying to help.

comment:22 Changed 14 years ago by danielk

If someone experiencing this problem could get a backtrace from the frontend after it enters this prebuffering state that might help.

gdb mythfrontend
run -v playback
[wait for prebuffer pauses]
Ctrl-C
thread apply all bt

This should tell us what each thread is waiting on.

comment:23 Changed 14 years ago by danielk

(In [8862]) References #942.

This commit moves the pthread_join on the NVP thread outside the osdlock, so that it is safe for the NVP to grab the qApp lock.

While trying to reproduce the bug in #942, I got the "Error encountered while displaying video" dialog. This was expected with what I was doing, but I didn't expect it to stop responding to input. Turns out that the NVP grabs a qApp lock when displaying this error dialog, but it does it while we are waiting for the thread to finish while holding the osdlock. If anything else is holding the qApp lock and tries to get the osdlock (which is the normal lock order), then we get into a deadlock situation between those two threads.

Changed 14 years ago by mythtv.cvs@…

Attachment: gdb.backtrace.log added

mythfrontend backtrace as requested

Changed 14 years ago by derek@…

Attachment: backtrace.feb04.out added

backtrace of prebuffer pause

comment:24 Changed 14 years ago by anonymous

The attached 'backtrace.feb04.out' gives the requested backtrace info. I also pasted the backend log to the bottom of the file. The program switched at 15:00 and the entries from 15:05 are a result of me quitting gdb. I don't have the frontend log as I forgot to pipe it from within the gdb run, however it looks the same as the last logs I posted.

Changed 14 years ago by FiveNines

Attachment: gdb.log added

Changed 14 years ago by FiveNines

Attachment: frontend.log.bz2 added

comment:25 Changed 14 years ago by derek@…

Cc: derek@… removed

I built 8862 and it looked promising as it seemed to switch programs fine and play, but after nearly one minute of the next program I get the same symptoms (may be worth noting that both programs were 'The Simpsons'). Unfortunately, I didn't have the verbose logging on nor was I running the frontend in gdb, but it appears to be the same problem. I'm heading out for the night, but if another backtrace of this is needed then I can create one in the morning. I also checked the recordings directory and there is no second file for the 5pm Simpsons, only one for the 4:30-5:00 episode I started watching. Please see bold lines and inline comments from the log entries below.


FRONTEND
========
2006-02-04 17:00:55.603 NVP: prebuffering pause
2006-02-04 17:00:57.006 NVP: Prebuffer wait timed out 10 times.
2006-02-04 17:00:58.406 NVP: Prebuffer wait timed out 10 times.

BACKEND
=======
2006-02-04 17:00:00.800 Finished recording The Simpsons: channel 1115
Expected, show ended at 5pm

2006-02-04 17:00:01.214 TVRec(1): Enabling Full LiveTV UI.
0: start_time: 0.036 duration: 98.162
1: start_time: 0.030 duration: 98.137
stream: start_time: 0.334 duration: 1090.757 bitrate=5107 kb/s
2006-02-04 17:00:01.309 AFD: Opened codec 0x8253540, id(MPEG2VIDEO) type(Video)
2006-02-04 17:00:01.311 TVRec(1): RingBufferChanged?()
2006-02-04 17:00:01.362 AFD: Opened codec 0x81476c0, id(MP2) type(Audio)
2006-02-04 17:00:01.375 Finished recording The Simpsons: channel 1115
Why is it saying finished again? This airing doesn't end until 5:30
Is this why I don't see a new file for the 5pm airing?
Perhaps a different reason for this particular prebuffer timeout?

2006-02-04 17:01:17.707 TVRec(1): Changing from WatchingLiveTV to None
2006-02-04 17:01:17.858 Finished recording The Simpsons: channel 1115
These last two are a result of me exiting back to the GUI

comment:26 Changed 14 years ago by brent@…

I have a PVR-500 using ivtv 0.4.1 and here is what I see:

The frontend reports this error: 2006-02-04 21:00:03.094 RingBuf?(/home/store/1012_20060204210002.mpg): Invalid file (fd 17) when opening '/home/store/1012_20060204210002.mpg'. 10 retries remain ing.

If I look at the store there is one with that name (0 bytes).

If I look at the files that the backend has opened: l-wx------ 1 root root 64 Feb 4 21:03 16 -> /home/store/1012_20060204210002.mpg

It is saying that file handle 16 has the file not fd 17.

At this point frontend gets error message and will let me return to the menu.

I am using svn from a few hours a go.

comment:27 Changed 14 years ago by Isaac Richards

Resolution: fixed
Status: reopenedclosed

(In [8866]) Fix a race condition (was confused about where it was in the chain during a smooth transition between shows)

Probably fixes #942, #971, #1213, and any other 'livetv breaks at end of a show' issue.

comment:28 Changed 14 years ago by brent@…

Resolution: fixed
Status: closedreopened

Yes, this does fix the show ending/show starting problem.

But, now if I change the channel 2 or 3 times the frontend just gos to the black screen and freezes.

Pressing ESC 2 times takes me back to the menu. Myth front end log shows: 2006-02-05 10:33:04.483 TV: Changing from None to WatchingLiveTV 2006-02-05 10:33:09.271 rebuffering (4097 32768) snip: 30 of these rebuffering msg's 2006-02-05 10:33:24.844 rebuffering (1 32768) 2006-02-05 10:33:25.070 NVP: prebuffering pause 2006-02-05 10:33:26.419 NVP: prebuffering pause 2006-02-05 10:33:26.484 rebuffering (16385 32768) 2006-02-05 10:33:26.806 NVP: prebuffering pause 2006-02-05 10:33:26.876 rebuffering (18433 32768) 2006-02-05 10:33:27.222 NVP: prebuffering pause 2006-02-05 10:33:27.780 rebuffering (4097 32768) 2006-02-05 10:33:28.484 rebuffering (6145 32768) 2006-02-05 10:33:28.676 rebuffering (18433 32768) 2006-02-05 10:33:29.388 rebuffering (4097 32768) 2006-02-05 10:33:29.836 rebuffering (4097 32768) 2006-02-05 10:33:29.964 rebuffering (10241 32768) 2006-02-05 10:33:30.612 rebuffering (10241 32768) 2006-02-05 10:33:30.748 rebuffering (14337 32768) Changed to channel 8 2006-02-05 10:33:31.205 rebuffering (22529 32768) 2006-02-05 10:33:31.653 NVP: prebuffering pause 2006-02-05 10:33:32.049 rebuffering (26625 32768) 2006-02-05 10:33:32.109 NVP: prebuffering pause 2006-02-05 10:33:32.569 rebuffering (6145 32768) 2006-02-05 10:33:32.953 rebuffering (18433 32768) 2006-02-05 10:33:33.657 rebuffering (20481 32768) Changed to channel 11 Changed to channel 55 - Black screen here Press keys: ESC ESC 2006-02-05 10:33:40.365 TV: Attempting to change from WatchingLiveTV to None

If I just do a channel up the second channel up cause the black screen. If you just around it does it on the third channel switch.

comment:29 Changed 14 years ago by Isaac Richards

Resolution: fixed
Status: reopenedclosed

If you have a different bug, you open a different ticket.

comment:30 Changed 14 years ago by anonymous

Resolution: fixed
Status: closedreopened

I'm not sure if this problem has been fixed for me - updated to SVN 8867 and I still have my problem which I think is related to this - LiveTV takes quite a while to start, and the video jerks forwards (slow->fast->slow->fast) and to fix this, need to adjust time stretch to 0.9 and then back to 1 then it's fixed until I exit and re-enter Live TV. Prebuffer pauses still comes up from the frontend. I will paste a snippet from the frontend output that I think hope shows my problem - I will be happy to post new logs if needed:

Prebuffer stuff:

2006-02-05 17:09:21.559 NVP: prebuffering pause 2006-02-05 17:09:21.559 NVP: Waiting for prebuffer.. 0 AAAAuLAAAAAAAAAAAAAAAAAAAAAAAAA 2006-02-05 17:09:21.647 NVP: Waiting for prebuffer.. 1 AAAAuLAAAAAAAAAAAAAAAAAAAAAAAAA <snip> 2006-02-05 17:09:22.457 NVP: Prebuffer wait timed out 10 times. <few more of this>

The slow->fast->slow->fast issue I get which I think is related to this:

2006-02-05 17:09:25.933 NVP: Audio is 3.15412 frames ahead of video,

doubling video frame interval.

2006-02-05 17:09:25.978 NVP: Audio is 3.52183 frames ahead of video,

doubling video frame interval.

2006-02-05 17:09:26.022 NVP: Audio is 3.76635 frames ahead of video,

doubling video frame interval.

<and this comes up until I change the time stretch rate>

comment:31 Changed 14 years ago by Isaac Richards

Resolution: fixed
Status: reopenedclosed

That's completely different behavior than the bug report.

comment:32 Changed 14 years ago by mythtv.cvs@…

Resolution: fixed
Status: closedreopened

It is very rare now, compared to before, but occasionally the frontend does stop between TV shows. I've attached a mythfrontend -v all log, hopefully it will help a bit.

On a side note, sometimes the frontend stops responding to lirc or keyboard commands for pause, etc.. but keeps playing perfectly fine. Not sure if this is related, and I haven't been able to reproduce it yet with -v logging.

Changed 14 years ago by anonymous

comment:33 Changed 14 years ago by Isaac Richards

Resolution: fixed
Status: reopenedclosed

Log indicates that this is very likely a different issue, please open a new bug.

Note: See TracTickets for help on using tickets.