[mythtv-users] mythjobqueue commflagging startup delay?

Sat Feb 11 16:00:09 UTC 2012

I'm running mythjobqueue on another machine to do commflagging and I've
noticed what seems to be a delay in processing.  Let me give you an
example:

2012-02-11 10:30:22.917792 I  Database connection created: DBManager19
2012-02-11 10:30:22.917821 I  New DB connection, total: 13
2012-02-11 10:30:22.919498 I  Connected to database 'mythconverg' at host: 10.75.22.2
2012-02-11 10:30:22.919551 I  JobQueue: Commercial Detection Starting for "This Old House":"This Old House Barrington Project, Part 2 of 10" recorded from channel 4024 at 2012-02-11T10:30:00
2012-02-11 10:30:25.451068 C  mythcommflag version: master [v0.25pre-4426-g52d2827] www.mythtv.org
2012-02-11 10:30:25.451128 N  Enabled verbose msgs:  general
2012-02-11 10:30:25.451182 N  Setting Log Level to LOG_INFO
2012-02-11 10:30:25.451263 I  Added logging to the console
2012-02-11 10:30:25.451275 I  Added database logging to table logging
2012-02-11 10:30:25.451416 N  Setting up SIGHUP handler
2012-02-11 10:30:25.451521 N  Using runtime prefix = /usr
2012-02-11 10:30:25.451543 N  Using configuration directory = /home/brian/.mythtv
2012-02-11 10:30:25.543901 N  Empty LocalHostName.
2012-02-11 10:30:25.543926 I  Using localhost value of pc
2012-02-11 10:30:25.544562 I  Starting process manager
2012-02-11 10:30:25.546888 I  Starting IO manager (write)
2012-02-11 10:30:25.546967 I  Starting IO manager (read)
2012-02-11 10:30:25.547043 I  Starting process signal handler
2012-02-11 10:30:25.817701 I  Database connection created: DBManager0
2012-02-11 10:30:25.817768 I  New DB connection, total: 1
2012-02-11 10:30:25.843636 I  Connected to database 'mythconverg' at host: 10.75.22.2
2012-02-11 10:30:25.848694 I  Closing DB connection named 'DBManager0'
2012-02-11 10:30:25.848902 I  Database connection created: DBManager1
2012-02-11 10:30:25.848932 I  New DB connection, total: 1
2012-02-11 10:30:25.851183 I  Connected to database 'mythconverg' at host: 10.75.22.2
2012-02-11 10:30:25.852749 I  Database connection created: DBManager2
2012-02-11 10:30:25.852780 I  New DB connection, total: 2
2012-02-11 10:30:25.855351 I  Connected to database 'mythconverg' at host: 10.75.22.2
2012-02-11 10:30:25.861968 I  Current locale EN_CA
2012-02-11 10:30:25.882886 N  Reading locale defaults from /usr/share/mythtv//locales/en_ca.xml
2012-02-11 10:30:26.000097 I  Loading en_us translation for module mythfrontend
2012-02-11 10:30:26.789249 I  MythCoreContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2012-02-11 10:30:26.799223 I  Database connection created: DBManager3
2012-02-11 10:30:26.799253 I  New DB connection, total: 3
2012-02-11 10:30:26.801067 I  Connected to database 'mythconverg' at host: 10.75.22.2
2012-02-11 10:30:26.806201 I  MythCoreContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2012-02-11 10:30:26.809136 I  Using protocol version 72
2012-02-11 10:30:26.809632 I  Using protocol version 72
2012-02-11 10:30:31.404149 I  AFD: Opened codec 0x99333d0, id(MPEG2VIDEO) type(Video)
2012-02-11 10:30:31.404165 I  AFD: codec AC3 has 2 channels
2012-02-11 10:30:31.406250 I  AFD: Opened codec 0x99494e0, id(AC3) type(Audio)
2012-02-11 10:30:31.449677 I  MythCoreContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2012-02-11 10:30:31.451716 I  Using protocol version 72
2012-02-11 10:32:28.061488 I  Closing DB connection named 'DBManager3'
2012-02-11 10:40:54.519037 I  Finding Logo
2012-02-11 10:42:01.968519 E  AFD: Unknown audio decoding error
2012-02-11 10:42:19.470186 E  AFD: Unknown audio decoding error
2012-02-11 10:42:36.420925 E  AFD: Unknown audio decoding error
2012-02-11 10:42:52.931502 E  AFD: Unknown audio decoding error
2012-02-11 10:43:08.256197 E  AFD: Unknown audio decoding error
2012-02-11 10:43:23.775711 E  AFD: Unknown audio decoding error
2012-02-11 10:43:23.988572 I  0% Completed @ 495.049 fps.
2012-02-11 10:43:33.202921 I  10% Completed @ 573.797 fps.
2012-02-11 10:43:42.435865 I  20% Completed @ 579.306 fps.
2012-02-11 10:43:51.206760 I  RingBuf(/storage1/4024_20120211103000.mpg): Waited 0.2 seconds for data 
			to become available... 0 < 32768
2012-02-11 10:43:52.654268 I  30% Completed @ 561.369 fps.
2012-02-11 10:44:02.607390 I  40% Completed @ 556.5 fps.
2012-02-11 10:45:30.903521 I  50% Completed @ 212.401 fps.
2012-02-11 10:48:31.088122 I  60% Completed @ 105.434 fps.
2012-02-11 10:51:31.241218 I  70% Completed @ 77.5456 fps.
2012-02-11 10:54:31.458540 I  80% Completed @ 64.7025 fps.
2012-02-11 10:55:24.038787 N  Finished, 2 break(s) found.
2012-02-11 10:55:24.071686 I  Waiting for threads to exit.
2012-02-11 10:55:25.171867 I  Closing DB connection named 'DBManager2'
2012-02-11 10:55:25.224100 I  Closing DB connection named 'DBManager1'

Clearly the job starts at 10:30 when the recording started but notice
that it's not until 10:43:23 that commflagging starts reporting an
"fps" progress and when it does start reporting the progress is in the
hundreds of frames per second.  Of course that's only possible because
enough of the recording has "backed up" in the queue to be flagged.

I wonder why there is such a delay to start the actual flagging and
I could imagine how that delay would end up making watching that
while it's recording suck since there would be no commercials flagged
at the start of the viewing.  Granted this is a rare use-case but
still.

Even for the sake of evening out resource usage, wouldn't it be better
to start the commflagging right away?

Cheers,
b.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 262 bytes
Desc: OpenPGP digital signature
Url : http://www.mythtv.org/pipermail/mythtv-users/attachments/20120211/1ef68ee5/attachment.bin 