It is hard to analyze trace logs with multiple virtio-blk devices

because none of the trace events include the VirtIODevice *vdev.

This patch adds vdev so it's clear which device a request is associated

with.

I considered using VirtIOBlock *s instead but VirtIODevice *vdev is more

general and may be correlated with generic virtio trace events like

virtio_set_status.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Message-id: 20170614092930.11234-1-stefanha@redhat.com

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

---

hw/block/virtio-blk.c | 12 +++++++-----

hw/block/trace-events | 10 +++++-----

2 files changed, 12 insertions(+), 10 deletions(-)

diff --git a/hw/block/virtio-blk.c b/hw/block/virtio-blk.c

index XXXXXXX..XXXXXXX 100644

--- a/hw/block/virtio-blk.c

+++ b/hw/block/virtio-blk.c

@@ -XXX,XX +XXX,XX @@ static void virtio_blk_req_complete(VirtIOBlockReq *req, unsigned char status)

VirtIOBlock *s = req->dev;

VirtIODevice *vdev = VIRTIO_DEVICE(s);

- trace_virtio_blk_req_complete(req, status);

+ trace_virtio_blk_req_complete(vdev, req, status);

stb_p(&req->in->status, status);

virtqueue_push(req->vq, &req->elem, req->in_len);

@@ -XXX,XX +XXX,XX @@ static void virtio_blk_rw_complete(void *opaque, int ret)

{

VirtIOBlockReq *next = opaque;

VirtIOBlock *s = next->dev;

+ VirtIODevice *vdev = VIRTIO_DEVICE(s);

aio_context_acquire(blk_get_aio_context(s->conf.conf.blk));

while (next) {

VirtIOBlockReq *req = next;

next = req->mr_next;

- trace_virtio_blk_rw_complete(req, ret);

+ trace_virtio_blk_rw_complete(vdev, req, ret);

if (req->qiov.nalloc != -1) {

/* If nalloc is != 1 req->qiov is a local copy of the original

@@ -XXX,XX +XXX,XX @@ static inline void submit_requests(BlockBackend *blk, MultiReqBuffer *mrb,

mrb->reqs[i - 1]->mr_next = mrb->reqs[i];

}

- trace_virtio_blk_submit_multireq(mrb, start, num_reqs,

+ trace_virtio_blk_submit_multireq(VIRTIO_DEVICE(mrb->reqs[start]->dev),

+ mrb, start, num_reqs,

sector_num << BDRV_SECTOR_BITS,

qiov->size, is_write);

block_acct_merge_done(blk_get_stats(blk),

@@ -XXX,XX +XXX,XX @@ static int virtio_blk_handle_request(VirtIOBlockReq *req, MultiReqBuffer *mrb)

if (is_write) {

qemu_iovec_init_external(&req->qiov, iov, out_num);

- trace_virtio_blk_handle_write(req, req->sector_num,

+ trace_virtio_blk_handle_write(vdev, req, req->sector_num,

req->qiov.size / BDRV_SECTOR_SIZE);

} else {

qemu_iovec_init_external(&req->qiov, in_iov, in_num);

- trace_virtio_blk_handle_read(req, req->sector_num,

+ trace_virtio_blk_handle_read(vdev, req, req->sector_num,

req->qiov.size / BDRV_SECTOR_SIZE);

}

diff --git a/hw/block/trace-events b/hw/block/trace-events

index XXXXXXX..XXXXXXX 100644

--- a/hw/block/trace-events

+++ b/hw/block/trace-events

@@ -XXX,XX +XXX,XX @@

# See docs/tracing.txt for syntax documentation.

# hw/block/virtio-blk.c

-virtio_blk_req_complete(void *req, int status) "req %p status %d"

-virtio_blk_rw_complete(void *req, int ret) "req %p ret %d"

-virtio_blk_handle_write(void *req, uint64_t sector, size_t nsectors) "req %p sector %"PRIu64" nsectors %zu"

-virtio_blk_handle_read(void *req, uint64_t sector, size_t nsectors) "req %p sector %"PRIu64" nsectors %zu"

-virtio_blk_submit_multireq(void *mrb, int start, int num_reqs, uint64_t offset, size_t size, bool is_write) "mrb %p start %d num_reqs %d offset %"PRIu64" size %zu is_write %d"

+virtio_blk_req_complete(void *vdev, void *req, int status) "vdev %p req %p status %d"

+virtio_blk_rw_complete(void *vdev, void *req, int ret) "vdev %p req %p ret %d"

+virtio_blk_handle_write(void *vdev, void *req, uint64_t sector, size_t nsectors) "vdev %p req %p sector %"PRIu64" nsectors %zu"

+virtio_blk_handle_read(void *vdev, void *req, uint64_t sector, size_t nsectors) "vdev %p req %p sector %"PRIu64" nsectors %zu"

+virtio_blk_submit_multireq(void *vdev, void *mrb, int start, int num_reqs, uint64_t offset, size_t size, bool is_write) "vdev %p mrb %p start %d num_reqs %d offset %"PRIu64" size %zu is_write %d"

# hw/block/hd-geometry.c

hd_geometry_lchs_guess(void *blk, int cyls, int heads, int secs) "blk %p LCHS %d %d %d"

--

2.9.4

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Michael S. Tsirkin <mst@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Tested-by: Eric Blake <eblake@redhat.com>

Tested-by: Kevin Wolf <kwolf@redhat.com>

Message-id: 20170628184724.21378-2-stefanha@redhat.com

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

---

tests/libqos/virtio.h | 2 +-

1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/libqos/virtio.h b/tests/libqos/virtio.h

index XXXXXXX..XXXXXXX 100644

--- a/tests/libqos/virtio.h

+++ b/tests/libqos/virtio.h

@@ -XXX,XX +XXX,XX @@ typedef struct QVirtioDevice {

typedef struct QVirtQueue {

uint64_t desc; /* This points to an array of struct vring_desc */

uint64_t avail; /* This points to a struct vring_avail */

- uint64_t used; /* This points to a struct vring_desc */

+ uint64_t used; /* This points to a struct vring_used */

uint16_t index;

uint32_t size;

uint32_t free_head;

--

2.9.4

Existing tests do not touch the virtqueue used ring. Instead they poll

the virtqueue ISR register and peek into their request's device-specific

status field.

It turns out that the virtqueue ISR register can be set to 1 more than

once for a single notification (see commit

83d768b5640946b7da55ce8335509df297e2c7cd "virtio: set ISR on dataplane

notifications"). This causes problems for tests that assume a 1:1

correspondence between the ISR being 1 and request completion.

Peeking at device-specific status fields is also problematic if the

device has no field that can be abused for EINPROGRESS polling

semantics. This is the case if all the field's values may be set by the

device; there's no magic constant left for polling.

It's time to process the used ring for completed requests, just like a

real virtio guest driver. This patch adds the necessary APIs.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Michael S. Tsirkin <mst@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Tested-by: Eric Blake <eblake@redhat.com>

Tested-by: Kevin Wolf <kwolf@redhat.com>

Message-id: 20170628184724.21378-3-stefanha@redhat.com

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

---

tests/libqos/virtio.h | 6 ++++++

tests/libqos/virtio.c | 60 +++++++++++++++++++++++++++++++++++++++++++++++++++

2 files changed, 66 insertions(+)

diff --git a/tests/libqos/virtio.h b/tests/libqos/virtio.h

index XXXXXXX..XXXXXXX 100644

--- a/tests/libqos/virtio.h

+++ b/tests/libqos/virtio.h

@@ -XXX,XX +XXX,XX @@ typedef struct QVirtQueue {

uint32_t free_head;

uint32_t num_free;

uint32_t align;

+ uint16_t last_used_idx;

bool indirect;

bool event;

} QVirtQueue;

@@ -XXX,XX +XXX,XX @@ uint8_t qvirtio_wait_status_byte_no_isr(QVirtioDevice *d,

QVirtQueue *vq,

uint64_t addr,

gint64 timeout_us);

+void qvirtio_wait_used_elem(QVirtioDevice *d,

+ QVirtQueue *vq,

+ uint32_t desc_idx,

+ gint64 timeout_us);

void qvirtio_wait_config_isr(QVirtioDevice *d, gint64 timeout_us);

QVirtQueue *qvirtqueue_setup(QVirtioDevice *d,

QGuestAllocator *alloc, uint16_t index);

@@ -XXX,XX +XXX,XX @@ uint32_t qvirtqueue_add(QVirtQueue *vq, uint64_t data, uint32_t len, bool write,

bool next);

uint32_t qvirtqueue_add_indirect(QVirtQueue *vq, QVRingIndirectDesc *indirect);

void qvirtqueue_kick(QVirtioDevice *d, QVirtQueue *vq, uint32_t free_head);

+bool qvirtqueue_get_buf(QVirtQueue *vq, uint32_t *desc_idx);

void qvirtqueue_set_used_event(QVirtQueue *vq, uint16_t idx);

#endif

diff --git a/tests/libqos/virtio.c b/tests/libqos/virtio.c

index XXXXXXX..XXXXXXX 100644

--- a/tests/libqos/virtio.c

+++ b/tests/libqos/virtio.c

@@ -XXX,XX +XXX,XX @@ uint8_t qvirtio_wait_status_byte_no_isr(QVirtioDevice *d,

return val;

}

+/*

+ * qvirtio_wait_used_elem:

+ * @desc_idx: The next expected vq->desc[] index in the used ring

+ * @timeout_us: How many microseconds to wait before failing

+ *

+ * This function waits for the next completed request on the used ring.

+ */

+void qvirtio_wait_used_elem(QVirtioDevice *d,

+ QVirtQueue *vq,

+ uint32_t desc_idx,

+ gint64 timeout_us)

+{

+ gint64 start_time = g_get_monotonic_time();

+

+ for (;;) {

+ uint32_t got_desc_idx;

+

+ clock_step(100);

+

+ if (d->bus->get_queue_isr_status(d, vq) &&

+ qvirtqueue_get_buf(vq, &got_desc_idx)) {

+ g_assert_cmpint(got_desc_idx, ==, desc_idx);

+ return;

+ }

+

+ g_assert(g_get_monotonic_time() - start_time <= timeout_us);

+ }

+}

+

void qvirtio_wait_config_isr(QVirtioDevice *d, gint64 timeout_us)

{

gint64 start_time = g_get_monotonic_time();

@@ -XXX,XX +XXX,XX @@ void qvirtqueue_kick(QVirtioDevice *d, QVirtQueue *vq, uint32_t free_head)

}

}

+/*

+ * qvirtqueue_get_buf:

+ * @desc_idx: A pointer that is filled with the vq->desc[] index, may be NULL

+ *

+ * This function gets the next used element if there is one ready.

+ *

+ * Returns: true if an element was ready, false otherwise

+ */

+bool qvirtqueue_get_buf(QVirtQueue *vq, uint32_t *desc_idx)

+{

+ uint16_t idx;

+

+ idx = readw(vq->used + offsetof(struct vring_used, idx));

+ if (idx == vq->last_used_idx) {

+ return false;

+ }

+

+ if (desc_idx) {

+ uint64_t elem_addr;

+

+ elem_addr = vq->used +

+ offsetof(struct vring_used, ring) +

+ (vq->last_used_idx % vq->size) *

+ sizeof(struct vring_used_elem);

+ *desc_idx = readl(elem_addr + offsetof(struct vring_used_elem, id));

+ }

+

+ vq->last_used_idx++;

+ return true;

+}

+

void qvirtqueue_set_used_event(QVirtQueue *vq, uint16_t idx)

{

g_assert(vq->event);

--

2.9.4

Use the new used ring APIs instead of assuming ISR being set means the

request has completed.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Michael S. Tsirkin <mst@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Tested-by: Eric Blake <eblake@redhat.com>

Tested-by: Kevin Wolf <kwolf@redhat.com>

Message-id: 20170628184724.21378-4-stefanha@redhat.com

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

---

tests/virtio-scsi-test.c | 2 +-

1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/virtio-scsi-test.c b/tests/virtio-scsi-test.c

index XXXXXXX..XXXXXXX 100644

--- a/tests/virtio-scsi-test.c

+++ b/tests/virtio-scsi-test.c

@@ -XXX,XX +XXX,XX @@ static uint8_t virtio_scsi_do_command(QVirtIOSCSI *vs, const uint8_t *cdb,

}

qvirtqueue_kick(vs->dev, vq, free_head);

- qvirtio_wait_queue_isr(vs->dev, vq, QVIRTIO_SCSI_TIMEOUT_US);

+ qvirtio_wait_used_elem(vs->dev, vq, free_head, QVIRTIO_SCSI_TIMEOUT_US);

response = readb(resp_addr +

offsetof(struct virtio_scsi_cmd_resp, response));

--

2.9.4

Use the new used ring APIs instead of assuming ISR being set means the

request has completed.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Michael S. Tsirkin <mst@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Tested-by: Eric Blake <eblake@redhat.com>

Tested-by: Kevin Wolf <kwolf@redhat.com>

Message-id: 20170628184724.21378-5-stefanha@redhat.com

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

---

tests/virtio-blk-test.c | 27 +++++++++++++++++----------

1 file changed, 17 insertions(+), 10 deletions(-)

diff --git a/tests/virtio-blk-test.c b/tests/virtio-blk-test.c

index XXXXXXX..XXXXXXX 100644

--- a/tests/virtio-blk-test.c

+++ b/tests/virtio-blk-test.c

@@ -XXX,XX +XXX,XX @@ static void test_basic(QVirtioDevice *dev, QGuestAllocator *alloc,

qvirtqueue_kick(dev, vq, free_head);

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_BLK_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

@@ -XXX,XX +XXX,XX @@ static void test_basic(QVirtioDevice *dev, QGuestAllocator *alloc,

qvirtqueue_kick(dev, vq, free_head);

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_BLK_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

@@ -XXX,XX +XXX,XX @@ static void test_basic(QVirtioDevice *dev, QGuestAllocator *alloc,

qvirtqueue_add(vq, req_addr + 528, 1, true, false);

qvirtqueue_kick(dev, vq, free_head);

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_BLK_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

@@ -XXX,XX +XXX,XX @@ static void test_basic(QVirtioDevice *dev, QGuestAllocator *alloc,

qvirtqueue_kick(dev, vq, free_head);

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_BLK_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

@@ -XXX,XX +XXX,XX @@ static void pci_indirect(void)

free_head = qvirtqueue_add_indirect(&vqpci->vq, indirect);

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

- qvirtio_wait_queue_isr(&dev->vdev, &vqpci->vq,

+ qvirtio_wait_used_elem(&dev->vdev, &vqpci->vq, free_head,

QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

@@ -XXX,XX +XXX,XX @@ static void pci_indirect(void)

free_head = qvirtqueue_add_indirect(&vqpci->vq, indirect);

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

- qvirtio_wait_queue_isr(&dev->vdev, &vqpci->vq,

+ qvirtio_wait_used_elem(&dev->vdev, &vqpci->vq, free_head,

QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

@@ -XXX,XX +XXX,XX @@ static void pci_msix(void)

qvirtqueue_add(&vqpci->vq, req_addr + 528, 1, true, false);

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

- qvirtio_wait_queue_isr(&dev->vdev, &vqpci->vq,

+ qvirtio_wait_used_elem(&dev->vdev, &vqpci->vq, free_head,

QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

@@ -XXX,XX +XXX,XX @@ static void pci_msix(void)

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

- qvirtio_wait_queue_isr(&dev->vdev, &vqpci->vq,

+ qvirtio_wait_used_elem(&dev->vdev, &vqpci->vq, free_head,

QVIRTIO_BLK_TIMEOUT_US);

status = readb(req_addr + 528);

@@ -XXX,XX +XXX,XX @@ static void pci_idx(void)

uint64_t capacity;

uint32_t features;

uint32_t free_head;

+ uint32_t write_head;

+ uint32_t desc_idx;

uint8_t status;

char *data;

@@ -XXX,XX +XXX,XX @@ static void pci_idx(void)

qvirtqueue_add(&vqpci->vq, req_addr + 528, 1, true, false);

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

- qvirtio_wait_queue_isr(&dev->vdev, &vqpci->vq, QVIRTIO_BLK_TIMEOUT_US);

+ qvirtio_wait_used_elem(&dev->vdev, &vqpci->vq, free_head,

+ QVIRTIO_BLK_TIMEOUT_US);

/* Write request */

req.type = VIRTIO_BLK_T_OUT;

@@ -XXX,XX +XXX,XX @@ static void pci_idx(void)

qvirtqueue_add(&vqpci->vq, req_addr + 16, 512, false, true);

qvirtqueue_add(&vqpci->vq, req_addr + 528, 1, true, false);

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

+ write_head = free_head;

/* No notification expected */

status = qvirtio_wait_status_byte_no_isr(&dev->vdev,

@@ -XXX,XX +XXX,XX @@ static void pci_idx(void)

qvirtqueue_kick(&dev->vdev, &vqpci->vq, free_head);

- qvirtio_wait_queue_isr(&dev->vdev, &vqpci->vq,

+ /* We get just one notification for both requests */

+ qvirtio_wait_used_elem(&dev->vdev, &vqpci->vq, write_head,

QVIRTIO_BLK_TIMEOUT_US);

+ g_assert(qvirtqueue_get_buf(&vqpci->vq, &desc_idx));

+ g_assert_cmpint(desc_idx, ==, free_head);

status = readb(req_addr + 528);

g_assert_cmpint(status, ==, 0);

--

2.9.4

Use the new used ring APIs instead of assuming ISR being set means the

request has completed.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Michael S. Tsirkin <mst@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Tested-by: Eric Blake <eblake@redhat.com>

Tested-by: Kevin Wolf <kwolf@redhat.com>

Message-id: 20170628184724.21378-6-stefanha@redhat.com

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

---

tests/virtio-net-test.c | 6 +++---

1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/tests/virtio-net-test.c b/tests/virtio-net-test.c

index XXXXXXX..XXXXXXX 100644

--- a/tests/virtio-net-test.c

+++ b/tests/virtio-net-test.c

@@ -XXX,XX +XXX,XX @@ static void rx_test(QVirtioDevice *dev,

ret = iov_send(socket, iov, 2, 0, sizeof(len) + sizeof(test));

g_assert_cmpint(ret, ==, sizeof(test) + sizeof(len));

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_NET_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_NET_TIMEOUT_US);

memread(req_addr + VNET_HDR_SIZE, buffer, sizeof(test));

g_assert_cmpstr(buffer, ==, "TEST");

@@ -XXX,XX +XXX,XX @@ static void tx_test(QVirtioDevice *dev,

free_head = qvirtqueue_add(vq, req_addr, 64, false, false);

qvirtqueue_kick(dev, vq, free_head);

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_NET_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_NET_TIMEOUT_US);

guest_free(alloc, req_addr);

ret = qemu_recv(socket, &len, sizeof(len), 0);

@@ -XXX,XX +XXX,XX @@ static void rx_stop_cont_test(QVirtioDevice *dev,

rsp = qmp("{ 'execute' : 'cont'}");

QDECREF(rsp);

- qvirtio_wait_queue_isr(dev, vq, QVIRTIO_NET_TIMEOUT_US);

+ qvirtio_wait_used_elem(dev, vq, free_head, QVIRTIO_NET_TIMEOUT_US);

memread(req_addr + VNET_HDR_SIZE, buffer, sizeof(test));

g_assert_cmpstr(buffer, ==, "TEST");

--

2.9.4