From 9b6d5bbe82a31b3f52863c475843f8a67f22f5f4 Mon Sep 17 00:00:00 2001 From: Evgeni Raikhel Date: Tue, 10 Nov 2020 22:09:59 +0200 Subject: [PATCH] Kernel Debugs only --- .../media/common/videobuf2/videobuf2-core.c | 16 ++++ .../media/common/videobuf2/videobuf2-v4l2.c | 3 + drivers/media/usb/uvc/uvc_queue.c | 13 +++- drivers/media/usb/uvc/uvc_video.c | 76 +++++++++++++++++-- 4 files changed, 99 insertions(+), 9 deletions(-) diff --git a/drivers/media/common/videobuf2/videobuf2-core.c b/drivers/media/common/videobuf2/videobuf2-core.c index 4489744fbbd9..8fd0aaa5f745 100644 --- a/drivers/media/common/videobuf2/videobuf2-core.c +++ b/drivers/media/common/videobuf2/videobuf2-core.c @@ -925,7 +925,11 @@ void vb2_buffer_done(struct vb2_buffer *vb, enum vb2_buffer_state state) unsigned int plane; if (WARN_ON(vb->state != VB2_BUF_STATE_ACTIVE)) + { + dprintk(4, "!!## early return on buffer %d, state: %d\n", + vb->index, state); return; + } if (WARN_ON(state != VB2_BUF_STATE_DONE && state != VB2_BUF_STATE_ERROR && @@ -944,6 +948,7 @@ void vb2_buffer_done(struct vb2_buffer *vb, enum vb2_buffer_state state) if (state != VB2_BUF_STATE_QUEUED) { /* sync buffers */ + dprintk(1, "sync buffers"); for (plane = 0; plane < vb->num_planes; ++plane) call_void_memop(vb, finish, vb->planes[plane].mem_priv); vb->synced = 0; @@ -952,10 +957,12 @@ void vb2_buffer_done(struct vb2_buffer *vb, enum vb2_buffer_state state) spin_lock_irqsave(&q->done_lock, flags); if (state == VB2_BUF_STATE_QUEUED) { vb->state = VB2_BUF_STATE_QUEUED; + dprintk(1, "Buf Queued - buffer %d, state: %d\n", vb->index, state); } else { /* Add the buffer to the done buffers list */ list_add_tail(&vb->done_entry, &q->done_list); vb->state = state; + dprintk(1, "Buf added to Done - buffer %d, state: %d\n", vb->index, state); } atomic_dec(&q->owned_by_drv_count); @@ -966,13 +973,16 @@ void vb2_buffer_done(struct vb2_buffer *vb, enum vb2_buffer_state state) spin_unlock_irqrestore(&q->done_lock, flags); + dprintk(1, "trace_vb2_buf_done"); trace_vb2_buf_done(q, vb); switch (state) { case VB2_BUF_STATE_QUEUED: + dprintk(1, "!! vb2_buffer_done: wake on skipped- state queued buffer %d, state: %d\n", vb->index, state); return; default: /* Inform any processes that may be waiting for buffers */ + dprintk(1, "wake on buffer %d, state: %d\n", vb->index, state); wake_up(&q->done_wq); break; } @@ -1748,7 +1758,10 @@ static int __vb2_get_done_vb(struct vb2_queue *q, struct vb2_buffer **vb, */ ret = __vb2_wait_for_done_vb(q, nonblocking); if (ret) + { + dprintk(3, "!! __vb2_wait_for_done_vb done buffer failed\n"); return ret; + } /* * Driver's lock has been held since we last verified that done_list @@ -1807,7 +1820,10 @@ int vb2_core_dqbuf(struct vb2_queue *q, unsigned int *pindex, void *pb, ret = __vb2_get_done_vb(q, &vb, pb, nonblocking); if (ret < 0) + { + dprintk(3, "__vb2_get_done_vb failed, err=%d, nonblocking=%d\n", ret,(int)nonblocking); return ret; + } switch (vb->state) { case VB2_BUF_STATE_DONE: diff --git a/drivers/media/common/videobuf2/videobuf2-v4l2.c b/drivers/media/common/videobuf2/videobuf2-v4l2.c index 5a9ba3846f0a..213f9a5a29c3 100644 --- a/drivers/media/common/videobuf2/videobuf2-v4l2.c +++ b/drivers/media/common/videobuf2/videobuf2-v4l2.c @@ -875,15 +875,18 @@ __poll_t vb2_poll(struct vb2_queue *q, struct file *file, poll_table *wait) __poll_t res; res = vb2_core_poll(q, file, wait); + dprintk(0, "vb2_core_poll=%x,\n",res); if (test_bit(V4L2_FL_USES_V4L2_FH, &vfd->flags)) { struct v4l2_fh *fh = file->private_data; poll_wait(file, &fh->wait, wait); + dprintk(0, "poll_wait done\n"); if (v4l2_event_pending(fh)) res |= EPOLLPRI; } + dprintk(0," finally res=%x,\n",res); return res; } EXPORT_SYMBOL_GPL(vb2_poll); diff --git a/drivers/media/usb/uvc/uvc_queue.c b/drivers/media/usb/uvc/uvc_queue.c index da72577c2998..47db5dec7538 100644 --- a/drivers/media/usb/uvc/uvc_queue.c +++ b/drivers/media/usb/uvc/uvc_queue.c @@ -139,11 +139,13 @@ static void uvc_buffer_queue(struct vb2_buffer *vb) if (likely(!(queue->flags & UVC_QUEUE_DISCONNECTED))) { kref_init(&buf->ref); list_add_tail(&buf->queue, &queue->irqqueue); + uvc_trace(UVC_TRACE_FRAME, "vb %d recycled\n",vb->index); } else { /* If the device is disconnected return the buffer to userspace * directly. The next QBUF call will fail with -ENODEV. */ buf->state = UVC_BUF_STATE_ERROR; + uvc_trace(UVC_TRACE_FRAME, "uvc_buffer_queue - will be done with error\n"); vb2_buffer_done(vb, VB2_BUF_STATE_ERROR); } @@ -159,6 +161,8 @@ static void uvc_buffer_finish(struct vb2_buffer *vb) if (vb->state == VB2_BUF_STATE_DONE) uvc_video_clock_update(stream, vbuf, buf); + else // Evgeni + uvc_trace(UVC_TRACE_FRAME, "uvc_buffer_finish - but not DONE (ready for DQBUF), vb->state = %d\n", vb->state); } static int uvc_start_streaming(struct vb2_queue *vq, unsigned int count) @@ -221,6 +225,7 @@ int uvc_queue_init(struct uvc_video_queue *queue, enum v4l2_buf_type type, { int ret; + uvc_trace(UVC_TRACE_FRAME, "uvc_queue_init\n"); queue->queue.type = type; queue->queue.io_modes = VB2_MMAP | VB2_USERPTR; queue->queue.drv_priv = queue; @@ -248,6 +253,8 @@ int uvc_queue_init(struct uvc_video_queue *queue, enum v4l2_buf_type type, spin_lock_init(&queue->irqlock); INIT_LIST_HEAD(&queue->irqqueue); queue->flags = drop_corrupted ? UVC_QUEUE_DROP_CORRUPTED : 0; + uvc_trace(UVC_TRACE_FRAME, "uvc_queue_init: drop_corrupted = %d, uvc flags = %d.\n", + drop_corrupted,queue->flags); return 0; } @@ -481,11 +488,15 @@ static void uvc_queue_buffer_complete(struct kref *ref) if ((queue->flags & UVC_QUEUE_DROP_CORRUPTED) && buf->error) { uvc_queue_buffer_requeue(queue, buf); + uvc_trace(UVC_TRACE_FRAME, "!!! uvc_queue_buffer_requeue called -" + " queue->flags=%x, buf err=%d state=%d",queue->flags,buf->error, buf->state); return; } buf->state = buf->error ? UVC_BUF_STATE_ERROR : UVC_BUF_STATE_DONE; vb2_set_plane_payload(&buf->buf.vb2_buf, 0, buf->bytesused); + uvc_trace(UVC_TRACE_FRAME, "uvc_queue_buffer_complete: state = %d ", + buf->state); vb2_buffer_done(&buf->buf.vb2_buf, VB2_BUF_STATE_DONE); } @@ -509,11 +520,11 @@ struct uvc_buffer *uvc_queue_next_buffer(struct uvc_video_queue *queue, struct uvc_buffer *nextbuf; unsigned long flags; + uvc_printk(KERN_NOTICE, "uvc_queue_next_buffer"); spin_lock_irqsave(&queue->irqlock, flags); list_del(&buf->queue); nextbuf = __uvc_queue_get_current_buffer(queue); spin_unlock_irqrestore(&queue->irqlock, flags); - uvc_queue_buffer_release(buf); return nextbuf; diff --git a/drivers/media/usb/uvc/uvc_video.c b/drivers/media/usb/uvc/uvc_video.c index 8fa77a81dd7f..1cb758d81745 100644 --- a/drivers/media/usb/uvc/uvc_video.c +++ b/drivers/media/usb/uvc/uvc_video.c @@ -875,9 +875,10 @@ static void uvc_video_stats_update(struct uvc_streaming *stream) { struct uvc_stats_frame *frame = &stream->stats.frame; - uvc_trace(UVC_TRACE_STATS, "frame %u stats: %u/%u/%u packets, " + uvc_trace(UVC_TRACE_STATS, "%s frame %u stats: %u/%u/%u packets, " "%u/%u/%u pts (%searly %sinitial), %u/%u scr, " "last pts/stc/sof %u/%u/%u\n", + stream->cur_format->name, stream->sequence, frame->first_data, frame->nb_packets - frame->nb_empty, frame->nb_packets, frame->nb_pts_diffs, frame->last_pts_diff, frame->nb_pts, @@ -1033,14 +1034,15 @@ static int uvc_video_decode_start(struct uvc_streaming *stream, * NULL. */ if (buf == NULL) { + uvc_trace(UVC_TRACE_FRAME, "!!uvc_video_decode_start received empty buf, size=%d, returns ENODATA.\n", len); stream->last_fid = fid; return -ENODATA; } /* Mark the buffer as bad if the error bit is set. */ if (data[1] & UVC_STREAM_ERR) { - uvc_trace(UVC_TRACE_FRAME, "Marking buffer as bad (error bit " - "set).\n"); + uvc_trace(UVC_TRACE_FRAME, "!!uvc_video_decode_start: mark buffer as bad (error bit " + "set)., data[0]=%x, data[1]=%x\n", data[0], data[1]); buf->error = 1; } @@ -1054,12 +1056,20 @@ static int uvc_video_decode_start(struct uvc_streaming *stream, */ if (buf->state != UVC_BUF_STATE_ACTIVE) { if (fid == stream->last_fid) { - uvc_trace(UVC_TRACE_FRAME, "Dropping payload (out of " - "sync).\n"); + uvc_trace(UVC_TRACE_FRAME, "FID idle - buf state is %d.\n", + buf->state); if ((stream->dev->quirks & UVC_QUIRK_STREAM_NO_FID) && (data[1] & UVC_STREAM_EOF)) stream->last_fid ^= UVC_STREAM_FID; - return -ENODATA; + + // if (stream->sequence == buf->buf.sequence) + // { + // uvc_trace(UVC_TRACE_FRAME, "!! Dropping payload out of sync!" + // ", stream->sequence == buf->buf.sequence > %d).\n", + // stream->sequence); + // return -ENODATA; + // } + return -ENODATA; // Evgeni } buf->buf.field = V4L2_FIELD_NONE; @@ -1108,12 +1118,20 @@ static void uvc_video_copy_data_work(struct work_struct *work) struct uvc_urb *uvc_urb = container_of(work, struct uvc_urb, work); unsigned int i; int ret; + static int last_seq = 0; for (i = 0; i < uvc_urb->async_operations; i++) { struct uvc_copy_op *op = &uvc_urb->copy_operations[i]; memcpy(op->dst, op->src, op->len); + // //Evgeni + // if (op->buf->buf.sequence != last_seq) + // { + // last_seq = op->buf->buf.sequence; + // uvc_printk(KERN_NOTICE, "uvc_video_copy_data_work ,vb2 seq id=%d" + // , op->buf->buf.sequence); + // } /* Release reference taken on this buffer. */ uvc_queue_buffer_release(op->buf); } @@ -1148,7 +1166,7 @@ static void uvc_video_decode_data(struct uvc_urb *uvc_urb, /* Complete the current frame if the buffer size was exceeded. */ if (len > maxlen) { - uvc_trace(UVC_TRACE_FRAME, "Frame complete (overflow).\n"); + uvc_trace(UVC_TRACE_FRAME, "!!uvc_video_decode_data: Frame complete (overflow).\n"); buf->error = 1; buf->state = UVC_BUF_STATE_READY; } @@ -1237,11 +1255,17 @@ static void uvc_video_decode_meta(struct uvc_streaming *stream, const u8 *scr; if (!meta_buf || length == 2) + { + uvc_trace(UVC_TRACE_FRAME, "!!! uvc_video_decode_meta - early return due to metabuf-=%d, lenght=%u\n", + meta_buf==NULL, length); return; + } if (meta_buf->length - meta_buf->bytesused < length + sizeof(meta->ns) + sizeof(meta->sof)) { meta_buf->error = 1; + uvc_trace(UVC_TRACE_FRAME, "!!! uvc_video_decode_meta - early return due to mb_len=%u, bytes_used=%u\n", + meta_buf->length, meta_buf->bytesused); return; } @@ -1263,7 +1287,10 @@ static void uvc_video_decode_meta(struct uvc_streaming *stream, if (length == len_std && (!has_scr || !memcmp(scr, stream->clock.last_scr, 6))) + { + uvc_trace(UVC_TRACE_FRAME, "uvc_video_decode_meta - return due to length%lu\n", len_std); return; + } meta = (struct uvc_meta_buf *)((u8 *)meta_buf->mem + meta_buf->bytesused); local_irq_save(flags); @@ -1300,7 +1327,12 @@ static void uvc_video_validate_buffer(const struct uvc_streaming *stream, { if (stream->ctrl.dwMaxVideoFrameSize != buf->bytesused && !(stream->cur_format->flags & UVC_FMT_FLAG_COMPRESSED)) - buf->error = 1; + { + uvc_trace(UVC_TRACE_FRAME, "uvc_video_validate_buffer: set error flag for incomplete buf." + " MaxVideoFrameSize=%u, bytes_used=%u\n", + stream->ctrl.dwMaxVideoFrameSize,buf->bytesused); + buf->error = 1; + } } /* @@ -1322,7 +1354,14 @@ static void uvc_video_next_buffers(struct uvc_streaming *stream, (*meta_buf)->state = UVC_BUF_STATE_READY; if (!(*meta_buf)->error) + { (*meta_buf)->error = (*video_buf)->error; + if ((*meta_buf)->error) + { + uvc_trace(UVC_TRACE_FRAME, "(*meta_buf)->error =%d.\n", + (*meta_buf)->error); + } + } *meta_buf = uvc_queue_next_buffer(&stream->meta.queue, *meta_buf); } @@ -1400,11 +1439,16 @@ static void uvc_video_decode_bulk(struct uvc_urb *uvc_urb, do { ret = uvc_video_decode_start(stream, buf, mem, len); if (ret == -EAGAIN) + { + uvc_trace(UVC_TRACE_VIDEO, "!!Caution: decode start res= %d, polling next\n", ret); uvc_video_next_buffers(stream, &buf, &meta_buf); + } } while (ret == -EAGAIN); /* If an error occurred skip the rest of the payload. */ if (ret < 0 || buf == NULL) { + uvc_trace(UVC_TRACE_VIDEO, "!!Error: going to skip payload due to ret=%d," + " null_buff=%d\n", ret, buf==NULL); stream->bulk.skip_payload = 1; } else { memcpy(stream->bulk.header, mem, ret); @@ -1425,6 +1469,9 @@ static void uvc_video_decode_bulk(struct uvc_urb *uvc_urb, /* Prepare video data for processing. */ if (!stream->bulk.skip_payload && buf != NULL) uvc_video_decode_data(uvc_urb, buf, mem, len); + else + uvc_trace(UVC_TRACE_VIDEO, "!! skipping uvc_video_decode_data," + " skip_payload=%d null_buf=%d\n", stream->bulk.skip_payload, buf == NULL); /* Detect the payload end by a URB smaller than the maximum size (or * a payload size equal to the maximum) and process the header again. @@ -1434,6 +1481,7 @@ static void uvc_video_decode_bulk(struct uvc_urb *uvc_urb, if (!stream->bulk.skip_payload && buf != NULL) { uvc_video_decode_end(stream, buf, stream->bulk.header, stream->bulk.payload_size); + uvc_trace(UVC_TRACE_VIDEO, "uvc_video_decode_ended, buf->state=%d\n", buf->state); if (buf->state == UVC_BUF_STATE_READY) uvc_video_next_buffers(stream, &buf, &meta_buf); } @@ -1501,6 +1549,13 @@ static void uvc_video_complete(struct urb *urb) struct uvc_buffer *buf_meta = NULL; unsigned long flags; int ret; + int sleeps = 0; + + //uvc_printk(KERN_WARNING, "uvc_video_complete, tr_buf_length=%d, actual_ln=%d, packets=%d\n", + // urb->transfer_buffer_length, urb->actual_length, urb->number_of_packets); + + if (urb->status) + uvc_printk(KERN_WARNING, "uvc_video_complete, urb status = %d\n", urb->status); switch (urb->status) { case 0: @@ -1551,6 +1606,11 @@ static void uvc_video_complete(struct urb *urb) return; } + if (NULL==buf) + { + uvc_printk(KERN_WARNING, "!!!! Going for async op eventhough vb2 was empty.\n"); + } + queue_work(stream->async_wq, &uvc_urb->work); } -- 2.17.1