Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: ivtv: devel

CX18 Oops

 

 

ivtv devel RSS feed   Index | Next | Previous | View Threaded


narflex at gmail

Aug 14, 2008, 6:12 PM

Post #1 of 12 (4164 views)
Permalink
CX18 Oops

Andy,

I've got some more dmesg logging from the CX18 Oops. I get it about every
other day now for the past couple weeks. Once it happens to me then the
device will no longer produce any video until I reboot the machine (or
unload/reload the driver). If you need any other details, let me know.

Cheers,
Jeff

(I'm the one who Brandon got the other log from before)

[38214.432000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[38214.432000] [<f0ab8656>] cx18_queue_move+0x246/0x250 [cx18]
[38214.432000] [<f0ab869c>] cx18_flush_queues+0x3c/0x50 [cx18]
[38214.432000] [<f0ab9b17>] cx18_release_stream+0x77/0xc0 [cx18]
[38214.432000] [<f0ab9f5c>] cx18_v4l2_close+0x9c/0x130 [cx18]
[38214.432000] [<c01816bd>] __fput+0xad/0x1a0
[38214.432000] [<c017ea97>] filp_close+0x47/0x80
[38214.432000] [<c017febb>] sys_close+0x6b/0xd0
[38214.432000] [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[38214.432000] =======================
[38214.432000] cx18-1: queue_move: driver bug! errant steal attempt for
to/from_free queue move, dumping queue stats
[38214.432000] cx18-1: queue_move: thought bytes_available = 65536 with
needed = 65536 and initial destination size = 2031616
[38214.432000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[38214.432000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[38214.432000] cx18-1: queue_log: q = e63201b0 buffers = 2 length =
65536 bytesused = 57344
[38214.432000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[38214.432000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[38214.432000] cx18-1: queue_log: q = e632019c buffers = 62 length =
2031616 bytesused = 0
[38214.432000] cx18-1: queue_log: i = 0 buf->id = 11 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 1 buf->id = 12 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 2 buf->id = 13 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 3 buf->id = 14 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 4 buf->id = 15 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 5 buf->id = 16 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 6 buf->id = 17 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 7 buf->id = 18 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 8 buf->id = 19 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 9 buf->id = 20 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 10 buf->id = 21 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 11 buf->id = 22 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 12 buf->id = 23 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 13 buf->id = 24 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 14 buf->id = 25 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 15 buf->id = 26 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 16 buf->id = 27 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 17 buf->id = 28 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 18 buf->id = 29 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 19 buf->id = 30 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 20 buf->id = 31 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 21 buf->id = 32 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 22 buf->id = 33 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 23 buf->id = 34 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 24 buf->id = 35 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 25 buf->id = 36 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 26 buf->id = 37 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 27 buf->id = 38 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 28 buf->id = 39 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 29 buf->id = 41 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 30 buf->id = 42 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 31 buf->id = 43 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 32 buf->id = 44 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 33 buf->id = 45 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 34 buf->id = 46 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 35 buf->id = 47 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 36 buf->id = 48 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 37 buf->id = 49 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 38 buf->id = 50 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 39 buf->id = 51 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 40 buf->id = 52 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 41 buf->id = 53 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 42 buf->id = 54 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 43 buf->id = 55 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 44 buf->id = 56 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 45 buf->id = 57 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 46 buf->id = 58 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 47 buf->id = 59 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 48 buf->id = 60 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 49 buf->id = 61 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 50 buf->id = 62 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 51 buf->id = 0 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 52 buf->id = 1 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 53 buf->id = 2 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 54 buf->id = 3 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 55 buf->id = 4 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 56 buf->id = 5 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 57 buf->id = 6 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 58 buf->id = 7 buf->bytesused = 0
buf->readpos = 0
[38214.432000] cx18-1: queue_log: i = 59 buf->id = 8 buf->bytesused = 0
buf->readpos = 0
[38815.196000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[38815.196000] [<f0ab8656>] cx18_queue_move+0x246/0x250 [cx18]
[38815.196000] [<f0ab869c>] cx18_flush_queues+0x3c/0x50 [cx18]
[38815.196000] [<f0ab9b17>] cx18_release_stream+0x77/0xc0 [cx18]
[38815.196000] [<f0ab9f5c>] cx18_v4l2_close+0x9c/0x130 [cx18]
[38815.196000] [<c01816bd>] __fput+0xad/0x1a0
[38815.196000] [<c017ea97>] filp_close+0x47/0x80
[38815.196000] [<c017febb>] sys_close+0x6b/0xd0
[38815.196000] [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[38815.196000] =======================
[38815.196000] cx18-1: queue_move: driver bug! errant steal attempt for
to/from_free queue move, dumping queue stats
[38815.196000] cx18-1: queue_move: thought bytes_available = 32768 with
needed = 32768 and initial destination size = 1998848
[38815.196000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[38815.196000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[38815.196000] cx18-1: queue_log: q = e63201b0 buffers = 1 length =
32768 bytesused = 32768
[38815.196000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[38815.196000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[38815.196000] cx18-1: queue_log: q = e632019c buffers = 61 length =
1998848 bytesused = 0
[38815.196000] cx18-1: queue_log: i = 0 buf->id = 12 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 1 buf->id = 13 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 2 buf->id = 14 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 3 buf->id = 15 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 4 buf->id = 16 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 5 buf->id = 17 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 6 buf->id = 18 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 7 buf->id = 19 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 8 buf->id = 20 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 9 buf->id = 21 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 10 buf->id = 22 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 11 buf->id = 23 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 12 buf->id = 24 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 13 buf->id = 25 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 14 buf->id = 26 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 15 buf->id = 27 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 16 buf->id = 28 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 17 buf->id = 29 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 18 buf->id = 30 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 19 buf->id = 31 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 20 buf->id = 32 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 21 buf->id = 33 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 22 buf->id = 34 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 23 buf->id = 35 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 24 buf->id = 36 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 25 buf->id = 37 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 26 buf->id = 38 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 27 buf->id = 39 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 28 buf->id = 41 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 29 buf->id = 42 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 30 buf->id = 43 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 31 buf->id = 44 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 32 buf->id = 45 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 33 buf->id = 46 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 34 buf->id = 47 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 35 buf->id = 48 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 36 buf->id = 49 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 37 buf->id = 50 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 38 buf->id = 51 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 39 buf->id = 52 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 40 buf->id = 53 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 41 buf->id = 54 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 42 buf->id = 55 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 43 buf->id = 56 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 44 buf->id = 57 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 45 buf->id = 58 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 46 buf->id = 59 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 47 buf->id = 60 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 48 buf->id = 61 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 49 buf->id = 62 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 50 buf->id = 0 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 51 buf->id = 1 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 52 buf->id = 2 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 53 buf->id = 3 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 54 buf->id = 4 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 55 buf->id = 5 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 56 buf->id = 6 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 57 buf->id = 7 buf->bytesused = 0
buf->readpos = 0
[38815.196000] cx18-1: queue_log: i = 58 buf->id = 8 buf->bytesused = 0
buf->readpos = 0
[38815.508000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[38815.508000] [<f0ab8656>] cx18_queue_move+0x246/0x250 [cx18]
[38815.508000] [<c018a20f>] __link_path_walk+0x9df/0xe70
[38815.508000] [<f0ab869c>] cx18_flush_queues+0x3c/0x50 [cx18]
[38815.508000] [<f0ab9b17>] cx18_release_stream+0x77/0xc0 [cx18]
[38815.508000] [<f0aba13f>] cx18_start_capture+0x14f/0x1b0 [cx18]
[38815.508000] [<f0aba1f1>] cx18_v4l2_read+0x51/0x9a0 [cx18]
[38815.508000] [<c018a957>] do_path_lookup+0x97/0x1d0
[38815.508000] [<c01ff040>] copy_to_user+0x30/0x60
[38815.508000] [<c0183849>] cp_new_stat64+0xf9/0x110
[38815.508000] [<c0183d0e>] sys_stat64+0x1e/0x30
[38815.508000] [<c0180e0c>] vfs_read+0xbc/0x160
[38815.508000] [<f0aba1a0>] cx18_v4l2_read+0x0/0x9a0 [cx18]
[38815.508000] [<c0181341>] sys_read+0x41/0x70
[38815.508000] [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[38815.508000] =======================
[38815.508000] cx18-1: queue_move: driver bug! errant steal attempt for
to/from_free queue move, dumping queue stats
[38815.508000] cx18-1: queue_move: thought bytes_available = 229376 with
needed = 229376 and initial destination size = 1769472
[38815.508000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[38815.508000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[38815.508000] cx18-1: queue_log: q = e63201b0 buffers = 7 length =
229376 bytesused = 163840
[38815.508000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[38815.508000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[38815.508000] cx18-1: queue_log: q = e632019c buffers = 54 length =
1769472 bytesused = 0
[38815.508000] cx18-1: queue_log: i = 0 buf->id = 19 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 1 buf->id = 20 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 2 buf->id = 21 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 3 buf->id = 22 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 4 buf->id = 23 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 5 buf->id = 24 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 6 buf->id = 25 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 7 buf->id = 26 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 8 buf->id = 27 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 9 buf->id = 28 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 10 buf->id = 29 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 11 buf->id = 30 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 12 buf->id = 31 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 13 buf->id = 32 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 14 buf->id = 33 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 15 buf->id = 34 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 16 buf->id = 35 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 17 buf->id = 36 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 18 buf->id = 37 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 19 buf->id = 38 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 20 buf->id = 39 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 21 buf->id = 41 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 22 buf->id = 42 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 23 buf->id = 43 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 24 buf->id = 44 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 25 buf->id = 45 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 26 buf->id = 46 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 27 buf->id = 47 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 28 buf->id = 48 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 29 buf->id = 49 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 30 buf->id = 50 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 31 buf->id = 51 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 32 buf->id = 52 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 33 buf->id = 53 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 34 buf->id = 54 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 35 buf->id = 55 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 36 buf->id = 56 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 37 buf->id = 57 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 38 buf->id = 58 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 39 buf->id = 59 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 40 buf->id = 60 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 41 buf->id = 61 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 42 buf->id = 62 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 43 buf->id = 0 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 44 buf->id = 1 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 45 buf->id = 2 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 46 buf->id = 3 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 47 buf->id = 4 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 48 buf->id = 5 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 49 buf->id = 6 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 50 buf->id = 7 buf->bytesused = 0
buf->readpos = 0
[38815.508000] cx18-1: queue_log: i = 51 buf->id = 8 buf->bytesused = 0
buf->readpos = 0
[39116.720000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[39116.720000] [<f0ab8656>] cx18_queue_move+0x246/0x250 [cx18]
[39116.720000] [<f0ab869c>] cx18_flush_queues+0x3c/0x50 [cx18]
[39116.720000] [<f0ab9b17>] cx18_release_stream+0x77/0xc0 [cx18]
[39116.720000] [<f0ab9f5c>] cx18_v4l2_close+0x9c/0x130 [cx18]
[39116.720000] [<c01816bd>] __fput+0xad/0x1a0
[39116.720000] [<c017ea97>] filp_close+0x47/0x80
[39116.720000] [<c017febb>] sys_close+0x6b/0xd0
[39116.720000] [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[39116.720000] =======================
[39116.720000] cx18-1: queue_move: driver bug! errant steal attempt for
to/from_free queue move, dumping queue stats
[39116.720000] cx18-1: queue_move: thought bytes_available = 1409024 with
needed = 1409024 and initial destination size = 360448
[39116.720000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[39116.720000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[39116.720000] cx18-1: queue_log: q = e63201b0 buffers = 43 length =
1409024 bytesused = 942080
[39116.720000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[39116.720000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[39116.720000] cx18-1: queue_log: q = e632019c buffers = 11 length =
360448 bytesused = 0
[39116.720000] cx18-1: queue_log: i = 0 buf->id = 0 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 1 buf->id = 1 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 2 buf->id = 2 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 3 buf->id = 3 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 4 buf->id = 4 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 5 buf->id = 5 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 6 buf->id = 6 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 7 buf->id = 7 buf->bytesused = 0
buf->readpos = 0
[39116.720000] cx18-1: queue_log: i = 8 buf->id = 8 buf->bytesused = 0
buf->readpos = 0
[39117.036000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[39117.036000] [<f0ab8656>] cx18_queue_move+0x246/0x250 [cx18]
[39117.036000] [<c018a20f>] __link_path_walk+0x9df/0xe70
[39117.036000] [<f0ab869c>] cx18_flush_queues+0x3c/0x50 [cx18]
[39117.036000] [<f0ab9b17>] cx18_release_stream+0x77/0xc0 [cx18]
[39117.036000] [<f0aba13f>] cx18_start_capture+0x14f/0x1b0 [cx18]
[39117.036000] [<f0aba1f1>] cx18_v4l2_read+0x51/0x9a0 [cx18]
[39117.036000] [<c018a957>] do_path_lookup+0x97/0x1d0
[39117.036000] [<c01ff040>] copy_to_user+0x30/0x60
[39117.036000] [<c0183849>] cp_new_stat64+0xf9/0x110
[39117.036000] [<c0183d0e>] sys_stat64+0x1e/0x30
[39117.036000] [<c0180e0c>] vfs_read+0xbc/0x160
[39117.036000] [<f0aba1a0>] cx18_v4l2_read+0x0/0x9a0 [cx18]
[39117.036000] [<c0181341>] sys_read+0x41/0x70
[39117.036000] [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[39117.036000] =======================
[39117.036000] cx18-1: queue_move: driver bug! errant steal attempt for
to/from_free queue move, dumping queue stats
[39117.036000] cx18-1: queue_move: thought bytes_available = 32768 with
needed = 32768 and initial destination size = 327680
[39117.036000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[39117.036000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[39117.036000] cx18-1: queue_log: q = e63201b0 buffers = 1 length =
32768 bytesused = 32768
[39117.036000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[39117.036000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[39117.036000] cx18-1: queue_log: q = e632019c buffers = 10 length =
327680 bytesused = 0
[39117.036000] cx18-1: queue_log: i = 0 buf->id = 1 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 1 buf->id = 2 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 2 buf->id = 3 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 3 buf->id = 4 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 4 buf->id = 5 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 5 buf->id = 6 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 6 buf->id = 7 buf->bytesused = 0
buf->readpos = 0
[39117.036000] cx18-1: queue_log: i = 7 buf->id = 8 buf->bytesused = 0
buf->readpos = 0
[39418.276000] WARNING: at /root/hdpvr/v4l/cx18-queue.c:204
cx18_queue_move()
[39418.276000] [<f0ab8656>] cx18_queue_move+0x246/0x250 [cx18]
[39418.276000] [<f0ab869c>] cx18_flush_queues+0x3c/0x50 [cx18]
[39418.276000] [<f0ab9b17>] cx18_release_stream+0x77/0xc0 [cx18]
[39418.276000] [<f0ab9f5c>] cx18_v4l2_close+0x9c/0x130 [cx18]
[39418.276000] [<c01816bd>] __fput+0xad/0x1a0
[39418.276000] [<c017ea97>] filp_close+0x47/0x80
[39418.276000] [<c017febb>] sys_close+0x6b/0xd0
[39418.276000] [<c01041d2>] sysenter_past_esp+0x6b/0xa9
[39418.276000] =======================
[39418.276000] cx18-1: queue_move: driver bug! errant steal attempt for
to/from_free queue move, dumping queue stats
[39418.276000] cx18-1: queue_move: thought bytes_available = 262144 with
needed = 262144 and initial destination size = 65536
[39418.276000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[39418.276000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[39418.276000] cx18-1: queue_log: q = e63201b0 buffers = 8 length =
262144 bytesused = 169984
[39418.276000] cx18-1: queue_log: stream 'encoder MPEG' buffers = 63
buf_size = 32768 buffers_stolen = 0
[39418.276000] cx18-1: queue_log: &q_free = e632019c &q_full = e63201b0
&q_io = e63201c4
[39418.276000] cx18-1: queue_log: q = e632019c buffers = 2 length =
65536 bytesused = 0


awalls at radix

Aug 16, 2008, 7:13 PM

Post #2 of 12 (4031 views)
Permalink
Re: CX18 Oops [In reply to]

On Mon, 2008-08-11 at 17:33 -0400, Brandon Jenkins wrote:
> On Fri, Aug 8, 2008 at 10:18 AM, Andy Walls <awalls [at] radix> 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 [at] redhat?subject=unsubscribe
> https://www.redhat.com/mailman/listinfo/video4linux-list
>


_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


hverkuil at xs4all

Aug 17, 2008, 2:41 AM

Post #3 of 12 (4031 views)
Permalink
Re: CX18 Oops [In reply to]

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 [at] radix>
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 [at] redhat?subject=unsubscribe
> > https://www.redhat.com/mailman/listinfo/video4linux-list



_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


awalls at radix

Aug 17, 2008, 12:12 PM

Post #4 of 12 (4008 views)
Permalink
Re: CX18 Oops [In reply to]

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 [at] radix>
> 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


_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


hverkuil at xs4all

Aug 17, 2008, 1:01 PM

Post #5 of 12 (4012 views)
Permalink
Re: CX18 Oops [In reply to]

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 [at] radix>
> >
> > 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

_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


awalls at radix

Aug 17, 2008, 7:53 PM

Post #6 of 12 (4013 views)
Permalink
Re: CX18 Oops [In reply to]

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 [at] radix>


> > 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
>


_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


bcjenkins at tvwhere

Aug 18, 2008, 3:35 AM

Post #7 of 12 (3985 views)
Permalink
Re: CX18 Oops [In reply to]

On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls [at] radix> 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 [at] radix> 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

_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


bcjenkins at tvwhere

Aug 18, 2008, 10:17 AM

Post #8 of 12 (3979 views)
Permalink
Re: CX18 Oops [In reply to]

On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins [at] tvwhere> wrote:
> On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls [at] radix> 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 [at] radix> 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

_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


awalls at radix

Aug 18, 2008, 4:52 PM

Post #9 of 12 (3976 views)
Permalink
Re: CX18 Oops [In reply to]

On Mon, 2008-08-18 at 06:35 -0400, Brandon Jenkins wrote:
> On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls [at] radix> 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 [at] radix> 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



_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


awalls at radix

Aug 18, 2008, 5:34 PM

Post #10 of 12 (3969 views)
Permalink
Re: CX18 Oops [In reply to]

On Mon, 2008-08-18 at 13:17 -0400, Brandon Jenkins wrote:
> On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins [at] tvwhere> wrote:
> > On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls [at] radix> 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 [at] radix> 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
>


_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


awalls at radix

Aug 23, 2008, 2:44 PM

Post #11 of 12 (3850 views)
Permalink
Re: CX18 Oops [In reply to]

On Mon, 2008-08-18 at 13:17 -0400, Brandon Jenkins wrote:
> On Mon, Aug 18, 2008 at 6:35 AM, Brandon Jenkins <bcjenkins [at] tvwhere> wrote:
> > On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls [at] radix> 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 [at] radix> 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


_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel


bcjenkins at tvwhere

Aug 25, 2008, 12:14 PM

Post #12 of 12 (3807 views)
Permalink
Re: CX18 Oops [In reply to]

On Sat, Aug 23, 2008 at 5:44 PM, Andy Walls <awalls [at] radix> 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 [at] tvwhere> wrote:
>> > On Sat, Aug 16, 2008 at 10:13 PM, Andy Walls <awalls [at] radix> 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 [at] radix> 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

_______________________________________________
ivtv-devel mailing list
ivtv-devel [at] ivtvdriver
http://ivtvdriver.org/mailman/listinfo/ivtv-devel

ivtv devel RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.