HVR-1600: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation

HVR-1600: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation

[Brian J. Murrell]

[-- Attachment #1: Type: text/plain, Size: 3129 bytes --]

I've got an HVR-1600 in a fairly fast machine (P4 3GHz, two cores) on a
3.2.0 kernel and seem to be getting lots of this sort of thing:

Apr 19 20:09:10 pvr kernel: [34651.015170] cx18-0: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation
Apr 19 20:10:05 pvr kernel: [34705.375793] cx18-0: Skipped encoder IDX, MDL 415, 2 times - it must have dropped out of rotation
Apr 19 20:12:45 pvr kernel: [34865.535784] cx18-0: Skipped encoder IDX, MDL 426, 2 times - it must have dropped out of rotation
Apr 19 20:12:45 pvr kernel: [34865.609900] cx18-0: Skipped encoder IDX, MDL 430, 1 times - it must have dropped out of rotation
Apr 19 20:12:45 pvr kernel: [34865.684180] cx18-0: Could not find MDL 426 for stream encoder IDX
Apr 19 20:12:58 pvr kernel: [34878.912976] cx18-0: Could not find MDL 430 for stream encoder IDX
Apr 19 20:13:00 pvr kernel: [34880.850172] cx18-0: Skipped encoder MPEG, MDL 53, 62 times - it must have dropped out of rotation
Apr 19 20:15:25 pvr kernel: [35025.696747] cx18-0: Skipped encoder IDX, MDL 435, 2 times - it must have dropped out of rotation
Apr 19 20:15:25 pvr kernel: [35025.771765] cx18-0: Skipped encoder IDX, MDL 439, 1 times - it must have dropped out of rotation
Apr 19 20:15:25 pvr kernel: [35025.847732] cx18-0: Could not find MDL 435 for stream encoder IDX
Apr 19 20:15:25 pvr kernel: [35025.901315] cx18-0: Skipped TS, MDL 82, 16 times - it must have dropped out of rotation
Apr 19 20:15:32 pvr kernel: [35032.370364] cx18-0: Skipped encoder IDX, MDL 435, 2 times - it must have dropped out of rotation
Apr 19 20:15:38 pvr kernel: [35039.074592] cx18-0: Could not find MDL 439 for stream encoder IDX
Apr 19 20:15:40 pvr kernel: [35040.938552] cx18-0: Skipped encoder MPEG, MDL 29, 62 times - it must have dropped out of rotation
Apr 19 20:18:05 pvr kernel: [35185.859652] cx18-0: Skipped encoder IDX, MDL 445, 2 times - it must have dropped out of rotation
Apr 19 20:18:05 pvr kernel: [35185.933816] cx18-0: Skipped encoder IDX, MDL 449, 1 times - it must have dropped out of rotation
Apr 19 20:18:05 pvr kernel: [35186.008176] cx18-0: Could not find MDL 445 for stream encoder IDX
Apr 19 20:18:19 pvr kernel: [35199.237035] cx18-0: Could not find MDL 449 for stream encoder IDX
Apr 19 20:18:19 pvr kernel: [35199.289870] cx18-0: Could not find MDL 49 for stream encoder MPEG
Apr 19 20:18:25 pvr kernel: [35205.879310] cx18-0: Skipped encoder IDX, MDL 450, 2 times - it must have dropped out of rotation
Apr 19 20:23:26 pvr kernel: [35506.147134] cx18-0: Skipped encoder IDX, MDL 402, 2 times - it must have dropped out of rotation
Apr 19 20:24:19 pvr kernel: [35559.705155] cx18-0: Skipped encoder MPEG, MDL 16, 62 times - it must have dropped out of rotation

IIRC I was told previously that it was due to interrupts not being
serviced quickly enough.  Am I recalling correctly?

Could that really be a problem even with a dual core 3GHz P4?

Also, are those messages related to the clearqam path or the
MPEG2 hardware encoder path?  i.e. are those digital recording
messages or analog recording messages?

Cheers,
b.


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 262 bytes --]

Re: HVR-1600: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation

[Andy Walls]

On Sun, 2012-04-22 at 12:03 -0400, Brian J. Murrell wrote:
> I've got an HVR-1600 in a fairly fast machine (P4 3GHz, two cores) on a
> 3.2.0 kernel and seem to be getting lots of this sort of thing:
> 
> Apr 19 20:09:10 pvr kernel: [34651.015170] cx18-0: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation
> Apr 19 20:10:05 pvr kernel: [34705.375793] cx18-0: Skipped encoder IDX, MDL 415, 2 times - it must have dropped out of rotation
> Apr 19 20:12:45 pvr kernel: [34865.535784] cx18-0: Skipped encoder IDX, MDL 426, 2 times - it must have dropped out of rotation
> Apr 19 20:12:45 pvr kernel: [34865.609900] cx18-0: Skipped encoder IDX, MDL 430, 1 times - it must have dropped out of rotation
> Apr 19 20:12:45 pvr kernel: [34865.684180] cx18-0: Could not find MDL 426 for stream encoder IDX
> Apr 19 20:12:58 pvr kernel: [34878.912976] cx18-0: Could not find MDL 430 for stream encoder IDX
> Apr 19 20:13:00 pvr kernel: [34880.850172] cx18-0: Skipped encoder MPEG, MDL 53, 62 times - it must have dropped out of rotation
> Apr 19 20:15:25 pvr kernel: [35025.696747] cx18-0: Skipped encoder IDX, MDL 435, 2 times - it must have dropped out of rotation
> Apr 19 20:15:25 pvr kernel: [35025.771765] cx18-0: Skipped encoder IDX, MDL 439, 1 times - it must have dropped out of rotation
> Apr 19 20:15:25 pvr kernel: [35025.847732] cx18-0: Could not find MDL 435 for stream encoder IDX
> Apr 19 20:15:25 pvr kernel: [35025.901315] cx18-0: Skipped TS, MDL 82, 16 times - it must have dropped out of rotation
> Apr 19 20:15:32 pvr kernel: [35032.370364] cx18-0: Skipped encoder IDX, MDL 435, 2 times - it must have dropped out of rotation
> Apr 19 20:15:38 pvr kernel: [35039.074592] cx18-0: Could not find MDL 439 for stream encoder IDX
> Apr 19 20:15:40 pvr kernel: [35040.938552] cx18-0: Skipped encoder MPEG, MDL 29, 62 times - it must have dropped out of rotation
> Apr 19 20:18:05 pvr kernel: [35185.859652] cx18-0: Skipped encoder IDX, MDL 445, 2 times - it must have dropped out of rotation
> Apr 19 20:18:05 pvr kernel: [35185.933816] cx18-0: Skipped encoder IDX, MDL 449, 1 times - it must have dropped out of rotation
> Apr 19 20:18:05 pvr kernel: [35186.008176] cx18-0: Could not find MDL 445 for stream encoder IDX
> Apr 19 20:18:19 pvr kernel: [35199.237035] cx18-0: Could not find MDL 449 for stream encoder IDX
> Apr 19 20:18:19 pvr kernel: [35199.289870] cx18-0: Could not find MDL 49 for stream encoder MPEG
> Apr 19 20:18:25 pvr kernel: [35205.879310] cx18-0: Skipped encoder IDX, MDL 450, 2 times - it must have dropped out of rotation
> Apr 19 20:23:26 pvr kernel: [35506.147134] cx18-0: Skipped encoder IDX, MDL 402, 2 times - it must have dropped out of rotation
> Apr 19 20:24:19 pvr kernel: [35559.705155] cx18-0: Skipped encoder MPEG, MDL 16, 62 times - it must have dropped out of rotation
> 
> IIRC I was told previously that it was due to interrupts not being
> serviced quickly enough.  Am I recalling correctly?

Yes.

> Could that really be a problem even with a dual core 3GHz P4?

Yes.  You are looking at the evidence in those log messages.

If, in your system, IRQ service for device A under some circumstances
has precendence over IRQ service for the CX23418 and hence holds off its
service; and the irq handler in the driver for device A decides to
perform some some long I/O operations with device A; then it doesn't
matter how fast your CPU is. 

You may wish to use perf or ftrace, or some other tool/method of
measuring kernel interrupt handling latency to find out what causes any
delays from the CX23418 raising its IRQ line to cx18_irq_handler() being
called by the kernel.

I can tell you that I have optimized cx18_irq_handler(), and the
functions it calls, to death.  I simply cannot make it perform
significantly better.  The required PCI MMIO operations to the CX23418
dominate the time consumed in cx18_irq_handler().
[I await "Challenge accepted" from anyone. ;) ]

> Also, are those messages related to the clearqam path or the
> MPEG2 hardware encoder path?  i.e. are those digital recording
> messages or analog recording messages?

MPEG: analog video encoder DMA buffers
IDX:  MPEG index data DMA buffers from the analog video encoder
TS:   DTV (ATSC or QAM) DMA buffers

Every message above in your log, indicates your system "lost" a
notifcation from the CX23418 as it was too slow to respond to the
CX23418's interrupt.  Hence your recording/viewing of said stream missed
some data.

Note, the IDX stream only matters if you have an application that calls
the VIDIOC_G_ENC_INDEX ioctl() to collect I-Frame offsets in the MPEG
stream.  That is very rare, so I would not worry about lost IDX buffers.

> Cheers,
> b.

Regards,
Andy

Re: HVR-1600: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation

[Brian J. Murrell]

[-- Attachment #1: Type: text/plain, Size: 1212 bytes --]

On 12-04-22 04:56 PM, Andy Walls wrote:
> 
> If, in your system, IRQ service for device A under some circumstances
> has precendence over IRQ service for the CX23418 and hence holds off its
> service; and the irq handler in the driver for device A decides to
> perform some some long I/O operations with device A; then it doesn't
> matter how fast your CPU is. 

Yes, quite true.  I was forgetting about how nasty an irq handler can be
on other hardware.

> You may wish to use perf or ftrace, or some other tool/method of
> measuring kernel interrupt handling latency to find out what causes any
> delays from the CX23418 raising its IRQ line to cx18_irq_handler() being
> called by the kernel.

Excellent idea.  I'm afraid I'm quite (read: very) green in the area of
kernel performance profiling.  But I'm smart.  Looking around, it seems
that with ftrace, I am looking for the irqsoff tracer, is that correct?
 Unfortunately my kernel doesn't have that one:

# cat /sys/kernel/debug/tracing/available_tracers
blk function_graph mmiotrace wakeup_rt wakeup function nop

I can't seem to find any useful information on using perf to analyze ISR
latency.  Any pointers?

Cheers,
b.


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 262 bytes --]

Re: HVR-1600: Skipped encoder MPEG, MDL 63, 62 times - it must have dropped out of rotation

[Andy Walls]

On Mon, 2012-04-23 at 13:07 -0400, Brian J. Murrell wrote:
> On 12-04-22 04:56 PM, Andy Walls wrote:
> > 
> > If, in your system, IRQ service for device A under some circumstances
> > has precendence over IRQ service for the CX23418 and hence holds off its
> > service; and the irq handler in the driver for device A decides to
> > perform some some long I/O operations with device A; then it doesn't
> > matter how fast your CPU is. 
> 
> Yes, quite true.  I was forgetting about how nasty an irq handler can be
> on other hardware.
> 
> > You may wish to use perf or ftrace, or some other tool/method of
> > measuring kernel interrupt handling latency to find out what causes any
> > delays from the CX23418 raising its IRQ line to cx18_irq_handler() being
> > called by the kernel.
> 
> Excellent idea.  I'm afraid I'm quite (read: very) green in the area of
> kernel performance profiling. 

Here's an example of me checking latencies in the ivtv driver:

http://www.spinics.net/lists/linux-media/msg15762.html

Here are some good articles:

http://lwn.net/Articles/322666/
http://lwn.net/Articles/322731/
http://lwn.net/Articles/366796/
http://lwn.net/Articles/365835/
http://lwn.net/Articles/410200/
http://lwn.net/Articles/425583/
http://lwn.net/Articles/370423/

http://people.redhat.com/srostedt/ftrace-tutorial.odp
https://events.linuxfoundation.org/slides/2010/linuxcon_japan/linuxcon_jp2010_rostedt.pdf

An account of an in depth investigation into the maximum interrupts
disabled duration on some Sony of America test systems:
https://events.linuxfoundation.org/slides/2010/linuxcon_japan/linuxcon_jp2010_rowand.pdf


>  But I'm smart.  Looking around, it seems
> that with ftrace, I am looking for the irqsoff tracer, is that correct?

That sounds good as good as any.  (I always just end up learning what I
have to do when I need it.)


>  Unfortunately my kernel doesn't have that one:

It was probably just compiled without it.  On my Fedora 15 system, that
is the case with the stock kernel:

[andy@palomino ~]$  grep IRQSOFF_TRACER /boot/config-`uname -r`
# CONFIG_IRQSOFF_TRACER is not set

> # cat /sys/kernel/debug/tracing/available_tracers
> blk function_graph mmiotrace wakeup_rt wakeup function nop

*sigh*  So much for being convenient and easy.


> I can't seem to find any useful information on using perf to analyze ISR
> latency.  Any pointers?

Not really.  I have never used perf.  I assume you found this page:

https://perf.wiki.kernel.org/

> Cheers,
> b.

Regards,
Andy