Opened 9 years ago

Closed 9 years ago

#8848 closed defect (fixed)

Realtime commercial detection fails for some QAM channels

Reported by: dlinvill@… Owned by: cpinkham
Priority: minor Milestone: 0.24
Component: MythTV - Mythcommflag Version: Master Head
Severity: medium Keywords: commflag commercial
Cc: Ticket locked: no

Description

For some QAM channels commercial detection during the recording appears to hand in the logo detection phase and once the recording completes reports 0 commercial breaks detected. Rerunning a flag commercials job against the recording will run successfully and find the correct number of commercials.

I believe this is most likely the special case mentioned in this post: http://www.mythtv.org/pipermail/mythtv-users/2010-March/283701.html

These problems appeared when I switched from analog PVR150 recordings to QAM over an HDHomerun. The FPS mismatch example seems to match what I am seeing. I do not see segfaults on mythcommflag.

I have set recordings to not commercial detect during recording and the 0 commercials detected stopped happening. This only happens while recording and only on specific channels. I am able to reproduce this fairly easily by scheduling a recording on those channels.

I have commercial detection during recordings selected in mythtv-setup. I have configured recordings to start 5 seconds early with the system wide default.

I'm using mythbuntu 0.23.1-fixes Please attach all output as a file in bug reports. MythTV Version : 26006 MythTV Branch : branches/release-0-23-fixes Network Protocol : 23056 Library API : 0.23.1.201000710-1 QT Version : 4.6.2 Options compiled in:

linux debug using_oss using_alsa using_pulse using_jack using_pulseoutput using_backend using_dvb using_firewire using_frontend using_glx_proc_addr_arb using_hdhomerun using_hdpvr using_iptv using_ivtv using_joystick_menu using_libudev using_lirc using_mheg using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld using_xvmcw using_bindings_perl using_bindings_python using_opengl using_vdpau using_ffmpeg_threads using_libavc_5_3 using_live using_mheg

Attachments (5)

mythbackend.log.1.bz2 (472.2 KB) - added by dlinvill@… 9 years ago.
part 1 mythbackend log with -v file,extra,commflag,jobqueue on .24 26176
mythbackend.log.2.bz2 (296.6 KB) - added by dlinvill 9 years ago.
mythcommflag.zip (182.0 KB) - added by dlinvill 9 years ago.
GDB log of stuck commflag (no debugging symbols)
mythcommflag.dbg.ZIP (106.6 KB) - added by dlinvill 9 years ago.
gdb with mythbuntu debug packages installed
mythbackend.log (250.5 KB) - added by dlinvill 9 years ago.
v extra,commflag,playback,database,record,network backend log of scheduled recording. This recording was still reporting 'searching for logo' at 28 minutes after recording started. This is a the 2 minutes after the logo detection phase started. log is short because the full 30 minute session was 50 megs

Download all attachments as: .zip

Change History (14)

comment:1 Changed 9 years ago by robertm

Status: newassigned

comment:2 Changed 9 years ago by cpinkham

Status: assignedinfoneeded

Please run your backend with the "-v file,extra,commflag,jobqueue" option and attach the relevant portion of the backend logfile to the ticket. You should be able to see when the flagging job starts and ends with the jobqueue debugging enabled. Include all output between and including these lines.

Changed 9 years ago by dlinvill@…

Attachment: mythbackend.log.1.bz2 added

part 1 mythbackend log with -v file,extra,commflag,jobqueue on .24 26176

Changed 9 years ago by dlinvill

Attachment: mythbackend.log.2.bz2 added

comment:3 Changed 9 years ago by dlinvill@…

Status: infoneededassigned

I've attached log files covering a 45 minute recording that started mid recoding. The commflag job started with the recording and changed to 'Searching for Logo' after around 6 minutes. It never changed status until the recording ended and the job reported successful with 0 breaks found.

Even though this is a partial recording this is the behavior I see with full recordings.

This is on a newly installed trunk 26176 mythbuntu server recording from an hdhomerun on a QAM channel. The only settings I changed were to allow commercial flagging during the recording and to start 5 seconds early and end 300 seconds late.

comment:4 Changed 9 years ago by anonymous

Here is the version of the new server installed to test this:

Please attach all output as a file in bug reports. MythTV Version : 26176 MythTV Branch : trunk Network Protocol : 61 Library API : 0.23.20100905-1 QT Version : 4.6.2 Options compiled in:

linux debug using_alsa using_jack using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_dvb using_firewire using_frontend using_hdhomerun using_hdpvr using_iptv using_ivtv using_joystick_menu using_lirc using_mheg using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld using_xvmcw using_bindings_perl using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads using_live using_mheg

comment:5 Changed 9 years ago by cpinkham

Milestone: unknown0.24
Status: assignedinfoneeded
Version: UnspecifiedTrunk Head

It appears that it is hanging inside ClassicLogoDetector::searchForLogo() until the recording completes then it continues on and seems to skip the rest of the detection phases for some reason.

Can you reproduce the issue one more time? A 10-minute recording is enough if you can replicate the issue on-demand. Once the JobQueue? fires off the mythcommflag job, you should see something like this in the logs:

2010-09-08 22:15:24.453 JobQueue?: Commercial Detection Starting for "Burn Notice":"Friends and Enemies" recorded from channel 12106 at 2010-09-08T22:14:00 2010-09-08 22:15:24.454 JobQueue?: Running command: '/usr/bin/mythcommflag -j 5 -V 1073746499' 2010-09-08 22:15:24.454 Launching: /usr/bin/mythcommflag -j 5 -V 1073746499

Once you see that, in another terminal window, please run the following (substituting for '5', the value that you see printed in your logs. that's the job ID in the database).

gdb --args /usr/bin/mythcommflag -j 5 -V 1073746499 2>&1 | tee /tmp/mythcommflag.log

Once inside gdb, type 'run' to start the mythcommflag process.

When you see the mythcommflag process print out the following, wait another 30-45 seconds and then hit CTRL-C:

2010-09-08 22:22:30.983 JobQueue?: ChangeJobStatus?(5, Running, 'Searching for Logo') 2010-09-08 22:22:30.986 JobQueue?: ChangeJobComment?(5, 'Searching for Logo') 2010-09-08 22:22:30.988 Searching for Station Logo 2010-09-08 22:22:30.989 Trying with edgeDiff == 5

hitting CTRL-C will drop you to a gdb command prompt. At the gdb prompt, type the following and hit ENTER:

thread apply all bt full

when the backtrace is done and you're back at a gdb command prompt, you can type 'quit' and quit gdb.

Please compress and attach that gdb log to the ticket.

Changed 9 years ago by dlinvill

Attachment: mythcommflag.zip added

GDB log of stuck commflag (no debugging symbols)

Changed 9 years ago by dlinvill

Attachment: mythcommflag.dbg.ZIP added

gdb with mythbuntu debug packages installed

comment:6 Changed 9 years ago by cpinkham

OK, that log was helpful. It's trying to seek past the known positionmap and going into frame-by-frame seek mode. It could be getting stuck here somehow when run ~realtime. When you ran mythcommflag externally, it did get past the first logo detection loop run and go into the second run before you hit CTRL-C, so the symptoms weren't quite the same as before but it was informative.

Can you re-create the scenario one more time, and this time, run the backend with "-v extra,commflag,playback,database,record,network"

You don't need to do the gdb session this time, just run the backend, schedule a recording. Wait until the backend logs show the "Searching for Logo" message and then wait another couple minutes and that should be enough info I think.

Also, I see this tried to use the LiveTV Storage Group, was this LiveTV or a recording that you assigned to the LiveTV storage group?

I don't know if the recorder isn't writing out the seektable often enough or if the player isn't getting the data. The new log should help determine this.

comment:7 Changed 9 years ago by dlinvill

I was using livetv to start the two gdb log recordings. I can only tell if it's failing by waiting the 6 minutes for logo detection to start and then waiting to see if it moves to the % completed status messages. I just tried to get the verbose backend logs with a live tv recording but this time the show started flagging properly.

It's possible that I didn't wait long enough and one of the gdb logs was not an example of the problem.

I'll work on the detailed backend log when i can identify another problem show. So far Burn Notice and Warehouse 13 seem to fail every time.

Changed 9 years ago by dlinvill

Attachment: mythbackend.log added

v extra,commflag,playback,database,record,network backend log of scheduled recording. This recording was still reporting 'searching for logo' at 28 minutes after recording started. This is a the 2 minutes after the logo detection phase started. log is short because the full 30 minute session was 50 megs

comment:8 Changed 9 years ago by robertm

Status: infoneededassigned

comment:9 Changed 9 years ago by cpinkham

Resolution: fixed
Status: assignedclosed

(In [26458]) Add a little fudge to the Logo Detection wait time. As shown in #8848, there are some recordings in the wild that look like they should be ~29.97FPS, but over time they average much less according to the keyframe position map. This causes the logo detection wait to not be long enough which causes the logo detector to become starved of data which can lead to logo detection and possibly all commercial detection failing as shown in #8848.

Closes #8848.

Note: See TracTickets for help on using tickets.