* cx88 invalid video opcodes when VBI enabled
@ 2018-04-15 17:37 Devin Heitmueller
2018-04-17 4:53 ` Daniel Glöckner
0 siblings, 1 reply; 7+ messages in thread
From: Devin Heitmueller @ 2018-04-15 17:37 UTC (permalink / raw)
To: Hans Verkuil, Linux Media Mailing List
Hello,
I received a report of a case where cx88 video capture was failing on
start and the dmesg was reporting an invalid opcode on the video IRQ
handler. I did a bisect, and it looks like it's a result of the
videobuf2 conversion done back in late 2014. A few notes:
1. It only seems to occur if both video and VBI are being used. I
cannot reproduce the issue when doing video only.
2. It seems like it's some sort of order-of-operations issue when
interacting with the video/vbi device nodes, since it only happens
with the stock VLC and not tvtime. It could also be that VLC uses
libzvbi, which access the VBI device in mmap mode, whereas tvtime
still uses read() for VBI access.
3. The problem is readily reproducible on a stock Ubuntu 14.04
system, as well as with 16.04, using the stock VLC that ships with the
distro. I'm testing with the following command line:
vlc v4l:///dev/video0 :v4l2-vbi-dev=/dev/vbi0
Sometimes it doesn't happen on the first hit and you have to run it a
few times, but I've never seen it take more than 5 executions for the
failure to occur.
4. The problem occurs even when I blacklist the cx88-alsa driver.
This is worth noting since cx88-alsa has a different issue that
results in dumping out the RISC engine state, and I wanted to both
ensure the two issues weren't confused for each other, nor that the
ALSA interaction could be impacting the order of operations for
interacting with the driver.
Any suggestions on the best way to debug this without having to learn
the intimate details of the RISC engine on the cx88? From the state
of the RISC engine it looks like there is some issue with queuing the
opcodes/arguments (where in some cases arguments are interpreted as
opcodes), but this is certainly not my area of expertise.
Thanks,
Devin
[ 54.427224] cx88[0]: irq vid [0x10088] vbi_risc1* vbi_risc2* opc_err*
[ 54.427232] cx88[0]/0: video risc op code error
[ 54.427238] cx88[0]: video y / packed - dma channel status dump
[ 54.427241] cx88[0]: cmds: initial risc: 0x87cdb000
[ 54.427244] cx88[0]: cmds: cdt base : 0x00180440
[ 54.427247] cx88[0]: cmds: cdt size : 0x0000000c
[ 54.427249] cx88[0]: cmds: iq base : 0x00180400
[ 54.427251] cx88[0]: cmds: iq size : 0x00000010
[ 54.427253] cx88[0]: cmds: risc pc : 0x87cdb03c
[ 54.427256] cx88[0]: cmds: iq wr ptr : 0x0000010e
[ 54.427258] cx88[0]: cmds: iq rd ptr : 0x00000102
[ 54.427260] cx88[0]: cmds: cdt current : 0x00000458
[ 54.427263] cx88[0]: cmds: pci target : 0x00000000
[ 54.427265] cx88[0]: cmds: line / byte : 0x00000000
[ 54.427267] cx88[0]: risc0: 0x80008000 [ sync resync count=0 ]
[ 54.427271] cx88[0]: risc1: 0x1c000280 [ write sol eol count=640 ]
[ 54.427276] cx88[0]: risc2: 0x87dc0000 [ arg #1 ]
[ 54.427279] cx88[0]: risc3: 0x1c000280 [ write sol eol count=640 ]
[ 54.427283] cx88[0]: iq 0: 0x70000000 [ jump count=0 ]
[ 54.427286] cx88[0]: iq 1: 0x80008000 [ arg #1 ]
[ 54.427289] cx88[0]: iq 2: 0x1c000280 [ write sol eol count=640 ]
[ 54.427293] cx88[0]: iq 3: 0x87dc0000 [ arg #1 ]
[ 54.427295] cx88[0]: iq 4: 0x1c000280 [ write sol eol count=640 ]
[ 54.427300] cx88[0]: iq 5: 0x87dc0500 [ arg #1 ]
[ 54.427302] cx88[0]: iq 6: 0x1c000280 [ write sol eol count=640 ]
[ 54.427306] cx88[0]: iq 7: 0x87dc0a00 [ arg #1 ]
[ 54.427309] cx88[0]: iq 8: 0x1c000280 [ write sol eol count=640 ]
[ 54.427313] cx88[0]: iq 9: 0x87dc0f00 [ arg #1 ]
[ 54.427315] cx88[0]: iq a: 0x1c000280 [ write sol eol count=640 ]
[ 54.427319] cx88[0]: iq b: 0x87dc1400 [ arg #1 ]
[ 54.427321] cx88[0]: iq c: 0x1c000280 [ write sol eol count=640 ]
[ 54.427326] cx88[0]: iq d: 0x87dc1900 [ arg #1 ]
[ 54.427328] cx88[0]: iq e: 0xd2000001 [ writecr irq2 count=1 ]
[ 54.427332] cx88[0]: iq f: 0x0031c040 [ arg #1 ]
[ 54.427334] cx88[0]: iq 10: 0x00180c00 [ arg #2 ]
[ 54.427337] cx88[0]: iq 11: 0x6f60580c [ arg #3 ]
[ 54.427339] cx88[0]: fifo: 0x00180c00 -> 0x183400
[ 54.427340] cx88[0]: ctrl: 0x00180400 -> 0x180460
[ 54.427342] cx88[0]: ptr1_reg: 0x00180eb8
[ 54.427344] cx88[0]: ptr2_reg: 0x00180458
[ 54.427347] cx88[0]: cnt1_reg: 0x00000007
[ 54.427349] cx88[0]: cnt2_reg: 0x00000000
--
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: cx88 invalid video opcodes when VBI enabled
2018-04-15 17:37 cx88 invalid video opcodes when VBI enabled Devin Heitmueller
@ 2018-04-17 4:53 ` Daniel Glöckner
2018-04-17 13:05 ` Devin Heitmueller
0 siblings, 1 reply; 7+ messages in thread
From: Daniel Glöckner @ 2018-04-17 4:53 UTC (permalink / raw)
To: Devin Heitmueller; +Cc: Hans Verkuil, Linux Media Mailing List
Hi,
On Sun, Apr 15, 2018 at 01:37:50PM -0400, Devin Heitmueller wrote:
> Any suggestions on the best way to debug this without having to learn
> the intimate details of the RISC engine on the cx88? From the state
> of the RISC engine it looks like there is some issue with queuing the
> opcodes/arguments (where in some cases arguments are interpreted as
> opcodes), but this is certainly not my area of expertise.
> [ 54.427224] cx88[0]: irq vid [0x10088] vbi_risc1* vbi_risc2* opc_err*
> [ 54.427232] cx88[0]/0: video risc op code error
> [ 54.427238] cx88[0]: video y / packed - dma channel status dump
Since the video IRQ status register has vbi_risc2 set, which we never
generate with our RISC programs, I assume it is the VBI RISC engine
that is executing garbage. So the dump of the video y/packed RISC engine
does not help us here. Can you add a call to cx88_sram_channel_dump for
SRAM_CH24 next to the existing one in cx8800_vid_irq?
Best regards,
Daniel
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: cx88 invalid video opcodes when VBI enabled
2018-04-17 4:53 ` Daniel Glöckner
@ 2018-04-17 13:05 ` Devin Heitmueller
2018-04-18 1:49 ` Devin Heitmueller
0 siblings, 1 reply; 7+ messages in thread
From: Devin Heitmueller @ 2018-04-17 13:05 UTC (permalink / raw)
To: Devin Heitmueller, Hans Verkuil, Linux Media Mailing List
Hi Daniel,
Thanks for the feedback.
On Tue, Apr 17, 2018 at 12:53 AM, Daniel Glöckner <daniel-gl@gmx.net> wrote:
>> [ 54.427224] cx88[0]: irq vid [0x10088] vbi_risc1* vbi_risc2* opc_err*
>> [ 54.427232] cx88[0]/0: video risc op code error
>> [ 54.427238] cx88[0]: video y / packed - dma channel status dump
>
> Since the video IRQ status register has vbi_risc2 set, which we never
> generate with our RISC programs, I assume it is the VBI RISC engine
> that is executing garbage. So the dump of the video y/packed RISC engine
> does not help us here. Can you add a call to cx88_sram_channel_dump for
> SRAM_CH24 next to the existing one in cx8800_vid_irq?
Doh, I actually already did that a few days ago but didn't save the
log (and in fact, it was the VBI RISC queue that had garbage on it).
I'll dig up the log later today (or just add the line back in and
recreate it).
Devin
--
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: cx88 invalid video opcodes when VBI enabled
2018-04-17 13:05 ` Devin Heitmueller
@ 2018-04-18 1:49 ` Devin Heitmueller
2018-04-18 18:29 ` Daniel Glöckner
0 siblings, 1 reply; 7+ messages in thread
From: Devin Heitmueller @ 2018-04-18 1:49 UTC (permalink / raw)
To: Devin Heitmueller, Hans Verkuil, Linux Media Mailing List
Hello Daniel,
See below.
Devin
[ 68.750805] cx88[0]: irq vid [0x18080] vbi_risc2* vbi_sync opc_err*
[ 68.750805] cx88[0]/0: video risc op code error
[ 68.750809] cx88[0]: video y / packed - dma channel status dump
[ 68.750811] cx88[0]: cmds: initial risc: 0x8aa98000
[ 68.750813] cx88[0]: cmds: cdt base : 0x00180440
[ 68.750815] cx88[0]: cmds: cdt size : 0x0000000c
[ 68.750816] cx88[0]: cmds: iq base : 0x00180400
[ 68.750818] cx88[0]: cmds: iq size : 0x00000010
[ 68.750820] cx88[0]: cmds: risc pc : 0x8aa1f03c
[ 68.750821] cx88[0]: cmds: iq wr ptr : 0x0000010d
[ 68.750823] cx88[0]: cmds: iq rd ptr : 0x00000101
[ 68.750825] cx88[0]: cmds: cdt current : 0x00000478
[ 68.750827] cx88[0]: cmds: pci target : 0x8a9ed800
[ 68.750828] cx88[0]: cmds: line / byte : 0x02780000
[ 68.750832] cx88[0]: risc0: 0x80008000 [ sync resync count=0 ]
[ 68.750835] cx88[0]: risc1: 0x1c000280 [ write sol eol count=640 ]
[ 68.750837] cx88[0]: risc2: 0x8ab20000 [ arg #1 ]
[ 68.750840] cx88[0]: risc3: 0x1c000280 [ write sol eol count=640 ]
[ 68.750842] cx88[0]: iq 0: 0x80008000 [ sync resync count=0 ]
[ 68.750845] cx88[0]: iq 1: 0x1c000280 [ write sol eol count=640 ]
[ 68.750847] cx88[0]: iq 2: 0x8ab20000 [ arg #1 ]
[ 68.750850] cx88[0]: iq 3: 0x1c000280 [ write sol eol count=640 ]
[ 68.750852] cx88[0]: iq 4: 0x8ab20500 [ arg #1 ]
[ 68.750854] cx88[0]: iq 5: 0x1c000280 [ write sol eol count=640 ]
[ 68.750856] cx88[0]: iq 6: 0x8ab20a00 [ arg #1 ]
[ 68.750859] cx88[0]: iq 7: 0x1c000280 [ write sol eol count=640 ]
[ 68.750861] cx88[0]: iq 8: 0x8ab20f00 [ arg #1 ]
[ 68.750864] cx88[0]: iq 9: 0x1c000280 [ write sol eol count=640 ]
[ 68.750866] cx88[0]: iq a: 0x8ab21400 [ arg #1 ]
[ 68.750868] cx88[0]: iq b: 0x1c000280 [ write sol eol count=640 ]
[ 68.750870] cx88[0]: iq c: 0x8ab21900 [ arg #1 ]
[ 68.750873] cx88[0]: iq d: 0x1c000280 [ write sol eol count=640 ]
[ 68.750875] cx88[0]: iq e: 0x8a9ed580 [ arg #1 ]
[ 68.750877] cx88[0]: iq f: 0x70010000 [ jump cnt0 count=0 ]
[ 68.750879] cx88[0]: iq 10: 0x00180c00 [ arg #1 ]
[ 68.750880] cx88[0]: fifo: 0x00180c00 -> 0x183400
[ 68.750881] cx88[0]: ctrl: 0x00180400 -> 0x180460
[ 68.750882] cx88[0]: ptr1_reg: 0x00181380
[ 68.750884] cx88[0]: ptr2_reg: 0x00180478
[ 68.750885] cx88[0]: cnt1_reg: 0x00000000
[ 68.750887] cx88[0]: cnt2_reg: 0x00000000
[ 68.750887] cx88[0]: vbi - dma channel status dump
[ 68.750889] cx88[0]: cmds: initial risc: 0x8a9cd000
[ 68.750891] cx88[0]: cmds: cdt base : 0x00180620
[ 68.750892] cx88[0]: cmds: cdt size : 0x00000004
[ 68.750894] cx88[0]: cmds: iq base : 0x001805e0
[ 68.750896] cx88[0]: cmds: iq size : 0x00000010
[ 68.750897] cx88[0]: cmds: risc pc : 0x8a9cd008
[ 68.750899] cx88[0]: cmds: iq wr ptr : 0x0000017f
[ 68.750901] cx88[0]: cmds: iq rd ptr : 0x00000011
[ 68.750902] cx88[0]: cmds: cdt current : 0x00000638
[ 68.750904] cx88[0]: cmds: pci target : 0x05d9d242
[ 68.750906] cx88[0]: cmds: line / byte : 0x00030000
[ 68.750910] cx88[0]: risc0: 0x8aa98000 [ sync sol irq2 23 21 19
cnt0 resync count=0 ]
[ 68.750913] cx88[0]: risc1: 0x00180440 [ INVALID 20 19 count=1088 ]
[ 68.750915] cx88[0]: risc2: 0x0000000c [ INVALID count=12 ]
[ 68.750918] cx88[0]: risc3: 0x00180400 [ INVALID 20 19 count=1024 ]
[ 68.750920] cx88[0]: iq 0: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750922] cx88[0]: iq 1: 0x8ab4f800 [ arg #1 ]
[ 68.750925] cx88[0]: iq 2: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750927] cx88[0]: iq 3: 0x8aa02000 [ arg #1 ]
[ 68.750930] cx88[0]: iq 4: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750932] cx88[0]: iq 5: 0x8ab43000 [ arg #1 ]
[ 68.750934] cx88[0]: iq 6: 0x70010000 [ jump cnt0 count=0 ]
[ 68.750936] cx88[0]: iq 7: 0x8ab43800 [ arg #1 ]
[ 68.750939] cx88[0]: iq 8: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750940] cx88[0]: iq 9: 0x8ab48000 [ arg #1 ]
[ 68.750943] cx88[0]: iq a: 0x80008200 [ sync resync count=512 ]
[ 68.750946] cx88[0]: iq b: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750948] cx88[0]: iq c: 0x8ab4c800 [ arg #1 ]
[ 68.750951] cx88[0]: iq d: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750952] cx88[0]: iq e: 0x8ab4d000 [ arg #1 ]
[ 68.750955] cx88[0]: iq f: 0x1c000800 [ write sol eol count=2048 ]
[ 68.750957] cx88[0]: iq 10: 0x00184400 [ arg #1 ]
[ 68.750958] cx88[0]: fifo: 0x00184400 -> 0x185400
[ 68.750958] cx88[0]: ctrl: 0x001805e0 -> 0x180640
[ 68.750960] cx88[0]: ptr1_reg: 0x00184400
[ 68.750961] cx88[0]: ptr2_reg: 0x00180628
[ 68.750963] cx88[0]: cnt1_reg: 0x00000000
[ 68.750964] cx88[0]: cnt2_reg: 0x00000000
--
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: cx88 invalid video opcodes when VBI enabled
2018-04-18 1:49 ` Devin Heitmueller
@ 2018-04-18 18:29 ` Daniel Glöckner
2018-04-20 21:54 ` Daniel Glöckner
0 siblings, 1 reply; 7+ messages in thread
From: Daniel Glöckner @ 2018-04-18 18:29 UTC (permalink / raw)
To: Devin Heitmueller; +Cc: Hans Verkuil, Linux Media Mailing List
Hi,
On Tue, Apr 17, 2018 at 09:49:22PM -0400, Devin Heitmueller wrote:
> [ 68.750809] cx88[0]: video y / packed - dma channel status dump
> [ 68.750811] cx88[0]: cmds: initial risc: 0x8aa98000
> [ 68.750813] cx88[0]: cmds: cdt base : 0x00180440
> [ 68.750815] cx88[0]: cmds: cdt size : 0x0000000c
> [ 68.750816] cx88[0]: cmds: iq base : 0x00180400
[...]
> [ 68.750887] cx88[0]: vbi - dma channel status dump
[...]
> [ 68.750899] cx88[0]: cmds: iq wr ptr : 0x0000017f
> [ 68.750901] cx88[0]: cmds: iq rd ptr : 0x00000011
> [ 68.750902] cx88[0]: cmds: cdt current : 0x00000638
[...]
> [ 68.750910] cx88[0]: risc0: 0x8aa98000 [ sync sol irq2 23 21 19 cnt0 resync count=0 ]
> [ 68.750913] cx88[0]: risc1: 0x00180440 [ INVALID 20 19 count=1088 ]
> [ 68.750915] cx88[0]: risc2: 0x0000000c [ INVALID count=12 ]
> [ 68.750918] cx88[0]: risc3: 0x00180400 [ INVALID 20 19 count=1024 ]
The VBI instruction queue read pointer points outside the VBI instruction
queue and into the video y/packed CMDS (to 0x180000+0x11*4). The values
next to the iq rd ptr look ok.
We only initialize the iq rd ptr to zero in cx88_sram_channel_setup and
then never touch it again. The hardware takes care of updating it.
Maybe cx88_sram_channel_setup is sometimes called for channel 24 while the
VBI risc engine is still running? One could try adding a WARN_ONCE at the
top of the function to catch that case.
Best regards,
Daniel
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: cx88 invalid video opcodes when VBI enabled
2018-04-18 18:29 ` Daniel Glöckner
@ 2018-04-20 21:54 ` Daniel Glöckner
2018-04-21 17:57 ` Devin Heitmueller
0 siblings, 1 reply; 7+ messages in thread
From: Daniel Glöckner @ 2018-04-20 21:54 UTC (permalink / raw)
To: Devin Heitmueller, Hans Verkuil, Linux Media Mailing List
Hi,
On Wed, Apr 18, 2018 at 08:29:59PM +0200, Daniel Glöckner wrote:
> The VBI instruction queue read pointer points outside the VBI instruction
> queue and into the video y/packed CMDS (to 0x180000+0x11*4). The values
> next to the iq rd ptr look ok.
>
> We only initialize the iq rd ptr to zero in cx88_sram_channel_setup and
> then never touch it again. The hardware takes care of updating it.
> Maybe cx88_sram_channel_setup is sometimes called for channel 24 while the
> VBI risc engine is still running?
for some reason I feel like buffer_queue in cx88-vbi.c should not be
calling cx8800_start_vbi_dma as it is also called a few lines further
down in start_streaming.
Devin, can you check if it helps to remove that line and if VBI still
works afterwards?
Best regards,
Daniel
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: cx88 invalid video opcodes when VBI enabled
2018-04-20 21:54 ` Daniel Glöckner
@ 2018-04-21 17:57 ` Devin Heitmueller
0 siblings, 0 replies; 7+ messages in thread
From: Devin Heitmueller @ 2018-04-21 17:57 UTC (permalink / raw)
To: Devin Heitmueller, Hans Verkuil, Linux Media Mailing List
Hi Daniel,
My apologies for the delayed replies; been out of town for the last
couple of days.
On Fri, Apr 20, 2018 at 5:54 PM, Daniel Glöckner <daniel-gl@gmx.net> wrote:
> for some reason I feel like buffer_queue in cx88-vbi.c should not be
> calling cx8800_start_vbi_dma as it is also called a few lines further
> down in start_streaming.
>
> Devin, can you check if it helps to remove that line and if VBI still
> works afterwards?
So I've commented out that line in buffer_queue, and so far haven't
been able to reproduce the issue, and it does look like VBI is working
as expected (captions are being rendered in VLC). This doesn't
suggest I've done exhaustive testing by any means, but it's certainly
a good sign.
I've seen drivers in the past which start the main data pump when
buffer_queue() or buffer_prepare() is called (whether it be to start a
DMA engine in the case of PCI or start URB submission in the case of
USB devices). However it's not clear that's required, in particular
with VB2 which will automatically call start_streaming() in the case
where read() is used. If I had to guess, I suspect the origin of
starting DMA that early was probably oriented around users who wanted
to simply run "cat /dev/video0 > out.mpeg" without having to
explicitly issue a bunch of V4L ioctl() calls beforehand.
It's worth noting that we're also doing it in the buffer_queue()
routine for video and not just VBI. Presumably we would want to drop
both cases.
Hans, you did the VB2 conversion and have obviously been through this
exercise with a number of other drivers. Any thoughts on whether we
can drop the starting of DMA engine in buffer_queue()?
On a related note, a quick review of the start/stop logic for DMA in
that driver suggests the calls might not be properly balanced. Looks
like portions of the core logic are also duplicated between
stop_streaming() and stop_video_dma() (which is only ever used if
CONFIG_PM is defined). It feels like it could probably use some
review/cleanup, although I'm loathed to touch such a mature driver for
fear of breaking something subtle.
Thanks,
Devin
--
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2018-04-21 17:57 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2018-04-15 17:37 cx88 invalid video opcodes when VBI enabled Devin Heitmueller
2018-04-17 4:53 ` Daniel Glöckner
2018-04-17 13:05 ` Devin Heitmueller
2018-04-18 1:49 ` Devin Heitmueller
2018-04-18 18:29 ` Daniel Glöckner
2018-04-20 21:54 ` Daniel Glöckner
2018-04-21 17:57 ` Devin Heitmueller
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox