CX18 Oops

CX18 Oops

[Brandon Jenkins]

Hi All

I am running kernel 2.6.26 on  Ubuntu 8.04. Any thoughts?

Thanks in advance

Brandon

[35037.080230] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000000
[35037.080258] IP: [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
[35037.080284] PGD 21b9e9067 PUD 218c12067 PMD 0
[35037.080298] Oops: 0000 [1] PREEMPT SMP
[35037.080311] CPU 1
[35037.080320] Modules linked in: binfmt_misc iptable_filter ip_tables
x_tables xfs loop mxl5005s s5h1409 tuner_simple ipv6 tuner_types
cs5345 tuner usbhid cx18 dvb_core hid compat_ioctl32 videodev
v4l1_compat i2c_algo_bit cx2341x v4l2_common tveeprom psmouse i2c_core
button ext3 jbd mbcache sd_mod ahci libata scsi_mod iTCO_wdt dock
r8169 ehci_hcd uhci_hcd usbcore raid10 raid456 async_xor async_memcpy
async_tx xor raid1 raid0 multipath linear md_mod dm_mirror dm_log
dm_snapshot dm_mod thermal processor fan fuse
[35037.080488] Pid: 15894, comm: java Not tainted 2.6.26-server-sagetv #1
[35037.080499] RIP: 0010:[<ffffffffa01e4180>]  [<ffffffffa01e4180>]
:cx18:cx18_queue_move_buf+0x0/0xa0
[35037.080521] RSP: 0018:ffff810217c4be50  EFLAGS: 00010046
[35037.080530] RAX: 00000000003d0000 RBX: 0000000000000000 RCX: 0000000000000001
[35037.080541] RDX: ffff81021d9a81f8 RSI: 0000000000000000 RDI: ffff81021d9a8188
[35037.080552] RBP: ffff81021d9a81f8 R08: 0000000000000000 R09: 000000000009d548
[35037.080563] R10: 000000000009d547 R11: 0000000000000002 R12: 0000000000000001
[35037.080574] R13: 0000000000020000 R14: 0000000000000000 R15: ffff81021d9a8188
[35037.080585] FS:  0000000000000000(0000) GS:ffff81021fc06580(0063)
knlGS:00000000c9efbb90
[35037.080601] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
[35037.080611] CR2: 0000000000000000 CR3: 00000002179b8000 CR4: 00000000000006a0
[35037.080622] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[35037.080633] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[35037.080644] Process java (pid: 15894, threadinfo ffff810217c4a000,
task ffff81020ad6c620)
[35037.080659] Stack:  ffffffffa01e42c2 00000000003d0000
ffff81021d9a81b0 0000000000000292
[35037.080682]  000000011d9a81f8 ffff8102003d0000 ffff81021d9a8188
ffff81021d9a8000
[35037.080703]  ffff81021d9a8188 ffff81021d9a8128 ffff81021fd15600
0000000000000000
[35037.080719] Call Trace:
[35037.080736]  [<ffffffffa01e42c2>] ? :cx18:cx18_queue_move+0xa2/0x160
[35037.080752]  [<ffffffffa01e58e8>] ? :cx18:cx18_release_stream+0x78/0xc0
[35037.080767]  [<ffffffffa01e5d86>] ? :cx18:cx18_v4l2_close+0xb6/0x150
[35037.080781]  [<ffffffff802a88d1>] ? __fput+0xb1/0x1d0
[35037.080792]  [<ffffffff802a5404>] ? filp_close+0x54/0x90
[35037.080803]  [<ffffffff802a6c1f>] ? sys_close+0x9f/0x110
[35037.080815]  [<ffffffff80226c02>] ? sysenter_do_call+0x1b/0x66
[35037.080826]  [<ffffffff80315060>] ? dummy_file_free_security+0x0/0x10
[35037.080839]
[35037.080845]
[35037.080852] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
10 49
[35037.080976] RIP  [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
[35037.080992]  RSP <ffff810217c4be50>
[35037.081000] CR2: 0000000000000000
[35037.081192] ---[ end trace 10100555b3a0d104 ]---
[35037.090147] note: java[15894] exited with preempt_count 1

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Tue, 2008-08-05 at 21:04 -0400, Brandon Jenkins wrote:
> Hi All
> 
> I am running kernel 2.6.26 on  Ubuntu 8.04. Any thoughts?

I ran into a similar Oops in the same function on 23 July.  I had it at
a lower priority since no one had complained about it and it seems rare.

I'll try and get to it before Saturday morning.  If anyone wants to
submit a patch before then, I'll review it ASAP after receipt.

Regards,
Andy

> Thanks in advance
> 
> Brandon
> 
> [35037.080230] BUG: unable to handle kernel NULL pointer dereference
> at 0000000000000000
> [35037.080258] IP: [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
> [35037.080284] PGD 21b9e9067 PUD 218c12067 PMD 0
> [35037.080298] Oops: 0000 [1] PREEMPT SMP
> [35037.080311] CPU 1
> [35037.080320] Modules linked in: binfmt_misc iptable_filter ip_tables
> x_tables xfs loop mxl5005s s5h1409 tuner_simple ipv6 tuner_types
> cs5345 tuner usbhid cx18 dvb_core hid compat_ioctl32 videodev
> v4l1_compat i2c_algo_bit cx2341x v4l2_common tveeprom psmouse i2c_core
> button ext3 jbd mbcache sd_mod ahci libata scsi_mod iTCO_wdt dock
> r8169 ehci_hcd uhci_hcd usbcore raid10 raid456 async_xor async_memcpy
> async_tx xor raid1 raid0 multipath linear md_mod dm_mirror dm_log
> dm_snapshot dm_mod thermal processor fan fuse
> [35037.080488] Pid: 15894, comm: java Not tainted 2.6.26-server-sagetv #1
> [35037.080499] RIP: 0010:[<ffffffffa01e4180>]  [<ffffffffa01e4180>]
> :cx18:cx18_queue_move_buf+0x0/0xa0
> [35037.080521] RSP: 0018:ffff810217c4be50  EFLAGS: 00010046
> [35037.080530] RAX: 00000000003d0000 RBX: 0000000000000000 RCX: 0000000000000001
> [35037.080541] RDX: ffff81021d9a81f8 RSI: 0000000000000000 RDI: ffff81021d9a8188
> [35037.080552] RBP: ffff81021d9a81f8 R08: 0000000000000000 R09: 000000000009d548
> [35037.080563] R10: 000000000009d547 R11: 0000000000000002 R12: 0000000000000001
> [35037.080574] R13: 0000000000020000 R14: 0000000000000000 R15: ffff81021d9a8188
> [35037.080585] FS:  0000000000000000(0000) GS:ffff81021fc06580(0063)
> knlGS:00000000c9efbb90
> [35037.080601] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
> [35037.080611] CR2: 0000000000000000 CR3: 00000002179b8000 CR4: 00000000000006a0
> [35037.080622] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [35037.080633] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [35037.080644] Process java (pid: 15894, threadinfo ffff810217c4a000,
> task ffff81020ad6c620)
> [35037.080659] Stack:  ffffffffa01e42c2 00000000003d0000
> ffff81021d9a81b0 0000000000000292
> [35037.080682]  000000011d9a81f8 ffff8102003d0000 ffff81021d9a8188
> ffff81021d9a8000
> [35037.080703]  ffff81021d9a8188 ffff81021d9a8128 ffff81021fd15600
> 0000000000000000
> [35037.080719] Call Trace:
> [35037.080736]  [<ffffffffa01e42c2>] ? :cx18:cx18_queue_move+0xa2/0x160
> [35037.080752]  [<ffffffffa01e58e8>] ? :cx18:cx18_release_stream+0x78/0xc0
> [35037.080767]  [<ffffffffa01e5d86>] ? :cx18:cx18_v4l2_close+0xb6/0x150
> [35037.080781]  [<ffffffff802a88d1>] ? __fput+0xb1/0x1d0
> [35037.080792]  [<ffffffff802a5404>] ? filp_close+0x54/0x90
> [35037.080803]  [<ffffffff802a6c1f>] ? sys_close+0x9f/0x110
> [35037.080815]  [<ffffffff80226c02>] ? sysenter_do_call+0x1b/0x66
> [35037.080826]  [<ffffffff80315060>] ? dummy_file_free_security+0x0/0x10
> [35037.080839]
> [35037.080845]
> [35037.080852] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
> 47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
> 1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
> 10 49
> [35037.080976] RIP  [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
> [35037.080992]  RSP <ffff810217c4be50>
> [35037.081000] CR2: 0000000000000000
> [35037.081192] ---[ end trace 10100555b3a0d104 ]---
> [35037.090147] note: java[15894] exited with preempt_count 1
> 
> --
> video4linux-list mailing list
> Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
> https://www.redhat.com/mailman/listinfo/video4linux-list
> 

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Tue, Aug 5, 2008 at 9:29 PM, Andy Walls <awalls@radix.net> wrote:
> On Tue, 2008-08-05 at 21:04 -0400, Brandon Jenkins wrote:
>> Hi All
>>
>> I am running kernel 2.6.26 on  Ubuntu 8.04. Any thoughts?
>
> I ran into a similar Oops in the same function on 23 July.  I had it at
> a lower priority since no one had complained about it and it seems rare.
>
> I'll try and get to it before Saturday morning.  If anyone wants to
> submit a patch before then, I'll review it ASAP after receipt.
>
> Regards,
> Andy
>
>> Thanks in advance
>>
>> Brandon
>>
>> [35037.080230] BUG: unable to handle kernel NULL pointer dereference
>> at 0000000000000000
>> [35037.080258] IP: [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
>> [35037.080284] PGD 21b9e9067 PUD 218c12067 PMD 0
>> [35037.080298] Oops: 0000 [1] PREEMPT SMP
>> [35037.080311] CPU 1
>> [35037.080320] Modules linked in: binfmt_misc iptable_filter ip_tables
>> x_tables xfs loop mxl5005s s5h1409 tuner_simple ipv6 tuner_types
>> cs5345 tuner usbhid cx18 dvb_core hid compat_ioctl32 videodev
>> v4l1_compat i2c_algo_bit cx2341x v4l2_common tveeprom psmouse i2c_core
>> button ext3 jbd mbcache sd_mod ahci libata scsi_mod iTCO_wdt dock
>> r8169 ehci_hcd uhci_hcd usbcore raid10 raid456 async_xor async_memcpy
>> async_tx xor raid1 raid0 multipath linear md_mod dm_mirror dm_log
>> dm_snapshot dm_mod thermal processor fan fuse
>> [35037.080488] Pid: 15894, comm: java Not tainted 2.6.26-server-sagetv #1
>> [35037.080499] RIP: 0010:[<ffffffffa01e4180>]  [<ffffffffa01e4180>]
>> :cx18:cx18_queue_move_buf+0x0/0xa0
>> [35037.080521] RSP: 0018:ffff810217c4be50  EFLAGS: 00010046
>> [35037.080530] RAX: 00000000003d0000 RBX: 0000000000000000 RCX: 0000000000000001
>> [35037.080541] RDX: ffff81021d9a81f8 RSI: 0000000000000000 RDI: ffff81021d9a8188
>> [35037.080552] RBP: ffff81021d9a81f8 R08: 0000000000000000 R09: 000000000009d548
>> [35037.080563] R10: 000000000009d547 R11: 0000000000000002 R12: 0000000000000001
>> [35037.080574] R13: 0000000000020000 R14: 0000000000000000 R15: ffff81021d9a8188
>> [35037.080585] FS:  0000000000000000(0000) GS:ffff81021fc06580(0063)
>> knlGS:00000000c9efbb90
>> [35037.080601] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
>> [35037.080611] CR2: 0000000000000000 CR3: 00000002179b8000 CR4: 00000000000006a0
>> [35037.080622] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> [35037.080633] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>> [35037.080644] Process java (pid: 15894, threadinfo ffff810217c4a000,
>> task ffff81020ad6c620)
>> [35037.080659] Stack:  ffffffffa01e42c2 00000000003d0000
>> ffff81021d9a81b0 0000000000000292
>> [35037.080682]  000000011d9a81f8 ffff8102003d0000 ffff81021d9a8188
>> ffff81021d9a8000
>> [35037.080703]  ffff81021d9a8188 ffff81021d9a8128 ffff81021fd15600
>> 0000000000000000
>> [35037.080719] Call Trace:
>> [35037.080736]  [<ffffffffa01e42c2>] ? :cx18:cx18_queue_move+0xa2/0x160
>> [35037.080752]  [<ffffffffa01e58e8>] ? :cx18:cx18_release_stream+0x78/0xc0
>> [35037.080767]  [<ffffffffa01e5d86>] ? :cx18:cx18_v4l2_close+0xb6/0x150
>> [35037.080781]  [<ffffffff802a88d1>] ? __fput+0xb1/0x1d0
>> [35037.080792]  [<ffffffff802a5404>] ? filp_close+0x54/0x90
>> [35037.080803]  [<ffffffff802a6c1f>] ? sys_close+0x9f/0x110
>> [35037.080815]  [<ffffffff80226c02>] ? sysenter_do_call+0x1b/0x66
>> [35037.080826]  [<ffffffff80315060>] ? dummy_file_free_security+0x0/0x10
>> [35037.080839]
>> [35037.080845]
>> [35037.080852] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
>> 47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
>> 1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
>> 10 49
>> [35037.080976] RIP  [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
>> [35037.080992]  RSP <ffff810217c4be50>
>> [35037.081000] CR2: 0000000000000000
>> [35037.081192] ---[ end trace 10100555b3a0d104 ]---
>> [35037.090147] note: java[15894] exited with preempt_count 1
>>
>> --
>> video4linux-list mailing list
>> Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
>> https://www.redhat.com/mailman/listinfo/video4linux-list
>>
>
>
Here's another one. Is there something I could do to lessen the issue
while a patch is being worked? Rebuild the kernel without preempting?

Thanks in advance,

Brandon

[37769.189579] cx18-0: Cannot find buffer 68 for stream encoder MPEG
[37769.189579] cx18-0: Could not find buf 68 for stream encoder MPEG
[37985.181190] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000000
[37985.181190] IP: [<ffffffffa01e2180>] :cx18:cx18_queue_move_buf+0x0/0xa0
[37985.181190] PGD 214969067 PUD 214884067 PMD 0
[37985.181190] Oops: 0000 [1] PREEMPT SMP
[37985.181190] CPU 3
[37985.181190] Modules linked in: binfmt_misc iptable_filter ip_tables
x_tables xfs loop mxl5005s ipv6 s5h1409 tuner_simple tuner_types
cs5345 tuner usbhid cx18 dvb_core hid compat_ioctl32 videodev
v4l1_compat i2c_algo_bit cx2341x v4l2_common tveeprom psmouse i2c_core
button ext3 jbd mbcache sd_mod ahci iTCO_wdt libata r8169 scsi_mod
dock ehci_hcd uhci_hcd usbcore raid10 raid456 async_xor async_memcpy
async_tx xor raid1 raid0 multipath linear md_mod dm_mirror dm_log
dm_snapshot dm_mod thermal processor fan fuse
[37985.181190] Pid: 493, comm: java Not tainted 2.6.26-server-sagetv #1
[37985.181190] RIP: 0010:[<ffffffffa01e2180>]  [<ffffffffa01e2180>]
:cx18:cx18_queue_move_buf+0x0/0xa0
[37985.181190] RSP: 0018:ffff810197ec9e50  EFLAGS: 00010046
[37985.181190] RAX: 00000000000e0000 RBX: 0000000000000000 RCX: 0000000000000001
[37985.181190] RDX: ffff81021d0181f8 RSI: 0000000000000000 RDI: ffff81021d018188
[37985.181190] RBP: ffff81021d0181f8 R08: 0000000000000000 R09: 000000000004c308
[37985.181190] R10: 000000000004c307 R11: ffff810001025a70 R12: 0000000000000001
[37985.181190] R13: 0000000000310000 R14: 0000000000000000 R15: ffff81021d018188
[37985.181190] FS:  0000000000000000(0000) GS:ffff81021fc06980(0063)
knlGS:00000000c74f2b90
[37985.181190] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
[37985.181190] CR2: 0000000000000000 CR3: 000000021405e000 CR4: 00000000000006a0
[37985.181190] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[37985.181190] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[37985.181190] Process java (pid: 493, threadinfo ffff810197ec8000,
task ffff8101fe97dfa0)
[37985.181190] Stack:  ffffffffa01e22c2 ffff8100000e0000
ffff81021d0181b0 0000000000000292
[37985.181190]  000000011d0181f8 ffff8102000e0000 ffff81021d018188
ffff81021d018000
[37985.181190]  ffff81021d018188 ffff81021d018128 ffff81021fc92300
0000000000000000
[37985.181190] Call Trace:
[37985.181190]  [<ffffffffa01e22c2>] ? :cx18:cx18_queue_move+0xa2/0x160
[37985.181190]  [<ffffffffa01e38d8>] ? :cx18:cx18_release_stream+0x78/0xc0
[37985.181190]  [<ffffffffa01e3d76>] ? :cx18:cx18_v4l2_close+0xb6/0x150
[37985.181190]  [<ffffffff802a88d1>] ? __fput+0xb1/0x1d0
[37985.181190]  [<ffffffff802a5404>] ? filp_close+0x54/0x90
[37985.181190]  [<ffffffff802a6c1f>] ? sys_close+0x9f/0x110
[37985.181190]  [<ffffffff80226c02>] ? sysenter_do_call+0x1b/0x66
[37985.181190]
[37985.181190]
[37985.181190] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
10 49
[37985.181190] RIP  [<ffffffffa01e2180>] :cx18:cx18_queue_move_buf+0x0/0xa0
[37985.181190]  RSP <ffff810197ec9e50>
[37985.181190] CR2: 0000000000000000
[37985.181190] ---[ end trace cbfa59d18c547596 ]---

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Wed, 2008-08-06 at 06:57 -0400, Brandon Jenkins wrote:
> On Tue, Aug 5, 2008 at 9:29 PM, Andy Walls <awalls@radix.net> wrote:
> > On Tue, 2008-08-05 at 21:04 -0400, Brandon Jenkins wrote:
> >> Hi All
> >>
> >> I am running kernel 2.6.26 on  Ubuntu 8.04. Any thoughts?
> >
> > I ran into a similar Oops in the same function on 23 July.  I had it at
> > a lower priority since no one had complained about it and it seems rare.
> >
> > I'll try and get to it before Saturday morning.  If anyone wants to
> > submit a patch before then, I'll review it ASAP after receipt.
> >
> > Regards,
> > Andy
> >
> >> Thanks in advance
> >>
> >> Brandon
> >>

> >> [35037.080852] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
> >> 47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
> >> 1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
> >> 10 49
> >> [35037.080976] RIP  [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
> >> [35037.080992]  RSP <ffff810217c4be50>
> >> [35037.081000] CR2: 0000000000000000
> >> [35037.081192] ---[ end trace 10100555b3a0d104 ]---
> >> [35037.090147] note: java[15894] exited with preempt_count 1
> >>
> >> --
> >> video4linux-list mailing list
> >> Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
> >> https://www.redhat.com/mailman/listinfo/video4linux-list
> >>
> >
> >
> Here's another one. Is there something I could do to lessen the issue
> while a patch is being worked? Rebuild the kernel without preempting?


Nope.  The problem I have has to do with per stream queue and buffer
accounting being slightly but you'll only notice when it's being freed.

I suspect you have the same problem, but I can't tell for sure as you
system is compiling the code differently than mine.

Could you please send the output of

$ cd v4l-dvb
$ objdump -D v4l/cx18-queue.o

from the offending build to me.  That way I can see the assembled
machine code and verify where in the function the NULL dereference is
happening.

If you have the exact same problem as me, I can give you a "band-aid"
patch which will lessen the problem in short order.  It'll be a band aid
because it won't fix the accounting problem though.  I need to do more
extensive test and debug to find out where the accounting of buffers is
getting screwed up.

Regards,
Andy

> Thanks in advance,
> 
> Brandon
> 
> [37769.189579] cx18-0: Cannot find buffer 68 for stream encoder MPEG
> [37769.189579] cx18-0: Could not find buf 68 for stream encoder MPEG
> [37985.181190] BUG: unable to handle kernel NULL pointer dereference
> at 0000000000000000
> [37985.181190] IP: [<ffffffffa01e2180>] :cx18:cx18_queue_move_buf+0x0/0xa0
> [37985.181190] PGD 214969067 PUD 214884067 PMD 0
> [37985.181190] Oops: 0000 [1] PREEMPT SMP
> [37985.181190] CPU 3
> [37985.181190] Modules linked in: binfmt_misc iptable_filter ip_tables
> x_tables xfs loop mxl5005s ipv6 s5h1409 tuner_simple tuner_types
> cs5345 tuner usbhid cx18 dvb_core hid compat_ioctl32 videodev
> v4l1_compat i2c_algo_bit cx2341x v4l2_common tveeprom psmouse i2c_core
> button ext3 jbd mbcache sd_mod ahci iTCO_wdt libata r8169 scsi_mod
> dock ehci_hcd uhci_hcd usbcore raid10 raid456 async_xor async_memcpy
> async_tx xor raid1 raid0 multipath linear md_mod dm_mirror dm_log
> dm_snapshot dm_mod thermal processor fan fuse
> [37985.181190] Pid: 493, comm: java Not tainted 2.6.26-server-sagetv #1
> [37985.181190] RIP: 0010:[<ffffffffa01e2180>]  [<ffffffffa01e2180>]
> :cx18:cx18_queue_move_buf+0x0/0xa0
> [37985.181190] RSP: 0018:ffff810197ec9e50  EFLAGS: 00010046
> [37985.181190] RAX: 00000000000e0000 RBX: 0000000000000000 RCX: 0000000000000001
> [37985.181190] RDX: ffff81021d0181f8 RSI: 0000000000000000 RDI: ffff81021d018188
> [37985.181190] RBP: ffff81021d0181f8 R08: 0000000000000000 R09: 000000000004c308
> [37985.181190] R10: 000000000004c307 R11: ffff810001025a70 R12: 0000000000000001
> [37985.181190] R13: 0000000000310000 R14: 0000000000000000 R15: ffff81021d018188
> [37985.181190] FS:  0000000000000000(0000) GS:ffff81021fc06980(0063)
> knlGS:00000000c74f2b90
> [37985.181190] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
> [37985.181190] CR2: 0000000000000000 CR3: 000000021405e000 CR4: 00000000000006a0
> [37985.181190] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [37985.181190] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [37985.181190] Process java (pid: 493, threadinfo ffff810197ec8000,
> task ffff8101fe97dfa0)
> [37985.181190] Stack:  ffffffffa01e22c2 ffff8100000e0000
> ffff81021d0181b0 0000000000000292
> [37985.181190]  000000011d0181f8 ffff8102000e0000 ffff81021d018188
> ffff81021d018000
> [37985.181190]  ffff81021d018188 ffff81021d018128 ffff81021fc92300
> 0000000000000000
> [37985.181190] Call Trace:
> [37985.181190]  [<ffffffffa01e22c2>] ? :cx18:cx18_queue_move+0xa2/0x160
> [37985.181190]  [<ffffffffa01e38d8>] ? :cx18:cx18_release_stream+0x78/0xc0
> [37985.181190]  [<ffffffffa01e3d76>] ? :cx18:cx18_v4l2_close+0xb6/0x150
> [37985.181190]  [<ffffffff802a88d1>] ? __fput+0xb1/0x1d0
> [37985.181190]  [<ffffffff802a5404>] ? filp_close+0x54/0x90
> [37985.181190]  [<ffffffff802a6c1f>] ? sys_close+0x9f/0x110
> [37985.181190]  [<ffffffff80226c02>] ? sysenter_do_call+0x1b/0x66
> [37985.181190]
> [37985.181190]
> [37985.181190] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
> 47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
> 1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
> 10 49
> [37985.181190] RIP  [<ffffffffa01e2180>] :cx18:cx18_queue_move_buf+0x0/0xa0
> [37985.181190]  RSP <ffff810197ec9e50>
> [37985.181190] CR2: 0000000000000000
> [37985.181190] ---[ end trace cbfa59d18c547596 ]---


--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

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

On Wed, Aug 6, 2008 at 8:55 PM, Andy Walls <awalls@radix.net> wrote:
> On Wed, 2008-08-06 at 06:57 -0400, Brandon Jenkins wrote:
>> On Tue, Aug 5, 2008 at 9:29 PM, Andy Walls <awalls@radix.net> wrote:
>> > On Tue, 2008-08-05 at 21:04 -0400, Brandon Jenkins wrote:
>> >> Hi All
>> >>
>> >> I am running kernel 2.6.26 on  Ubuntu 8.04. Any thoughts?
>> >
>> > I ran into a similar Oops in the same function on 23 July.  I had it at
>> > a lower priority since no one had complained about it and it seems rare.
>> >
>> > I'll try and get to it before Saturday morning.  If anyone wants to
>> > submit a patch before then, I'll review it ASAP after receipt.
>> >
>> > Regards,
>> > Andy
>> >
>> >> Thanks in advance
>> >>
>> >> Brandon
>> >>
>
>> >> [35037.080852] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
>> >> 47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
>> >> 1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
>> >> 10 49
>> >> [35037.080976] RIP  [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
>> >> [35037.080992]  RSP <ffff810217c4be50>
>> >> [35037.081000] CR2: 0000000000000000
>> >> [35037.081192] ---[ end trace 10100555b3a0d104 ]---
>> >> [35037.090147] note: java[15894] exited with preempt_count 1
>> >>
>> >> --
>> >> video4linux-list mailing list
>> >> Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
>> >> https://www.redhat.com/mailman/listinfo/video4linux-list
>> >>
>> >
>> >
>> Here's another one. Is there something I could do to lessen the issue
>> while a patch is being worked? Rebuild the kernel without preempting?
>
>
> Nope.  The problem I have has to do with per stream queue and buffer
> accounting being slightly but you'll only notice when it's being freed.
>
> I suspect you have the same problem, but I can't tell for sure as you
> system is compiling the code differently than mine.
>
> Could you please send the output of
>
> $ cd v4l-dvb
> $ objdump -D v4l/cx18-queue.o
>
> from the offending build to me.  That way I can see the assembled
> machine code and verify where in the function the NULL dereference is
> happening.
>
> If you have the exact same problem as me, I can give you a "band-aid"
> patch which will lessen the problem in short order.  It'll be a band aid
> because it won't fix the accounting problem though.  I need to do more
> extensive test and debug to find out where the accounting of buffers is
> getting screwed up.
>
> Regards,
> Andy
>
Andy,

Thanks for the continued help and contributions. Please see attached.

Brandon

[-- Attachment #2: cx18-queue.o.objdump.tar.gz --]
[-- Type: application/x-gzip, Size: 436591 bytes --]

[-- Attachment #3: Type: text/plain, Size: 164 bytes --]

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Wed, Aug 6, 2008 at 8:55 PM, Andy Walls <awalls@radix.net> wrote:
> On Wed, 2008-08-06 at 06:57 -0400, Brandon Jenkins wrote:
>> On Tue, Aug 5, 2008 at 9:29 PM, Andy Walls <awalls@radix.net> wrote:
>> > On Tue, 2008-08-05 at 21:04 -0400, Brandon Jenkins wrote:
>> >> Hi All
>> >>
>> >> I am running kernel 2.6.26 on  Ubuntu 8.04. Any thoughts?
>> >
>> > I ran into a similar Oops in the same function on 23 July.  I had it at
>> > a lower priority since no one had complained about it and it seems rare.
>> >
>> > I'll try and get to it before Saturday morning.  If anyone wants to
>> > submit a patch before then, I'll review it ASAP after receipt.
>> >
>> > Regards,
>> > Andy
>> >
>> >> Thanks in advance
>> >>
>> >> Brandon
>> >>
>
>> >> [35037.080852] Code: 74 22 31 c9 0f 1f 80 00 00 00 00 48 89 c8 48 03
>> >> 47 28 8b 10 0f ca 89 10 8d 41 04 48 83 c1 04 39 47 30 77 e7 f3 c3 0f
>> >> 1f 44 00 00 <4c> 8b 0e 49 89 d2 49 8b 41 08 49 8b 11 48 89 42 08 48 89
>> >> 10 49
>> >> [35037.080976] RIP  [<ffffffffa01e4180>] :cx18:cx18_queue_move_buf+0x0/0xa0
>> >> [35037.080992]  RSP <ffff810217c4be50>
>> >> [35037.081000] CR2: 0000000000000000
>> >> [35037.081192] ---[ end trace 10100555b3a0d104 ]---
>> >> [35037.090147] note: java[15894] exited with preempt_count 1
>> >>
>> >> --
>> >> video4linux-list mailing list
>> >> Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
>> >> https://www.redhat.com/mailman/listinfo/video4linux-list
>> >>
>> >
>> >
>> Here's another one. Is there something I could do to lessen the issue
>> while a patch is being worked? Rebuild the kernel without preempting?
>
>
> Nope.  The problem I have has to do with per stream queue and buffer
> accounting being slightly but you'll only notice when it's being freed.
>
> I suspect you have the same problem, but I can't tell for sure as you
> system is compiling the code differently than mine.
>
> Could you please send the output of
>
> $ cd v4l-dvb
> $ objdump -D v4l/cx18-queue.o
>
> from the offending build to me.  That way I can see the assembled
> machine code and verify where in the function the NULL dereference is
> happening.
>
> If you have the exact same problem as me, I can give you a "band-aid"
> patch which will lessen the problem in short order.  It'll be a band aid
> because it won't fix the accounting problem though.  I need to do more
> extensive test and debug to find out where the accounting of buffers is
> getting screwed up.
>
> Regards,
> Andy

Andy,

Reposting with the file hosted in my dropbox instead. I didn't realize
there was a size limit on the devel list.

Brandon

https://dl.getdropbox.com/u/4976/cx18-queue.o.objdump.tar.gz

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Thu, 2008-08-07 at 09:36 -0400, Brandon Jenkins wrote:
> On Wed, Aug 6, 2008 at 8:55 PM, Andy Walls <awalls@radix.net> wrote:
> > On Wed, 2008-08-06 at 06:57 -0400, Brandon Jenkins wrote:
> >> On Tue, Aug 5, 2008 at 9:29 PM, Andy Walls <awalls@radix.net> wrote:
> >> > On Tue, 2008-08-05 at 21:04 -0400, Brandon Jenkins wrote:

> >
> > Nope.  The problem I have has to do with per stream queue and buffer
> > accounting being slightly but you'll only notice when it's being freed.
> >
> > I suspect you have the same problem, but I can't tell for sure as you
> > system is compiling the code differently than mine.
> >
> > Could you please send the output of
> >
> > $ cd v4l-dvb
> > $ objdump -D v4l/cx18-queue.o
> >
> > from the offending build to me.  That way I can see the assembled
> > machine code and verify where in the function the NULL dereference is
> > happening.
> >
> > If you have the exact same problem as me, I can give you a "band-aid"
> > patch which will lessen the problem in short order.  It'll be a band aid
> > because it won't fix the accounting problem though.  I need to do more
> > extensive test and debug to find out where the accounting of buffers is
> > getting screwed up.
> >
> > Regards,
> > Andy
> 
> Andy,
> 
> Reposting with the file hosted in my dropbox instead. I didn't realize
> there was a size limit on the devel list.

Brandon,

I got the file anyway.  You have the exact same problem I had in the
oops.  Ubuntu's compilation options appear to be a little more
aggressive than Fedora's, but it's the same NULL pointer.

The problem is when moving all the buffers for a stream back to the
q_free queue, it appears the source queue claims to have more bytes to
move back to q_free than it actually does.  The old general purpose
code, copied from ivtv I think, then tries to steal buffers from another
queue to satisfy the request to move all the remaining bytes that the
first queue lied about having. But there is no queue to steal from, so
you deref a NULL pointer.

I'll have a quick fix sometime tomorrow.  It's been a long day and
experience tells me I'll only code up bugs tonight when I'm tired. :)

Regards,
Andy



> Brandon
> 
> https://dl.getdropbox.com/u/4976/cx18-queue.o.objdump.tar.gz
> 

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Thu, 2008-08-07 at 09:36 -0400, Brandon Jenkins wrote:
> On Wed, Aug 6, 2008 at 8:55 PM, Andy Walls <awalls@radix.net> wrote:

> > from the offending build to me.  That way I can see the assembled
> > machine code and verify where in the function the NULL dereference is
> > happening.
> >
> > If you have the exact same problem as me, I can give you a "band-aid"
> > patch which will lessen the problem in short order.  It'll be a band aid
> > because it won't fix the accounting problem though.  I need to do more
> > extensive test and debug to find out where the accounting of buffers is
> > getting screwed up.
> >
> > Regards,
> > Andy

Brandon,

I have checked in a fix to defend against the Ooops we both encountered.
The fix will also generate a WARN dump and some queue stats when it runs
across the cause, but will otherwise try to clean up as best it can to
allow further operation.

The band-aid fix is the latest change at 

http://linuxtv.org/hg/~awalls/v4l-dvb

Please provide the extra debug that happens if you encounter the warning
in your logs.  I have only encountered the problem twice over a several
month period, so its hard to get insight into the root cause buffer
accounting error at that rate.


Hans,

The provided patch is a bit ugly, so I'm not sure I want it to go to the
main repo as is.  Since the cx18_queue_move() and cx18_queue_move_buf()
functions are a bit general for how cx18 is using them (compared to
ivtv) and a bit confusing at first, I was going to rewrite them down to
the minimum needed for cx18.  Do you have any objection?

I normally like the fact that cx18 mirrors ivtv in many aspects as it
provides an certain economy for common bug fixes.  Here I think cx18 is
carrying complexity and unused code (and maybe bugs) for only that
reason.

Regards,
Andy

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Hans Verkuil]

On Friday 08 August 2008 16:18:28 Andy Walls wrote:
> On Thu, 2008-08-07 at 09:36 -0400, Brandon Jenkins wrote:
> > On Wed, Aug 6, 2008 at 8:55 PM, Andy Walls <awalls@radix.net> wrote:
> > > from the offending build to me.  That way I can see the assembled
> > > machine code and verify where in the function the NULL
> > > dereference is happening.
> > >
> > > If you have the exact same problem as me, I can give you a
> > > "band-aid" patch which will lessen the problem in short order. 
> > > It'll be a band aid because it won't fix the accounting problem
> > > though.  I need to do more extensive test and debug to find out
> > > where the accounting of buffers is getting screwed up.
> > >
> > > Regards,
> > > Andy
>
> Brandon,
>
> I have checked in a fix to defend against the Ooops we both
> encountered. The fix will also generate a WARN dump and some queue
> stats when it runs across the cause, but will otherwise try to clean
> up as best it can to allow further operation.
>
> The band-aid fix is the latest change at
>
> http://linuxtv.org/hg/~awalls/v4l-dvb
>
> Please provide the extra debug that happens if you encounter the
> warning in your logs.  I have only encountered the problem twice over
> a several month period, so its hard to get insight into the root
> cause buffer accounting error at that rate.
>
>
> Hans,
>
> The provided patch is a bit ugly, so I'm not sure I want it to go to
> the main repo as is.  Since the cx18_queue_move() and
> cx18_queue_move_buf() functions are a bit general for how cx18 is
> using them (compared to ivtv) and a bit confusing at first, I was
> going to rewrite them down to the minimum needed for cx18.  Do you
> have any objection?

No objection at all. If you look at where cx18_queue_move is used, then 
you'll notice that it is only in cx18_flush_queues(). And all it has to 
do there is to move any buffers in the q_io or q_full queue to the 
q_free queue and initialize all those buffers to their initial state. 
You do not need all that complicated code for that. I suggest that you 
make a new function instead that replaces cx18_queue_move and 
cx18_queue_move_buf.

> I normally like the fact that cx18 mirrors ivtv in many aspects as it
> provides an certain economy for common bug fixes.  Here I think cx18
> is carrying complexity and unused code (and maybe bugs) for only that
> reason.

Definitely. These two functions should be replaced for the cx18.

Regards,

	Hans

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Fri, 2008-08-08 at 16:35 +0200, Hans Verkuil wrote:
> On Friday 08 August 2008 16:18:28 Andy Walls wrote:

> No objection at all. If you look at where cx18_queue_move is used, then 
> you'll notice that it is only in cx18_flush_queues(). And all it has to 
> do there is to move any buffers in the q_io or q_full queue to the 
> q_free queue and initialize all those buffers to their initial state. 
> You do not need all that complicated code for that. I suggest that you 
> make a new function instead that replaces cx18_queue_move and 
> cx18_queue_move_buf.

:)

I was especially annoyed at the local var that was named 'from_free' but
that was also used being for transfers *to* q_free, which happened to be
cx18's only use case for the variable.,,,

Regards,
Andy


> Regards,
> 
> 	Hans
> 

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
> On Thu, 2008-08-07 at 09:36 -0400, Brandon Jenkins wrote:
>> On Wed, Aug 6, 2008 at 8:55 PM, Andy Walls <awalls@radix.net> wrote:
>
>> > from the offending build to me.  That way I can see the assembled
>> > machine code and verify where in the function the NULL dereference is
>> > happening.
>> >
>> > If you have the exact same problem as me, I can give you a "band-aid"
>> > patch which will lessen the problem in short order.  It'll be a band aid
>> > because it won't fix the accounting problem though.  I need to do more
>> > extensive test and debug to find out where the accounting of buffers is
>> > getting screwed up.
>> >
>> > Regards,
>> > Andy
>
> Brandon,
>
> I have checked in a fix to defend against the Ooops we both encountered.
> The fix will also generate a WARN dump and some queue stats when it runs
> across the cause, but will otherwise try to clean up as best it can to
> allow further operation.
>
> The band-aid fix is the latest change at
>
> http://linuxtv.org/hg/~awalls/v4l-dvb
>
> Please provide the extra debug that happens if you encounter the warning
> in your logs.  I have only encountered the problem twice over a several
> month period, so its hard to get insight into the root cause buffer
> accounting error at that rate.
>
>
> Hans,
>
> The provided patch is a bit ugly, so I'm not sure I want it to go to the
> main repo as is.  Since the cx18_queue_move() and cx18_queue_move_buf()
> functions are a bit general for how cx18 is using them (compared to
> ivtv) and a bit confusing at first, I was going to rewrite them down to
> the minimum needed for cx18.  Do you have any objection?
>
> I normally like the fact that cx18 mirrors ivtv in many aspects as it
> provides an certain economy for common bug fixes.  Here I think cx18 is
> carrying complexity and unused code (and maybe bugs) for only that
> reason.
>
> Regards,
> Andy
>
>

Andy,

I have not experienced a recurrence yet, but  a friend has. We're both
users of SageTV, I asked him for info on reproducing the error to see
if I can make it trip as well.

Thanks for the help.

Brandon

PS - You'll note he's testing the HDPVR device as am I. Janne
performed a tree merge 3 days ago so it is fairly fresh.

He sent me the following output:

[18101.988000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[18101.988000]  [<f0abe656>] cx18_queue_move+0x246/0x250 [cx18]
[18101.988000]  [<f0abe69c>] cx18_flush_queues+0x3c/0x50 [cx18]
[18101.988000]  [<f0abfb17>] cx18_release_stream+0x77/0xc0 [cx18]
[18101.988000]  [<f0abff5c>] cx18_v4l2_close+0x9c/0x130 [cx18]
[18101.988000]  [<c01816bd>] __fput+0xad/0x1a0
[18101.988000]  [<c017ea97>] filp_close+0x47/0x80
[18101.988000]  [<c017febb>] sys_close+0x6b/0xd0
[18101.988000]  [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[18101.988000]  =======================
[18101.988000] cx18-1: queue_move: driver bug! errant steal attempt
for to/from_free queue move, dumping queue stats
[18101.988000] cx18-1: queue_move: thought bytes_available = 32768
with needed = 32768 and initial destination size = 2031616
[18101.988000] cx18-1: queue_log: stream 'encoder MPEG'  buffers = 63
buf_size = 32768  buffers_stolen = 0
[18101.988000] cx18-1: queue_log: &q_free = ea9e819c  &q_full =
ea9e81b0 &q_io = ea9e81c4
[18101.988000] cx18-1: queue_log: q = ea9e81b0   buffers = 1  length =
32768 bytesused = 2048
[18101.988000] cx18-1: queue_log: stream 'encoder MPEG'  buffers = 63
buf_size = 32768  buffers_stolen = 0
[18101.988000] cx18-1: queue_log: &q_free = ea9e819c  &q_full =
ea9e81b0 &q_io = ea9e81c4
[18101.988000] cx18-1: queue_log: q = ea9e819c   buffers = 62  length
= 2031616  bytesused = 0
[18101.988000] cx18-1: queue_log: i = 0  buf->id = 53  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 1  buf->id = 54  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 2  buf->id = 55  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 3  buf->id = 56  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 4  buf->id = 57  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 5  buf->id = 58  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 6  buf->id = 59  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 7  buf->id = 60  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 8  buf->id = 61  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 9  buf->id = 62  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 10  buf->id = 0  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 11  buf->id = 1  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 12  buf->id = 2  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 13  buf->id = 3  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 14  buf->id = 4  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 15  buf->id = 5  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 16  buf->id = 6  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 17  buf->id = 7  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 18  buf->id = 8  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 19  buf->id = 9  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 20  buf->id = 10  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 21  buf->id = 11  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 22  buf->id = 12  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 23  buf->id = 13  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 24  buf->id = 14  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 25  buf->id = 15  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 26  buf->id = 16  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 27  buf->id = 17  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 28  buf->id = 18  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 29  buf->id = 20  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 30  buf->id = 21  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 31  buf->id = 22  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 32  buf->id = 23  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 33  buf->id = 24  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 34  buf->id = 25  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 35  buf->id = 26  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 36  buf->id = 27  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 37  buf->id = 28  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 38  buf->id = 29  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 39  buf->id = 30  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 40  buf->id = 31  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 41  buf->id = 32  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 42  buf->id = 33  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 43  buf->id = 34  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 44  buf->id = 35  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 45  buf->id = 36  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 46  buf->id = 37  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 47  buf->id = 38  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 48  buf->id = 39  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 49  buf->id = 40  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 50  buf->id = 41  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 51  buf->id = 42  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 52  buf->id = 43  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 53  buf->id = 44  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 54  buf->id = 45  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 55  buf->id = 46  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 56  buf->id = 47  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 57  buf->id = 48  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 58  buf->id = 49  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 59  buf->id = 50  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 60  buf->id = 51  buf->bytesused
= 0 buf->readpos = 0
[18101.988000] cx18-1: queue_log: i = 61  buf->id = 52  buf->bytesused
= 0 buf->readpos = 0

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
> Brandon,
>
> I have checked in a fix to defend against the Ooops we both encountered.
> The fix will also generate a WARN dump and some queue stats when it runs
> across the cause, but will otherwise try to clean up as best it can to
> allow further operation.
>
> The band-aid fix is the latest change at
>
> http://linuxtv.org/hg/~awalls/v4l-dvb
>
> Please provide the extra debug that happens if you encounter the warning
> in your logs.  I have only encountered the problem twice over a several
> month period, so its hard to get insight into the root cause buffer
> accounting error at that rate.

Andy,

I had an oops today, first one in a few days

Brandon

[35446.681402] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move+0x207/0x220 [cx18]()
[35446.681402] Modules linked in: nls_cp437 cifs binfmt_misc
iptable_filter ip_tables x_tables xfs loop mxl5005s s5h1409
tuner_simple tuner_types ipv6 cs5345 tuner cx18 dvb_core
compat_ioctl32 usbhid videodev v4l1_compat hid i2c_algo_bit cx2341x
v4l2_common tveeprom psmouse i2c_core button ext3 jbd mbcache sd_mod
ahci iTCO_wdt libata r8169 scsi_mod dock ehci_hcd uhci_hcd usbcore
raid10 raid456 async_xor async_memcpy async_tx xor raid1 raid0
multipath linear md_mod dm_mirror dm_log dm_snapshot dm_mod thermal
processor fan fuse [last unloaded: hdpvr]
[35446.681402] Pid: 14030, comm: java Not tainted 2.6.26-server-sagetv #1
[35446.681402]
[35446.681402] Call Trace:
[35446.681402]  [<ffffffff80238c24>] warn_on_slowpath+0x64/0xa0
[35446.681402]  [<ffffffffa01efd47>] :cx18:cx18_vapi+0xa7/0x110
[35446.681402]  [<ffffffff8044901f>] _spin_lock_irqsave+0x1f/0x50
[35446.681402]  [<ffffffff804493f2>] _spin_unlock_irqrestore+0x12/0x40
[35446.681402]  [<ffffffff8044901f>] _spin_lock_irqsave+0x1f/0x50
[35446.681402]  [<ffffffffa01eb617>] :cx18:cx18_queue_move+0x207/0x220
[35446.681402]  [<ffffffffa01eca58>] :cx18:cx18_release_stream+0x78/0xc0
[35446.681402]  [<ffffffffa01ecef6>] :cx18:cx18_v4l2_close+0xb6/0x150
[35446.681402]  [<ffffffff802a88d1>] __fput+0xb1/0x1d0
[35446.681402]  [<ffffffff802a5404>] filp_close+0x54/0x90
[35446.681402]  [<ffffffff802a6c1f>] sys_close+0x9f/0x110
[35446.681402]  [<ffffffff80226c02>] sysenter_do_call+0x1b/0x66
[35446.681402]
[35446.681402] ---[ end trace 5fa5ceee62929416 ]---
[35446.681402] cx18-2: queue_move: driver bug! errant steal attempt
for to/from_free queue move, dumping queue stats
[35446.681402] cx18-2: queue_move: thought bytes_available = 196608
with needed = 196608 and initial destination size = 3866624
[35446.681402] cx18-2: queue_log: stream 'encoder MPEG'  buffers = 63
buf_size = 65536  buffers_stolen = 0
[35446.681402] cx18-2: queue_log: &q_free = ffff81021d7901f8  &q_full
= ffff81021d790218  &q_io = ffff81021d790238
[35446.681402] cx18-2: queue_log: q = ffff81021d790218   buffers = 1
length = 65536  bytesused = 43008
[35446.681402] cx18-2: queue_log: stream 'encoder MPEG'  buffers = 63
buf_size = 65536  buffers_stolen = 0
[35446.681402] cx18-2: queue_log: &q_free = ffff81021d7901f8  &q_full
= ffff81021d790218  &q_io = ffff81021d790238
[35446.681402] cx18-2: queue_log: q = ffff81021d7901f8   buffers = 62
length = 3997696  bytesused = 0
[35446.681402] cx18-2: queue_log: i = 0  buf->id = 39  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 1  buf->id = 40  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 2  buf->id = 41  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 3  buf->id = 42  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 4  buf->id = 43  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 5  buf->id = 44  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 6  buf->id = 45  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 7  buf->id = 46  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 8  buf->id = 47  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 9  buf->id = 48  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 10  buf->id = 49  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 11  buf->id = 50  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 12  buf->id = 51  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 13  buf->id = 52  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 14  buf->id = 53  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 15  buf->id = 54  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 16  buf->id = 55  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 17  buf->id = 56  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 18  buf->id = 57  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 19  buf->id = 58  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 20  buf->id = 59  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 21  buf->id = 60  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 22  buf->id = 61  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 23  buf->id = 62  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 24  buf->id = 0  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 25  buf->id = 1  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 26  buf->id = 2  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 27  buf->id = 3  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 28  buf->id = 4  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 29  buf->id = 5  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 30  buf->id = 6  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 31  buf->id = 7  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 32  buf->id = 8  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 33  buf->id = 9  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 34  buf->id = 10  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 35  buf->id = 11  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 36  buf->id = 12  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 37  buf->id = 13  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 38  buf->id = 14  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 39  buf->id = 15  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 40  buf->id = 16  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 41  buf->id = 17  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 42  buf->id = 18  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 43  buf->id = 19  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 44  buf->id = 20  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 45  buf->id = 21  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 46  buf->id = 22  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 47  buf->id = 23  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 48  buf->id = 24  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 49  buf->id = 25  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 50  buf->id = 26  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 51  buf->id = 27  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 52  buf->id = 28  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 53  buf->id = 29  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 54  buf->id = 30  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 55  buf->id = 32  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 56  buf->id = 33  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 57  buf->id = 34  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 58  buf->id = 35  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 59  buf->id = 36  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 60  buf->id = 37  buf->bytesused
= 0  buf->readpos = 0
[35446.681402] cx18-2: queue_log: i = 61  buf->id = 38  buf->bytesused
= 0  buf->readpos = 0

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
> > Brandon,
> >
> > I have checked in a fix to defend against the Ooops we both encountered.
> > The fix will also generate a WARN dump and some queue stats when it runs
> > across the cause, but will otherwise try to clean up as best it can to
> > allow further operation.
> >
> > The band-aid fix is the latest change at
> >
> > http://linuxtv.org/hg/~awalls/v4l-dvb
> >
> > Please provide the extra debug that happens if you encounter the warning
> > in your logs.  I have only encountered the problem twice over a several
> > month period, so its hard to get insight into the root cause buffer
> > accounting error at that rate.
> 
> Andy,
> 
> I had an oops today, first one in a few days
> 
> Brandon

Brandon & Jeff,

I have updated my repo at 

http://linuxtv.org/hg/~awalls/v4l-dvb

with 3 changes:

1. Back out the original band aid fix
2. Simplify the queue flush routines (you will not see that oops again)
3. Fix the interrupt handler to obtain a queue lock (prevents queue
corruption)

>From most of the output you provided, it was pretty obvious that q_full
was always claiming to have more buffers that it actually did.  I
hypothesized this could come about at the end of a capture when the
encoder hadn't really stopped transferring buffers yet (after we told it
to stop) and then we try to clear q_full while the interrupt handler is
still trying to add buffers.  This could happen because the interrupt
handler never (ever) properly obtained a lock for manipulating the
queues.  This could have been causing the queue corruption.

Please test.  I need feedback that I haven't introduced a deadlock.

It also appears that the last change requiring the interrupt handler to
obtain a lock, completely mitigates me having to use the "-cache 8192"
option to mplayer for digital captures, and greatly reduces the amount
of cache I need to have mplayer use for analog captures. 


Hans,
(or anyone else with expertise in using spinlocks withing an interrupt
handler),

Could you please provide comments on if I'm doing something wrong with
the way I obtain the spinlock in the interrupt handler?

http://linuxtv.org/hg/~awalls/v4l-dvb/rev/f3ada35200c0

>From reading Bovet and Cesati's _Understanding_the_Linux_Kernel_ and
Corbet, Rubini, and Kroah-Hartman's _Linux_Device_Drivers_ I think I've
got it right.

When the stream queues (q_full, q_io, and q_free) are accessed from the
system call exception handler, I need to do a spin_lock_irqsave() to
disable local CPU interrupts and protect access to the queues by kernel
control paths on other CPU's.  When they stream queues are accessed by
the interrupt handler on any CPU, the interrupt handler is serialized
with respect to itself and need not disable any interrupts and simply
obtain the lock via spin_lock() to protect against access from system
call exceptions.


Regards,
Andy


> [35446.681402] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
> cx18_queue_move+0x207/0x220 [cx18]()
> [35446.681402] Modules linked in: nls_cp437 cifs binfmt_misc
> iptable_filter ip_tables x_tables xfs loop mxl5005s s5h1409
> tuner_simple tuner_types ipv6 cs5345 tuner cx18 dvb_core
> compat_ioctl32 usbhid videodev v4l1_compat hid i2c_algo_bit cx2341x
> v4l2_common tveeprom psmouse i2c_core button ext3 jbd mbcache sd_mod
> ahci iTCO_wdt libata r8169 scsi_mod dock ehci_hcd uhci_hcd usbcore
> raid10 raid456 async_xor async_memcpy async_tx xor raid1 raid0
> multipath linear md_mod dm_mirror dm_log dm_snapshot dm_mod thermal
> processor fan fuse [last unloaded: hdpvr]
> [35446.681402] Pid: 14030, comm: java Not tainted 2.6.26-server-sagetv #1
> [35446.681402]
> [35446.681402] Call Trace:
> [35446.681402]  [<ffffffff80238c24>] warn_on_slowpath+0x64/0xa0
> [35446.681402]  [<ffffffffa01efd47>] :cx18:cx18_vapi+0xa7/0x110
> [35446.681402]  [<ffffffff8044901f>] _spin_lock_irqsave+0x1f/0x50
> [35446.681402]  [<ffffffff804493f2>] _spin_unlock_irqrestore+0x12/0x40
> [35446.681402]  [<ffffffff8044901f>] _spin_lock_irqsave+0x1f/0x50
> [35446.681402]  [<ffffffffa01eb617>] :cx18:cx18_queue_move+0x207/0x220
> [35446.681402]  [<ffffffffa01eca58>] :cx18:cx18_release_stream+0x78/0xc0
> [35446.681402]  [<ffffffffa01ecef6>] :cx18:cx18_v4l2_close+0xb6/0x150
> [35446.681402]  [<ffffffff802a88d1>] __fput+0xb1/0x1d0
> [35446.681402]  [<ffffffff802a5404>] filp_close+0x54/0x90
> [35446.681402]  [<ffffffff802a6c1f>] sys_close+0x9f/0x110
> [35446.681402]  [<ffffffff80226c02>] sysenter_do_call+0x1b/0x66
> [35446.681402]
> [35446.681402] ---[ end trace 5fa5ceee62929416 ]---
> [35446.681402] cx18-2: queue_move: driver bug! errant steal attempt
> for to/from_free queue move, dumping queue stats
> [35446.681402] cx18-2: queue_move: thought bytes_available = 196608
> with needed = 196608 and initial destination size = 3866624
> [35446.681402] cx18-2: queue_log: stream 'encoder MPEG'  buffers = 63
> buf_size = 65536  buffers_stolen = 0
> [35446.681402] cx18-2: queue_log: &q_free = ffff81021d7901f8  &q_full
> = ffff81021d790218  &q_io = ffff81021d790238
> [35446.681402] cx18-2: queue_log: q = ffff81021d790218   buffers = 1
> length = 65536  bytesused = 43008
> [35446.681402] cx18-2: queue_log: stream 'encoder MPEG'  buffers = 63
> buf_size = 65536  buffers_stolen = 0
> [35446.681402] cx18-2: queue_log: &q_free = ffff81021d7901f8  &q_full
> = ffff81021d790218  &q_io = ffff81021d790238
> [35446.681402] cx18-2: queue_log: q = ffff81021d7901f8   buffers = 62
> length = 3997696  bytesused = 0
> [35446.681402] cx18-2: queue_log: i = 0  buf->id = 39  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 1  buf->id = 40  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 2  buf->id = 41  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 3  buf->id = 42  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 4  buf->id = 43  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 5  buf->id = 44  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 6  buf->id = 45  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 7  buf->id = 46  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 8  buf->id = 47  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 9  buf->id = 48  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 10  buf->id = 49  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 11  buf->id = 50  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 12  buf->id = 51  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 13  buf->id = 52  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 14  buf->id = 53  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 15  buf->id = 54  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 16  buf->id = 55  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 17  buf->id = 56  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 18  buf->id = 57  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 19  buf->id = 58  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 20  buf->id = 59  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 21  buf->id = 60  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 22  buf->id = 61  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 23  buf->id = 62  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 24  buf->id = 0  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 25  buf->id = 1  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 26  buf->id = 2  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 27  buf->id = 3  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 28  buf->id = 4  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 29  buf->id = 5  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 30  buf->id = 6  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 31  buf->id = 7  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 32  buf->id = 8  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 33  buf->id = 9  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 34  buf->id = 10  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 35  buf->id = 11  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 36  buf->id = 12  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 37  buf->id = 13  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 38  buf->id = 14  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 39  buf->id = 15  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 40  buf->id = 16  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 41  buf->id = 17  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 42  buf->id = 18  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 43  buf->id = 19  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 44  buf->id = 20  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 45  buf->id = 21  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 46  buf->id = 22  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 47  buf->id = 23  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 48  buf->id = 24  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 49  buf->id = 25  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 50  buf->id = 26  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 51  buf->id = 27  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 52  buf->id = 28  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 53  buf->id = 29  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 54  buf->id = 30  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 55  buf->id = 32  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 56  buf->id = 33  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 57  buf->id = 34  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 58  buf->id = 35  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 59  buf->id = 36  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 60  buf->id = 37  buf->bytesused
> = 0  buf->readpos = 0
> [35446.681402] cx18-2: queue_log: i = 61  buf->id = 38  buf->bytesused
> = 0  buf->readpos = 0
> 
> --
> video4linux-list mailing list
> Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
> https://www.redhat.com/mailman/listinfo/video4linux-list
> 

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Hans Verkuil]

On Sunday 17 August 2008 04:13:24 Andy Walls wrote:
> On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> > On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> 
wrote:
> > > Brandon,
> > >
> > > I have checked in a fix to defend against the Ooops we both
> > > encountered. The fix will also generate a WARN dump and some
> > > queue stats when it runs across the cause, but will otherwise try
> > > to clean up as best it can to allow further operation.
> > >
> > > The band-aid fix is the latest change at
> > >
> > > http://linuxtv.org/hg/~awalls/v4l-dvb
> > >
> > > Please provide the extra debug that happens if you encounter the
> > > warning in your logs.  I have only encountered the problem twice
> > > over a several month period, so its hard to get insight into the
> > > root cause buffer accounting error at that rate.
> >
> > Andy,
> >
> > I had an oops today, first one in a few days
> >
> > Brandon
>
> Brandon & Jeff,
>
> I have updated my repo at
>
> http://linuxtv.org/hg/~awalls/v4l-dvb
>
> with 3 changes:
>
> 1. Back out the original band aid fix
> 2. Simplify the queue flush routines (you will not see that oops
> again)

Nice! Cleans it up considerably.

> 3. Fix the interrupt handler to obtain a queue lock (prevents 
> queue corruption)

No, that is not the bug. I'm pretty sure that the real bug is that the 
old cx18_queue_move() function didn't use a spin_lock_irqsave(). I 
think that it was possible for an interrupt to arrive when the CPU was 
in the middle of a cx18_queue_move(). A spinlock in an interrupt 
handler is usually bogus (and that includes the one in the ivtv irq 
handler, I've just realized).

What I am uneasy about, though, is why an interrupt could arrive while 
in the cx18_queue_move() function. In principle this function should 
only be called when the capture has stopped. I think it might be a good 
idea to debug this: is it possible for interrupts to arrive after the 
capture was stopped? Or is it possible for cx18_queue_move() to be 
called when a capture is still in progress?

I do think it is a good idea to rename cx18_queue_find_buf to 
cx18_queue_get_buf_irq to denote that it 1) not just finds a buffer but 
also removes it from the queue, and 2) it can only be called safely 
from interrupt context.

> >From most of the output you provided, it was pretty obvious that
> > q_full
>
> was always claiming to have more buffers that it actually did.  I
> hypothesized this could come about at the end of a capture when the
> encoder hadn't really stopped transferring buffers yet (after we told
> it to stop) and then we try to clear q_full while the interrupt
> handler is still trying to add buffers.  This could happen because
> the interrupt handler never (ever) properly obtained a lock for
> manipulating the queues.  This could have been causing the queue
> corruption.
>
> Please test.  I need feedback that I haven't introduced a deadlock.
>
> It also appears that the last change requiring the interrupt handler
> to obtain a lock, completely mitigates me having to use the "-cache
> 8192" option to mplayer for digital captures, and greatly reduces the
> amount of cache I need to have mplayer use for analog captures.

I suspect that it is the change before that one: adding a spinlock to 
cx18_queue_move(). The spinlock in the interrupt handler doesn't do 
anything. It would only be useful if you could have two independent 
interrupt handlers that both needed access to that resource. But that 
is not the case here.

>
>
> Hans,
> (or anyone else with expertise in using spinlocks withing an
> interrupt handler),
>
> Could you please provide comments on if I'm doing something wrong
> with the way I obtain the spinlock in the interrupt handler?

See above :-)

>
> http://linuxtv.org/hg/~awalls/v4l-dvb/rev/f3ada35200c0
>
> >From reading Bovet and Cesati's _Understanding_the_Linux_Kernel_ and
>
> Corbet, Rubini, and Kroah-Hartman's _Linux_Device_Drivers_ I think
> I've got it right.
>
> When the stream queues (q_full, q_io, and q_free) are accessed from
> the system call exception handler, I need to do a spin_lock_irqsave()
> to disable local CPU interrupts and protect access to the queues by
> kernel control paths on other CPU's.  When they stream queues are
> accessed by the interrupt handler on any CPU, the interrupt handler
> is serialized with respect to itself and need not disable any
> interrupts and simply obtain the lock via spin_lock() to protect
> against access from system call exceptions.

System call exceptions? Not sure what you mean. AFAIK the interrupt 
handler doesn't have to protect against anything.

Regards,

	Hans

>
>
> Regards,
> Andy
>
> > [35446.681402] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
> > cx18_queue_move+0x207/0x220 [cx18]()
> > [35446.681402] Modules linked in: nls_cp437 cifs binfmt_misc
> > iptable_filter ip_tables x_tables xfs loop mxl5005s s5h1409
> > tuner_simple tuner_types ipv6 cs5345 tuner cx18 dvb_core
> > compat_ioctl32 usbhid videodev v4l1_compat hid i2c_algo_bit cx2341x
> > v4l2_common tveeprom psmouse i2c_core button ext3 jbd mbcache
> > sd_mod ahci iTCO_wdt libata r8169 scsi_mod dock ehci_hcd uhci_hcd
> > usbcore raid10 raid456 async_xor async_memcpy async_tx xor raid1
> > raid0 multipath linear md_mod dm_mirror dm_log dm_snapshot dm_mod
> > thermal processor fan fuse [last unloaded: hdpvr]
> > [35446.681402] Pid: 14030, comm: java Not tainted
> > 2.6.26-server-sagetv #1 [35446.681402]
> > [35446.681402] Call Trace:
> > [35446.681402]  [<ffffffff80238c24>] warn_on_slowpath+0x64/0xa0
> > [35446.681402]  [<ffffffffa01efd47>] :cx18:cx18_vapi+0xa7/0x110
> > [35446.681402]  [<ffffffff8044901f>] _spin_lock_irqsave+0x1f/0x50
> > [35446.681402]  [<ffffffff804493f2>]
> > _spin_unlock_irqrestore+0x12/0x40 [35446.681402] 
> > [<ffffffff8044901f>] _spin_lock_irqsave+0x1f/0x50 [35446.681402] 
> > [<ffffffffa01eb617>] :cx18:cx18_queue_move+0x207/0x220
> > [35446.681402]  [<ffffffffa01eca58>]
> > :cx18:cx18_release_stream+0x78/0xc0 [35446.681402] 
> > [<ffffffffa01ecef6>] :cx18:cx18_v4l2_close+0xb6/0x150
> > [35446.681402]  [<ffffffff802a88d1>] __fput+0xb1/0x1d0
> > [35446.681402]  [<ffffffff802a5404>] filp_close+0x54/0x90
> > [35446.681402]  [<ffffffff802a6c1f>] sys_close+0x9f/0x110
> > [35446.681402]  [<ffffffff80226c02>] sysenter_do_call+0x1b/0x66
> > [35446.681402]
> > [35446.681402] ---[ end trace 5fa5ceee62929416 ]---
> > [35446.681402] cx18-2: queue_move: driver bug! errant steal attempt
> > for to/from_free queue move, dumping queue stats
> > [35446.681402] cx18-2: queue_move: thought bytes_available = 196608
> > with needed = 196608 and initial destination size = 3866624
> > [35446.681402] cx18-2: queue_log: stream 'encoder MPEG'  buffers =
> > 63 buf_size = 65536  buffers_stolen = 0
> > [35446.681402] cx18-2: queue_log: &q_free = ffff81021d7901f8 
> > &q_full = ffff81021d790218  &q_io = ffff81021d790238
> > [35446.681402] cx18-2: queue_log: q = ffff81021d790218   buffers =
> > 1 length = 65536  bytesused = 43008
> > [35446.681402] cx18-2: queue_log: stream 'encoder MPEG'  buffers =
> > 63 buf_size = 65536  buffers_stolen = 0
> > [35446.681402] cx18-2: queue_log: &q_free = ffff81021d7901f8 
> > &q_full = ffff81021d790218  &q_io = ffff81021d790238
> > [35446.681402] cx18-2: queue_log: q = ffff81021d7901f8   buffers =
> > 62 length = 3997696  bytesused = 0
> > [35446.681402] cx18-2: queue_log: i = 0  buf->id = 39 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 1  buf->id = 40 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 2  buf->id = 41 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 3  buf->id = 42 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 4  buf->id = 43 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 5  buf->id = 44 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 6  buf->id = 45 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 7  buf->id = 46 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 8  buf->id = 47 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 9  buf->id = 48 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 10  buf->id = 49 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 11  buf->id = 50 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 12  buf->id = 51 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 13  buf->id = 52 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 14  buf->id = 53 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 15  buf->id = 54 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 16  buf->id = 55 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 17  buf->id = 56 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 18  buf->id = 57 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 19  buf->id = 58 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 20  buf->id = 59 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 21  buf->id = 60 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 22  buf->id = 61 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 23  buf->id = 62 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 24  buf->id = 0 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 25  buf->id = 1 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 26  buf->id = 2 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 27  buf->id = 3 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 28  buf->id = 4 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 29  buf->id = 5 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 30  buf->id = 6 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 31  buf->id = 7 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 32  buf->id = 8 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 33  buf->id = 9 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 34  buf->id = 10 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 35  buf->id = 11 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 36  buf->id = 12 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 37  buf->id = 13 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 38  buf->id = 14 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 39  buf->id = 15 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 40  buf->id = 16 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 41  buf->id = 17 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 42  buf->id = 18 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 43  buf->id = 19 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 44  buf->id = 20 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 45  buf->id = 21 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 46  buf->id = 22 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 47  buf->id = 23 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 48  buf->id = 24 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 49  buf->id = 25 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 50  buf->id = 26 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 51  buf->id = 27 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 52  buf->id = 28 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 53  buf->id = 29 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 54  buf->id = 30 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 55  buf->id = 32 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 56  buf->id = 33 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 57  buf->id = 34 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 58  buf->id = 35 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 59  buf->id = 36 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 60  buf->id = 37 
> > buf->bytesused = 0  buf->readpos = 0
> > [35446.681402] cx18-2: queue_log: i = 61  buf->id = 38 
> > buf->bytesused = 0  buf->readpos = 0
> >
> > --
> > video4linux-list mailing list
> > Unsubscribe
> > mailto:video4linux-list-request@redhat.com?subject=unsubscribe
> > https://www.redhat.com/mailman/listinfo/video4linux-list


--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Sun, 2008-08-17 at 11:41 +0200, Hans Verkuil wrote:
> On Sunday 17 August 2008 04:13:24 Andy Walls wrote:
> > On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> > > On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> 
> wrote:

> > I have updated my repo at
> >
> > http://linuxtv.org/hg/~awalls/v4l-dvb
> >
> > with 3 changes:
> >
> > 1. Back out the original band aid fix
> > 2. Simplify the queue flush routines (you will not see that oops
> > again)
> 
> Nice! Cleans it up considerably.

:)

> > 3. Fix the interrupt handler to obtain a queue lock (prevents 
> > queue corruption)
> 
> No, that is not the bug.

Yeah, it is not *the* bug I was after, but pending further discussion
below I'll maintain it is a bug.


I really want to do a full audit of all the queue manipulations in the
driver.  I'll try to find some time when I'm offline this week.

(Thanks for all the comments BTW!)

> I'm pretty sure that the real bug is that the 
> old cx18_queue_move() function didn't use a spin_lock_irqsave(). I 
> think that it was possible for an interrupt to arrive when the CPU was 
> in the middle of a cx18_queue_move().

On the surface it did look OK since all the interrupts for that stream
*should* have been stopped.  But after some hypothetical thought about
how the encoder might not stop right away and looking at Jeff's logs
where a new capture may have been started before the queue flush was
done, it's safer just to have the queue flush routine to acquire the
lock.  Since the queue flush routine in question is called very
infrequently, there's not much of a time penalty.


>  A spinlock in an interrupt 
> handler is usually bogus (and that includes the one in the ivtv irq 
> handler, I've just realized).

Chapter 5 of _Understanding_the_Linux_Kernel_ (2nd edition) on page 185
& 188 mentions that to protect data structures, being accessed by both
exceptions (like open/close/read/write/poll induced INT 0x80 exceptions
on Intel) and interrupt handlers on a MP system, a spinlock needs to be
used.  The book also mentions that a semaphore (now a mutex) is
sometimes preferable in this case, where the interrupt routine polls the
semaphore in a tight loop like a spinlock, but the system calls use the
semaphore normally and are allowed to sleep.




> What I am uneasy about, though, is why an interrupt could arrive while 
> in the cx18_queue_move() function. In principle this function should 
> only be called when the capture has stopped. I think it might be a good 
> idea to debug this: is it possible for interrupts to arrive after the 
> capture was stopped? Or is it possible for cx18_queue_move() to be 
> called when a capture is still in progress?

Right.  I should really test to see if this actually happens.  Since
spinlocks are supposedly optimized for the case of the lock being
available and the cx18_queue_move() is called infrequently, leaving it
in for now, should be OK.  

I also have difficulty reproducing the original oops, so my test results
could be misleading.  I have no good criteria for terminating the
experiment/testing and declaring "interrupts can't happen when we decide
to flush queues".



> I do think it is a good idea to rename cx18_queue_find_buf to 
> cx18_queue_get_buf_irq to denote that it 1) not just finds a buffer but 
> also removes it from the queue, and 2) it can only be called safely 
> from interrupt context.

Agree.  I'll make that part of the final change.



> > >From most of the output you provided, it was pretty obvious that
> > > q_full
> >
> > was always claiming to have more buffers that it actually did.  I
> > hypothesized this could come about at the end of a capture when the
> > encoder hadn't really stopped transferring buffers yet (after we told
> > it to stop) and then we try to clear q_full while the interrupt
> > handler is still trying to add buffers.  This could happen because
> > the interrupt handler never (ever) properly obtained a lock for
> > manipulating the queues.  This could have been causing the queue
> > corruption.
> >
> > Please test.  I need feedback that I haven't introduced a deadlock.
> >
> > It also appears that the last change requiring the interrupt handler
> > to obtain a lock, completely mitigates me having to use the "-cache
> > 8192" option to mplayer for digital captures, and greatly reduces the
> > amount of cache I need to have mplayer use for analog captures.
> 
> I suspect that it is the change before that one: adding a spinlock to 
> cx18_queue_move().

I have a recollection that in my incremental testing that this was not
the case.  It was actually the spinlock in the irq handler that made
things better.  But it was late and I was tired.  I'll retest and run my
blocking read timing test to see if I can see a difference in the
numbers for a few cases.



>  The spinlock in the interrupt handler doesn't do 
> anything. It would only be useful if you could have two independent 
> interrupt handlers that both needed access to that resource. But that 
> is not the case here.

I agree that 2+ interrupt handlers could not access that resource
concurrently.  But, AFAICT, a system call on one processor and the
interrupt handler on the other processor can access the queues
concurrently.

It's my understanding that spin_lock_irqsave() and spin_lock_irq() only
disable local interrupts for the particular CPU and not globally.  So
here's the case I think needs a spinlock lock in the irq handler:

1. A capture is in progress

2. Application on CPU #0 issues a read(). cx18_dequeue() is ultimately
called on q_full.  cx18_dequeue() calls spin_lock_irqsave(), disabling
preemption, disabling local interrupts, and acquiring the lock, and
begins manipulating q_full

3. At an inopportune time, an interrupt arrives from the encoder and is
sent to CPU #1 for servicing.   In the cx18 driver, in an interrupt
context, epu_dma_done() is eventually invoked.  Without obtaining a
lock, epu_dma_done() calls cx18_queue_find_buf() and manipulates q_full.
This manipulation of q_full happens while the system call on CPU #0
holds the lock and thinks things are safe.


Given the above situation I think the interrupt handler does need to
acquire the spinlock.  So, here's where people get to hit me with the
clue-stick: in the above case, what do I have wrong?




> > Hans,
> > (or anyone else with expertise in using spinlocks withing an
> > interrupt handler),
> >
> > Could you please provide comments on if I'm doing something wrong
> > with the way I obtain the spinlock in the interrupt handler?
> 
> See above :-)
> 
> >
> > http://linuxtv.org/hg/~awalls/v4l-dvb/rev/f3ada35200c0
> >
> > >From reading Bovet and Cesati's _Understanding_the_Linux_Kernel_ and
> >
> > Corbet, Rubini, and Kroah-Hartman's _Linux_Device_Drivers_ I think
> > I've got it right.
> >
> > When the stream queues (q_full, q_io, and q_free) are accessed from
> > the system call exception handler, I need to do a spin_lock_irqsave()
> > to disable local CPU interrupts and protect access to the queues by
> > kernel control paths on other CPU's.  When they stream queues are
> > accessed by the interrupt handler on any CPU, the interrupt handler
> > is serialized with respect to itself and need not disable any
> > interrupts and simply obtain the lock via spin_lock() to protect
> > against access from system call exceptions.
> 
> System call exceptions? Not sure what you mean.

As I understand it, on Intel platforms, when a user land application
invokes read(), write(), or some other system call, said system call
eventually invokes an INT 0x80 software exception to make the transition
to kernel code and data space with the proper privileges.


> AFAIK the interrupt 
> handler doesn't have to protect against anything.

See my concern above.  In brief, AFAICT, a system call on one processor
concurrent with interrupt service on another processor requires the irq
handler to obtain the proper lock before mucking with the shared data
structure.  


Regards,
Andy

> Regards,
> 
> 	Hans
> 
> >
> >
> > Regards,
> > Andy

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Hans Verkuil]

On Sunday 17 August 2008 21:12:50 Andy Walls wrote:
> On Sun, 2008-08-17 at 11:41 +0200, Hans Verkuil wrote:
> > On Sunday 17 August 2008 04:13:24 Andy Walls wrote:
> > > On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> > > > On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net>
> >
> > wrote:
> > > I have updated my repo at
> > >
> > > http://linuxtv.org/hg/~awalls/v4l-dvb
> > >
> > > with 3 changes:
> > >
> > > 1. Back out the original band aid fix
> > > 2. Simplify the queue flush routines (you will not see that oops
> > > again)
> >
> > Nice! Cleans it up considerably.
> >
> :)
> :
> > > 3. Fix the interrupt handler to obtain a queue lock (prevents
> > > queue corruption)
> >
> > No, that is not the bug.
>
> Yeah, it is not *the* bug I was after, but pending further discussion
> below I'll maintain it is a bug.
>
>
> I really want to do a full audit of all the queue manipulations in
> the driver.  I'll try to find some time when I'm offline this week.
>
> (Thanks for all the comments BTW!)
>
> > I'm pretty sure that the real bug is that the
> > old cx18_queue_move() function didn't use a spin_lock_irqsave(). I
> > think that it was possible for an interrupt to arrive when the CPU
> > was in the middle of a cx18_queue_move().
>
> On the surface it did look OK since all the interrupts for that
> stream *should* have been stopped.  But after some hypothetical
> thought about how the encoder might not stop right away and looking
> at Jeff's logs where a new capture may have been started before the
> queue flush was done, it's safer just to have the queue flush routine
> to acquire the lock.  Since the queue flush routine in question is
> called very infrequently, there's not much of a time penalty.
>
> >  A spinlock in an interrupt
> > handler is usually bogus (and that includes the one in the ivtv irq
> > handler, I've just realized).
>
> Chapter 5 of _Understanding_the_Linux_Kernel_ (2nd edition) on page
> 185 & 188 mentions that to protect data structures, being accessed by
> both exceptions (like open/close/read/write/poll induced INT 0x80
> exceptions on Intel) and interrupt handlers on a MP system, a
> spinlock needs to be used.  The book also mentions that a semaphore
> (now a mutex) is sometimes preferable in this case, where the
> interrupt routine polls the semaphore in a tight loop like a
> spinlock, but the system calls use the semaphore normally and are
> allowed to sleep.
>
> > What I am uneasy about, though, is why an interrupt could arrive
> > while in the cx18_queue_move() function. In principle this function
> > should only be called when the capture has stopped. I think it
> > might be a good idea to debug this: is it possible for interrupts
> > to arrive after the capture was stopped? Or is it possible for
> > cx18_queue_move() to be called when a capture is still in progress?
>
> Right.  I should really test to see if this actually happens.  Since
> spinlocks are supposedly optimized for the case of the lock being
> available and the cx18_queue_move() is called infrequently, leaving
> it in for now, should be OK.
>
> I also have difficulty reproducing the original oops, so my test
> results could be misleading.  I have no good criteria for terminating
> the experiment/testing and declaring "interrupts can't happen when we
> decide to flush queues".
>
> > I do think it is a good idea to rename cx18_queue_find_buf to
> > cx18_queue_get_buf_irq to denote that it 1) not just finds a buffer
> > but also removes it from the queue, and 2) it can only be called
> > safely from interrupt context.
>
> Agree.  I'll make that part of the final change.
>
> > > >From most of the output you provided, it was pretty obvious that
> > > > q_full
> > >
> > > was always claiming to have more buffers that it actually did.  I
> > > hypothesized this could come about at the end of a capture when
> > > the encoder hadn't really stopped transferring buffers yet (after
> > > we told it to stop) and then we try to clear q_full while the
> > > interrupt handler is still trying to add buffers.  This could
> > > happen because the interrupt handler never (ever) properly
> > > obtained a lock for manipulating the queues.  This could have
> > > been causing the queue corruption.
> > >
> > > Please test.  I need feedback that I haven't introduced a
> > > deadlock.
> > >
> > > It also appears that the last change requiring the interrupt
> > > handler to obtain a lock, completely mitigates me having to use
> > > the "-cache 8192" option to mplayer for digital captures, and
> > > greatly reduces the amount of cache I need to have mplayer use
> > > for analog captures.
> >
> > I suspect that it is the change before that one: adding a spinlock
> > to cx18_queue_move().
>
> I have a recollection that in my incremental testing that this was
> not the case.  It was actually the spinlock in the irq handler that
> made things better.  But it was late and I was tired.  I'll retest
> and run my blocking read timing test to see if I can see a difference
> in the numbers for a few cases.
>
> >  The spinlock in the interrupt handler doesn't do
> > anything. It would only be useful if you could have two independent
> > interrupt handlers that both needed access to that resource. But
> > that is not the case here.
>
> I agree that 2+ interrupt handlers could not access that resource
> concurrently.  But, AFAICT, a system call on one processor and the
> interrupt handler on the other processor can access the queues
> concurrently.
>
> It's my understanding that spin_lock_irqsave() and spin_lock_irq()
> only disable local interrupts for the particular CPU and not
> globally.  So here's the case I think needs a spinlock lock in the
> irq handler:
>
> 1. A capture is in progress
>
> 2. Application on CPU #0 issues a read(). cx18_dequeue() is
> ultimately called on q_full.  cx18_dequeue() calls
> spin_lock_irqsave(), disabling preemption, disabling local
> interrupts, and acquiring the lock, and begins manipulating q_full
>
> 3. At an inopportune time, an interrupt arrives from the encoder and
> is sent to CPU #1 for servicing.   In the cx18 driver, in an
> interrupt context, epu_dma_done() is eventually invoked.  Without
> obtaining a lock, epu_dma_done() calls cx18_queue_find_buf() and
> manipulates q_full. This manipulation of q_full happens while the
> system call on CPU #0 holds the lock and thinks things are safe.
>
>
> Given the above situation I think the interrupt handler does need to
> acquire the spinlock.  So, here's where people get to hit me with the
> clue-stick: in the above case, what do I have wrong?
>
> > > Hans,
> > > (or anyone else with expertise in using spinlocks withing an
> > > interrupt handler),
> > >
> > > Could you please provide comments on if I'm doing something wrong
> > > with the way I obtain the spinlock in the interrupt handler?
> >
> > See above :-)
> >
> > > http://linuxtv.org/hg/~awalls/v4l-dvb/rev/f3ada35200c0
> > >
> > > >From reading Bovet and Cesati's _Understanding_the_Linux_Kernel_
> > > > and
> > >
> > > Corbet, Rubini, and Kroah-Hartman's _Linux_Device_Drivers_ I
> > > think I've got it right.
> > >
> > > When the stream queues (q_full, q_io, and q_free) are accessed
> > > from the system call exception handler, I need to do a
> > > spin_lock_irqsave() to disable local CPU interrupts and protect
> > > access to the queues by kernel control paths on other CPU's. 
> > > When they stream queues are accessed by the interrupt handler on
> > > any CPU, the interrupt handler is serialized with respect to
> > > itself and need not disable any interrupts and simply obtain the
> > > lock via spin_lock() to protect against access from system call
> > > exceptions.
> >
> > System call exceptions? Not sure what you mean.
>
> As I understand it, on Intel platforms, when a user land application
> invokes read(), write(), or some other system call, said system call
> eventually invokes an INT 0x80 software exception to make the
> transition to kernel code and data space with the proper privileges.

Ah, I just call them 'system calls' :-)

> > AFAIK the interrupt
> > handler doesn't have to protect against anything.
>
> See my concern above.  In brief, AFAICT, a system call on one
> processor concurrent with interrupt service on another processor
> requires the irq handler to obtain the proper lock before mucking
> with the shared data structure.

You are completely right and I stand corrected. cx18_queue_find_buf (aka 
cx18_queue_get_buf_irq) must have a spin_lock. So that spin_lock in 
ivtv wasn't bogus either :-)

Damn, it's so easy to get confused with locking, even you've implemented 
it several times already.

That's a serious bug which needs to go into 2.6.27 (and probably to the 
2.6.26 stable series as well).

Andy, can you make a patch that adds the spin_lock to 
cx18_queue_find_buf(). It's better to do it there rather than in the 
interrupt routine.

Then that patch can go into v4l-dvb and from there to 2.6.27. The other 
changes can come later.

Apologies for probably confusing you. I certainly confused myself.

Regards,

	Hans

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Sun, 2008-08-17 at 22:01 +0200, Hans Verkuil wrote:
> On Sunday 17 August 2008 21:12:50 Andy Walls wrote:
> > On Sun, 2008-08-17 at 11:41 +0200, Hans Verkuil wrote:
> > > On Sunday 17 August 2008 04:13:24 Andy Walls wrote:
> > > > On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> > > > > On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net>


> > See my concern above.  In brief, AFAICT, a system call on one
> > processor concurrent with interrupt service on another processor
> > requires the irq handler to obtain the proper lock before mucking
> > with the shared data structure.
> 
> You are completely right and I stand corrected. cx18_queue_find_buf (aka 
> cx18_queue_get_buf_irq) must have a spin_lock. So that spin_lock in 
> ivtv wasn't bogus either :-)
> 
> Damn, it's so easy to get confused with locking, even you've implemented 
> it several times already.

Yup.  And I found that "reading the code" without any sort of design
paperwork, design description, or reference textbooks makes locking
problems hard to spot.

I spent ~6 years on $BIG_PROJECT on a team maintaining highly
multithreaded applications that ran on an SMP machine.  The apps used
spinlocks, mutexes (with and without condition variables), semaphores,
rendezvous, etc.  A peer review of any significant code change usually
revealed at least one locking problem.


> That's a serious bug which needs to go into 2.6.27 (and probably to the 
> 2.6.26 stable series as well).
> 
> Andy, can you make a patch that adds the spin_lock to 
> cx18_queue_find_buf(). It's better to do it there rather than in the 
> interrupt routine.
> 
> Then that patch can go into v4l-dvb and from there to 2.6.27. The other 
> changes can come later.

Done.  Pull request submitted.


> Apologies for probably confusing you. I certainly confused myself.

No big deal.  I wasn't confused, but I did think I had missed something.


Regards,
Andy

> Regards,
> 
> 	Hans
> 

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls@radix.net> wrote:
> On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
>> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
>> > Brandon,
>> >
>> > I have checked in a fix to defend against the Ooops we both encountered.
>> > The fix will also generate a WARN dump and some queue stats when it runs
>> > across the cause, but will otherwise try to clean up as best it can to
>> > allow further operation.
>> >
>> > The band-aid fix is the latest change at
>> >
>> > http://linuxtv.org/hg/~awalls/v4l-dvb
>> >
>> > Please provide the extra debug that happens if you encounter the warning
>> > in your logs.  I have only encountered the problem twice over a several
>> > month period, so its hard to get insight into the root cause buffer
>> > accounting error at that rate.
>>
>> Andy,
>>
>> I had an oops today, first one in a few days
>>
>> Brandon
>
> Brandon & Jeff,
>
> I have updated my repo at
>
> http://linuxtv.org/hg/~awalls/v4l-dvb
>
> with 3 changes:
>
> 1. Back out the original band aid fix
> 2. Simplify the queue flush routines (you will not see that oops again)
> 3. Fix the interrupt handler to obtain a queue lock (prevents queue
> corruption)
>
> >From most of the output you provided, it was pretty obvious that q_full
> was always claiming to have more buffers that it actually did.  I
> hypothesized this could come about at the end of a capture when the
> encoder hadn't really stopped transferring buffers yet (after we told it
> to stop) and then we try to clear q_full while the interrupt handler is
> still trying to add buffers.  This could happen because the interrupt
> handler never (ever) properly obtained a lock for manipulating the
> queues.  This could have been causing the queue corruption.
>
> Please test.  I need feedback that I haven't introduced a deadlock.
>
> It also appears that the last change requiring the interrupt handler to
> obtain a lock, completely mitigates me having to use the "-cache 8192"
> option to mplayer for digital captures, and greatly reduces the amount
> of cache I need to have mplayer use for analog captures.
>
[snip]

Andy,

I have update to the new code. Interestingly now I am getting audio
noises (chirping) while watching TV. Is there anything which has been
done that could affect sound?

Otherwise no issues thus far.

Brandon

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins@tvwhere.com> wrote:
> On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls@radix.net> wrote:
>> On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
>>> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
>>> > Brandon,
>>> >
>>> > I have checked in a fix to defend against the Ooops we both encountered.
>>> > The fix will also generate a WARN dump and some queue stats when it runs
>>> > across the cause, but will otherwise try to clean up as best it can to
>>> > allow further operation.
>>> >
>>> > The band-aid fix is the latest change at
>>> >
>>> > http://linuxtv.org/hg/~awalls/v4l-dvb
>>> >
>>> > Please provide the extra debug that happens if you encounter the warning
>>> > in your logs.  I have only encountered the problem twice over a several
>>> > month period, so its hard to get insight into the root cause buffer
>>> > accounting error at that rate.
>>>
>>> Andy,
>>>
>>> I had an oops today, first one in a few days
>>>
>>> Brandon
>>
>> Brandon & Jeff,
>>
>> I have updated my repo at
>>
>> http://linuxtv.org/hg/~awalls/v4l-dvb
>>
>> with 3 changes:
>>
>> 1. Back out the original band aid fix
>> 2. Simplify the queue flush routines (you will not see that oops again)
>> 3. Fix the interrupt handler to obtain a queue lock (prevents queue
>> corruption)
>>
>> >From most of the output you provided, it was pretty obvious that q_full
>> was always claiming to have more buffers that it actually did.  I
>> hypothesized this could come about at the end of a capture when the
>> encoder hadn't really stopped transferring buffers yet (after we told it
>> to stop) and then we try to clear q_full while the interrupt handler is
>> still trying to add buffers.  This could happen because the interrupt
>> handler never (ever) properly obtained a lock for manipulating the
>> queues.  This could have been causing the queue corruption.
>>
>> Please test.  I need feedback that I haven't introduced a deadlock.
>>
>> It also appears that the last change requiring the interrupt handler to
>> obtain a lock, completely mitigates me having to use the "-cache 8192"
>> option to mplayer for digital captures, and greatly reduces the amount
>> of cache I need to have mplayer use for analog captures.
>>
> [snip]
>
> Andy,
>
> I have update to the new code. Interestingly now I am getting audio
> noises (chirping) while watching TV. Is there anything which has been
> done that could affect sound?
>
> Otherwise no issues thus far.
>
> Brandon
>
Andy,

I also seeing these messages in dmesg:

[65288.817420] cx18-0: Cannot find buffer 58 for stream TS
[65288.817440] cx18-0: Could not find buf 58 for stream TS
[65840.130797] cx18-0: Cannot find buffer 17 for stream TS
[65840.130797] cx18-0: Could not find buf 17 for stream TS
[65861.882721] cx18-0: Cannot find buffer 48 for stream TS
[65861.882741] cx18-0: Could not find buf 48 for stream TS
[66151.627392] cx18-0: Cannot find buffer 107 for stream encoder MPEG
[66151.627392] cx18-0: Could not find buf 107 for stream encoder MPEG
[67632.953680] cx18-0: Cannot find buffer 99 for stream encoder MPEG
[67632.953680] cx18-0: Could not find buf 99 for stream encoder MPEG
[67795.527911] cx18-0: Cannot find buffer 106 for stream encoder MPEG
[67795.527911] cx18-0: Could not find buf 106 for stream encoder MPEG

Brandon

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Mon, 2008-08-18 at 13:17 -0400, Brandon Jenkins wrote:
> On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins@tvwhere.com> wrote:
> > On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls@radix.net> wrote:
> >> On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> >>> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
> >>> > Brandon,
> >>> >
> >>> > I have checked in a fix to defend against the Ooops we both encountered.
> >>> > The fix will also generate a WARN dump and some queue stats when it runs
> >>> > across the cause, but will otherwise try to clean up as best it can to
> >>> > allow further operation.
> >>> >
> >>> > The band-aid fix is the latest change at
> >>> >
> >>> > http://linuxtv.org/hg/~awalls/v4l-dvb
> >>> >
> >>> > Please provide the extra debug that happens if you encounter the warning
> >>> > in your logs.  I have only encountered the problem twice over a several
> >>> > month period, so its hard to get insight into the root cause buffer
> >>> > accounting error at that rate.
> >>>
> >>> Andy,
> >>>
> >>> I had an oops today, first one in a few days
> >>>
> >>> Brandon
> >>
> >> Brandon & Jeff,
> >>
> >> I have updated my repo at
> >>
> >> http://linuxtv.org/hg/~awalls/v4l-dvb
> >>
> >> with 3 changes:
> >>
> >> 1. Back out the original band aid fix
> >> 2. Simplify the queue flush routines (you will not see that oops again)
> >> 3. Fix the interrupt handler to obtain a queue lock (prevents queue
> >> corruption)
> >>
> >> >From most of the output you provided, it was pretty obvious that q_full
> >> was always claiming to have more buffers that it actually did.  I
> >> hypothesized this could come about at the end of a capture when the
> >> encoder hadn't really stopped transferring buffers yet (after we told it
> >> to stop) and then we try to clear q_full while the interrupt handler is
> >> still trying to add buffers.  This could happen because the interrupt
> >> handler never (ever) properly obtained a lock for manipulating the
> >> queues.  This could have been causing the queue corruption.
> >>
> >> Please test.  I need feedback that I haven't introduced a deadlock.
> >>
> >> It also appears that the last change requiring the interrupt handler to
> >> obtain a lock, completely mitigates me having to use the "-cache 8192"
> >> option to mplayer for digital captures, and greatly reduces the amount
> >> of cache I need to have mplayer use for analog captures.
> >>
> > [snip]
> >
> > Andy,
> >
> > I have update to the new code. Interestingly now I am getting audio
> > noises (chirping) while watching TV. Is there anything which has been
> > done that could affect sound?
> >
> > Otherwise no issues thus far.
> >
> > Brandon
> >
> Andy,
> 
> I also seeing these messages in dmesg:
> 
> [65288.817420] cx18-0: Cannot find buffer 58 for stream TS
> [65288.817440] cx18-0: Could not find buf 58 for stream TS
[9.2 minute interval]
> [65840.130797] cx18-0: Cannot find buffer 17 for stream TS
> [65840.130797] cx18-0: Could not find buf 17 for stream TS
[21 second interval]
> [65861.882721] cx18-0: Cannot find buffer 48 for stream TS
> [65861.882741] cx18-0: Could not find buf 48 for stream TS
[4.8 minute interval]
> [66151.627392] cx18-0: Cannot find buffer 107 for stream encoder MPEG
> [66151.627392] cx18-0: Could not find buf 107 for stream encoder MPEG
[24.7 minute interval]
> [67632.953680] cx18-0: Cannot find buffer 99 for stream encoder MPEG
> [67632.953680] cx18-0: Could not find buf 99 for stream encoder MPEG
[2.7 miunte interval]
> [67795.527911] cx18-0: Cannot find buffer 106 for stream encoder MPEG
> [67795.527911] cx18-0: Could not find buf 106 for stream encoder MPEG

So the encoder is saying it has buffers ready for a particular stream,
but we now occasionally can't find that buffer in q_free for the stream.

The funny part is that since the streams are alloc'ed in order at init
time, buffer id's 0-62 (or so) are used for stream MPEG and buffer id's
63-127 (or so) are used for stream TS.  The warnings clearly show a
mismatch.


So the warning messages above shows that either

a) the encoder firmware has a bug that it gives us back a buffer with
the wrong buffer id/stream handle pair

b) the cx18 driver somehow gives the wrong stream handle/buffer id pair
to the encoder firmware occasionally when giving it a buffer to use.

In the case of a) it's probably best to ignore the buffer it's best to
ignore the buffer from the encoder as who knows what's really in the
buffer.  If this happens 63 times for one capture during simultaneous
analog & digital captures, I think the encoder may get starved of
buffers for the other stream.  I'll have to check the code to make to
see what can be done to prevent that.

I'll also have to audit the code to see if case b) can happen somehow.


Off the cuff, these warnings seem unrelated to the test patch I
provided.  I can't begin to look at the problem until at least Friday.
Hopefully you can get by OK for now with the event happening on the
order of every 5 minutes or so.

Regards,
Andy

> Brandon
> 

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Mon, 2008-08-18 at 13:17 -0400, Brandon Jenkins wrote:
> On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins@tvwhere.com> wrote:
> > On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls@radix.net> wrote:
> >> On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> >>> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:

> Andy,
> 
> I also seeing these messages in dmesg:
> 
> [65288.817420] cx18-0: Cannot find buffer 58 for stream TS
> [65288.817440] cx18-0: Could not find buf 58 for stream TS
> [65840.130797] cx18-0: Cannot find buffer 17 for stream TS
> [65840.130797] cx18-0: Could not find buf 17 for stream TS
> [65861.882721] cx18-0: Cannot find buffer 48 for stream TS
> [65861.882741] cx18-0: Could not find buf 48 for stream TS
> [66151.627392] cx18-0: Cannot find buffer 107 for stream encoder MPEG
> [66151.627392] cx18-0: Could not find buf 107 for stream encoder MPEG
> [67632.953680] cx18-0: Cannot find buffer 99 for stream encoder MPEG
> [67632.953680] cx18-0: Could not find buf 99 for stream encoder MPEG
> [67795.527911] cx18-0: Cannot find buffer 106 for stream encoder MPEG
> [67795.527911] cx18-0: Could not find buf 106 for stream encoder MPEG
> 
> Brandon

Brandon,

There is now a fix for this bug as well in my v4l-dvb repo.

Regards,
Andy

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Brandon Jenkins]

On Sat, Aug 23, 2008 at 5:44 PM, Andy Walls <awalls@radix.net> wrote:
> On Mon, 2008-08-18 at 13:17 -0400, Brandon Jenkins wrote:
>> On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins@tvwhere.com> wrote:
>> > On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls@radix.net> wrote:
>> >> On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
>> >>> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
>
>> Andy,
>>
>> I also seeing these messages in dmesg:
>>
>> [65288.817420] cx18-0: Cannot find buffer 58 for stream TS
>> [65288.817440] cx18-0: Could not find buf 58 for stream TS
>> [65840.130797] cx18-0: Cannot find buffer 17 for stream TS
>> [65840.130797] cx18-0: Could not find buf 17 for stream TS
>> [65861.882721] cx18-0: Cannot find buffer 48 for stream TS
>> [65861.882741] cx18-0: Could not find buf 48 for stream TS
>> [66151.627392] cx18-0: Cannot find buffer 107 for stream encoder MPEG
>> [66151.627392] cx18-0: Could not find buf 107 for stream encoder MPEG
>> [67632.953680] cx18-0: Cannot find buffer 99 for stream encoder MPEG
>> [67632.953680] cx18-0: Could not find buf 99 for stream encoder MPEG
>> [67795.527911] cx18-0: Cannot find buffer 106 for stream encoder MPEG
>> [67795.527911] cx18-0: Could not find buf 106 for stream encoder MPEG
>>
>> Brandon
>
> Brandon,
>
> There is now a fix for this bug as well in my v4l-dvb repo.
>
> Regards,
> Andy
>
>

Andy,

Thank you very much. I am sorry I have not been overly responsive to
your previous questions.

The audio chirping is on analog coax tuner which is tuned to channel 3
for FiOS set top box use. I will do another pull and then make the
change as you suggested earlier. It only seems to affect the shows my
wife likes to watch.. (Or I am too busy only watching HD)

Thanks again

Brandon

--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list

Re: CX18 Oops

[Andy Walls]

On Mon, 2008-08-18 at 06:35 -0400, Brandon Jenkins wrote:
> On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls@radix.net> wrote:
> > On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> >> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls@radix.net> wrote:
> >> > Brandon,
> >> >
> >> > I have checked in a fix to defend against the Ooops we both encountered.
> >> > The fix will also generate a WARN dump and some queue stats when it runs
> >> > across the cause, but will otherwise try to clean up as best it can to
> >> > allow further operation.
> >> >
> >> > The band-aid fix is the latest change at
> >> >
> >> > http://linuxtv.org/hg/~awalls/v4l-dvb
> >> >
> >> > Please provide the extra debug that happens if you encounter the warning
> >> > in your logs.  I have only encountered the problem twice over a several
> >> > month period, so its hard to get insight into the root cause buffer
> >> > accounting error at that rate.
> >>
> >> Andy,
> >>
> >> I had an oops today, first one in a few days
> >>
> >> Brandon
> >
> > Brandon & Jeff,
> >
> > I have updated my repo at
> >
> > http://linuxtv.org/hg/~awalls/v4l-dvb
> >
> > with 3 changes:
> >
> > 1. Back out the original band aid fix
> > 2. Simplify the queue flush routines (you will not see that oops again)
> > 3. Fix the interrupt handler to obtain a queue lock (prevents queue
> > corruption)
> >
> > >From most of the output you provided, it was pretty obvious that q_full
> > was always claiming to have more buffers that it actually did.  I
> > hypothesized this could come about at the end of a capture when the
> > encoder hadn't really stopped transferring buffers yet (after we told it
> > to stop) and then we try to clear q_full while the interrupt handler is
> > still trying to add buffers.  This could happen because the interrupt
> > handler never (ever) properly obtained a lock for manipulating the
> > queues.  This could have been causing the queue corruption.
> >
> > Please test.  I need feedback that I haven't introduced a deadlock.
> >
> > It also appears that the last change requiring the interrupt handler to
> > obtain a lock, completely mitigates me having to use the "-cache 8192"
> > option to mplayer for digital captures, and greatly reduces the amount
> > of cache I need to have mplayer use for analog captures.
> >
> [snip]
> 
> Andy,
> 
> I have update to the new code. Interestingly now I am getting audio
> noises (chirping) while watching TV.

Analog or digital capture?  Analog tuner only or analog line in as well?
All digitial channels or just certain ones?


> Is there anything which has been done that could affect sound?

For analog capture, I recently added code to "lock" the video PLL to the
audio PLL in the cx18-av core.  The Conexant CX2854[0123] data sheet
recommended this for MPEG encoding applications - a primary use case for
the CX23418.

In cx18-av-audio.c:set_audclk_freq(), look for lines like

	cx18_av_write4(cx, 0x128, 0xa1nnnnnn);

and change them to 

	cx18_av_write4(cx, 0x128, 0xa0nnnnnn);

to have the video and audio sample clocks run independently again and
effectively back out that change.


You can also try to back out the change to have the interrupt handler
obtain the qlock spinlock.  It's the wrong thing to do, but it will let
you determine if it causes the artifacts you now hear.


If that doesn't make the chirping go away, then:

does caching help?  Does recordings captured with "cat" exhibit the
chirps on playback? Does mplayer (64 bit native) exhibit the chirping as
well as Sage (32 bit compat mode)?



> Otherwise no issues thus far.

:)

I won't have access to personal email for the next few days, so I won't
be able to help until Friday at the earliest.

Regards,
Andy

> Brandon


--
video4linux-list mailing list
Unsubscribe mailto:video4linux-list-request@redhat.com?subject=unsubscribe
https://www.redhat.com/mailman/listinfo/video4linux-list