Opened 18 years ago
Closed 18 years ago
#942 closed defect (fixed)
Prebuffer pauses in LiveTV with SVN 8479
Reported by: | 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)
Change History (54)
Changed 18 years ago by
Attachment: | mythfrontend.log added |
---|
comment:1 Changed 18 years ago by
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 18 years ago by
Attachment: | mythfrontendlog.txt added |
---|
my log from similar occurence using firewire
comment:2 Changed 18 years ago by
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 18 years ago by
Attachment: | mythfrontendlog-piers.txt added |
---|
used "mythfrontend -v playback"
comment:3 Changed 18 years ago by
Resolution: | → invalid |
---|---|
Status: | new → closed |
Need backend logs from the same time period as well.
comment:4 Changed 18 years ago by
Resolution: | invalid |
---|---|
Status: | closed → reopened |
Here you go. Logs as requested. Cheers!
Changed 18 years ago by
Attachment: | mythbackendlog-20060110.txt added |
---|
Changed 18 years ago by
Attachment: | mythfrontendlog-20060110.txt added |
---|
Changed 18 years ago by
Attachment: | mythbackend.log added |
---|
comment:6 Changed 18 years ago by
Milestone: | → 0.19 |
---|
comment:8 Changed 18 years ago by
Can't speak for Bob, but I tried the latest SVN this morning and still got the same problem.
comment:9 Changed 18 years ago by
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 18 years ago by
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 18 years ago by
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 18 years ago by
Attachment: | mythfrontend log 1-30-2006.txt added |
---|
Changed 18 years ago by
Attachment: | mythbackend log 1-30-2006.txt added |
---|
Changed 18 years ago by
Attachment: | mythfrontend log 1-31-2006.txt added |
---|
Changed 18 years ago by
Attachment: | mythbackend log 1-31-2006.txt added |
---|
comment:12 Changed 18 years ago by
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 18 years ago by
Attachment: | mythfrontend-prebuffer.log added |
---|
Changed 18 years ago by
Attachment: | mythbackend-prebuffer.log added |
---|
comment:13 Changed 18 years ago by
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 18 years ago by
I will update tonight and test. This is using XFS for the storage volume.
comment:15 Changed 18 years ago by
Cc: | derek@… added |
---|
Changed 18 years ago by
Attachment: | mythfrontend.feb03.log added |
---|
Output of mythfrontend -v playback
comment:16 Changed 18 years ago by
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 18 years ago by
Priority: | minor → blocker |
---|
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 18 years ago by
Priority: | blocker → minor |
---|
comment:19 Changed 18 years ago by
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 18 years ago by
Attachment: | mythbackend.L8R.log.gz added |
---|
Changed 18 years ago by
Attachment: | mythfrontend.L8R.log.gz added |
---|
comment:20 Changed 18 years ago by
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 18 years ago by
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 18 years ago by
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 18 years ago by
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.
comment:24 Changed 18 years ago by
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 18 years ago by
Attachment: | frontend.log.bz2 added |
---|
comment:25 Changed 18 years ago by
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 18 years ago by
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 18 years ago by
Resolution: | → fixed |
---|---|
Status: | reopened → closed |
comment:28 Changed 18 years ago by
Resolution: | fixed |
---|---|
Status: | closed → reopened |
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 18 years ago by
Resolution: | → fixed |
---|---|
Status: | reopened → closed |
If you have a different bug, you open a different ticket.
comment:30 Changed 18 years ago by
Resolution: | fixed |
---|---|
Status: | closed → reopened |
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 18 years ago by
Resolution: | → fixed |
---|---|
Status: | reopened → closed |
That's completely different behavior than the bug report.
comment:32 Changed 18 years ago by
Resolution: | fixed |
---|---|
Status: | closed → reopened |
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 18 years ago by
Attachment: | svn8873.5feb.mythfrontend.txt added |
---|
comment:33 Changed 18 years ago by
Resolution: | → fixed |
---|---|
Status: | reopened → closed |
Log indicates that this is very likely a different issue, please open a new bug.
mythfrontend -v playback