Re: [Qemu-block] [PATCH v5] nvme: Add tracing

2017-11-24 Thread Doug Gale
Ping

On Thu, Nov 16, 2017 at 6:16 AM, Doug Gale  wrote:
> I submitted it with git Nov 3 - the long lines issue with git-am
> should be resolved. Please let me know if there's still a problem.
>
> Thanks.
>
>
> On Fri, Nov 3, 2017 at 11:58 AM, Philippe Mathieu-Daudé  
> wrote:
>> Cc'ing Trivial ;)
>>
>> On 11/03/2017 10:37 AM, Doug Gale wrote:
>>> Add trace output for commands, errors, and undefined behavior.
>>> Add guest error log output for undefined behavior.
>>> Report invalid undefined accesses to MMIO.
>>> Annotate unlikely error checks with unlikely.
>>>
>>> Signed-off-by: Doug Gale 
>>> Reviewed-by: Philippe Mathieu-Daudé 
>>> Reviewed-by: Stefan Hajnoczi 
>>> ---
>>> changes v4 -> v5: add R-b tags
>>>  hw/block/nvme.c   | 349 
>>> ++
>>>  hw/block/trace-events |  93 ++
>>>  2 files changed, 390 insertions(+), 52 deletions(-)
>>>
>>> diff --git a/hw/block/nvme.c b/hw/block/nvme.c
>>> index 441e21ed1f..4d98ed9fba 100644
>>> --- a/hw/block/nvme.c
>>> +++ b/hw/block/nvme.c
>>> @@ -34,8 +34,17 @@
>>>  #include "qapi/visitor.h"
>>>  #include "sysemu/block-backend.h"
>>>
>>> +#include "qemu/log.h"
>>> +#include "trace.h"
>>>  #include "nvme.h"
>>>
>>> +#define NVME_GUEST_ERR(trace, fmt, ...) \
>>> +do { \
>>> +(trace_##trace)(__VA_ARGS__); \
>>> +qemu_log_mask(LOG_GUEST_ERROR, #trace \
>>> +" in %s: " fmt "\n", __func__, ## __VA_ARGS__); \
>>> +} while (0)
>>> +
>>>  static void nvme_process_sq(void *opaque);
>>>
>>>  static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
>>> @@ -86,10 +95,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue *cq)
>>>  {
>>>  if (cq->irq_enabled) {
>>>  if (msix_enabled(&(n->parent_obj))) {
>>> +trace_nvme_irq_msix(cq->vector);
>>>  msix_notify(&(n->parent_obj), cq->vector);
>>>  } else {
>>> +trace_nvme_irq_pin();
>>>  pci_irq_pulse(&n->parent_obj);
>>>  }
>>> +} else {
>>> +trace_nvme_irq_masked();
>>>  }
>>>  }
>>>
>>> @@ -100,7 +113,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, 
>>> QEMUIOVector *iov, uint64_t prp1,
>>>  trans_len = MIN(len, trans_len);
>>>  int num_prps = (len >> n->page_bits) + 1;
>>>
>>> -if (!prp1) {
>>> +if (unlikely(!prp1)) {
>>> +trace_nvme_err_invalid_prp();
>>>  return NVME_INVALID_FIELD | NVME_DNR;
>>>  } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
>>> prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size)) {
>>> @@ -113,7 +127,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, 
>>> QEMUIOVector *iov, uint64_t prp1,
>>>  }
>>>  len -= trans_len;
>>>  if (len) {
>>> -if (!prp2) {
>>> +if (unlikely(!prp2)) {
>>> +trace_nvme_err_invalid_prp2_missing();
>>>  goto unmap;
>>>  }
>>>  if (len > n->page_size) {
>>> @@ -128,7 +143,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, 
>>> QEMUIOVector *iov, uint64_t prp1,
>>>  uint64_t prp_ent = le64_to_cpu(prp_list[i]);
>>>
>>>  if (i == n->max_prp_ents - 1 && len > n->page_size) {
>>> -if (!prp_ent || prp_ent & (n->page_size - 1)) {
>>> +if (unlikely(!prp_ent || prp_ent & (n->page_size - 
>>> 1))) {
>>> +trace_nvme_err_invalid_prplist_ent(prp_ent);
>>>  goto unmap;
>>>  }
>>>
>>> @@ -140,7 +156,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, 
>>> QEMUIOVector *iov, uint64_t prp1,
>>>  prp_ent = le64_to_cpu(prp_list[i]);
>>>  }
>>>
>>> -if (!prp_ent || prp_ent & (n->page_size - 1)) {
>>> +if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
>>> +tr

[Qemu-block] [PATCH] nvme: Add tracing

2017-11-03 Thread Doug Gale
Add trace output for commands, errors, and undefined behavior.
Add guest error log output for undefined behavior.
Report invalid undefined accesses to MMIO.
Annotate unlikely error checks with unlikely.

Signed-off-by: Doug Gale 
---
 hw/block/nvme.c   | 349 ++
 hw/block/trace-events |  93 ++
 2 files changed, 390 insertions(+), 52 deletions(-)

diff --git a/hw/block/nvme.c b/hw/block/nvme.c
index 441e21ed1f..4d98ed9fba 100644
--- a/hw/block/nvme.c
+++ b/hw/block/nvme.c
@@ -34,8 +34,17 @@
 #include "qapi/visitor.h"
 #include "sysemu/block-backend.h"
 
+#include "qemu/log.h"
+#include "trace.h"
 #include "nvme.h"
 
+#define NVME_GUEST_ERR(trace, fmt, ...) \
+do { \
+(trace_##trace)(__VA_ARGS__); \
+qemu_log_mask(LOG_GUEST_ERROR, #trace \
+" in %s: " fmt "\n", __func__, ## __VA_ARGS__); \
+} while (0)
+
 static void nvme_process_sq(void *opaque);
 
 static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
@@ -86,10 +95,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue *cq)
 {
 if (cq->irq_enabled) {
 if (msix_enabled(&(n->parent_obj))) {
+trace_nvme_irq_msix(cq->vector);
 msix_notify(&(n->parent_obj), cq->vector);
 } else {
+trace_nvme_irq_pin();
 pci_irq_pulse(&n->parent_obj);
 }
+} else {
+trace_nvme_irq_masked();
 }
 }
 
@@ -100,7 +113,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, QEMUIOVector 
*iov, uint64_t prp1,
 trans_len = MIN(len, trans_len);
 int num_prps = (len >> n->page_bits) + 1;
 
-if (!prp1) {
+if (unlikely(!prp1)) {
+trace_nvme_err_invalid_prp();
 return NVME_INVALID_FIELD | NVME_DNR;
 } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size)) {
@@ -113,7 +127,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, QEMUIOVector 
*iov, uint64_t prp1,
 }
 len -= trans_len;
 if (len) {
-if (!prp2) {
+if (unlikely(!prp2)) {
+trace_nvme_err_invalid_prp2_missing();
 goto unmap;
 }
 if (len > n->page_size) {
@@ -128,7 +143,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, QEMUIOVector 
*iov, uint64_t prp1,
 uint64_t prp_ent = le64_to_cpu(prp_list[i]);
 
 if (i == n->max_prp_ents - 1 && len > n->page_size) {
-if (!prp_ent || prp_ent & (n->page_size - 1)) {
+if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
+trace_nvme_err_invalid_prplist_ent(prp_ent);
 goto unmap;
 }
 
@@ -140,7 +156,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, QEMUIOVector 
*iov, uint64_t prp1,
 prp_ent = le64_to_cpu(prp_list[i]);
 }
 
-if (!prp_ent || prp_ent & (n->page_size - 1)) {
+if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
+trace_nvme_err_invalid_prplist_ent(prp_ent);
 goto unmap;
 }
 
@@ -154,7 +171,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg, QEMUIOVector 
*iov, uint64_t prp1,
 i++;
 }
 } else {
-if (prp2 & (n->page_size - 1)) {
+if (unlikely(prp2 & (n->page_size - 1))) {
+trace_nvme_err_invalid_prp2_align(prp2);
 goto unmap;
 }
 if (qsg->nsg) {
@@ -178,16 +196,20 @@ static uint16_t nvme_dma_read_prp(NvmeCtrl *n, uint8_t 
*ptr, uint32_t len,
 QEMUIOVector iov;
 uint16_t status = NVME_SUCCESS;
 
+trace_nvme_dma_read(prp1, prp2);
+
 if (nvme_map_prp(&qsg, &iov, prp1, prp2, len, n)) {
 return NVME_INVALID_FIELD | NVME_DNR;
 }
 if (qsg.nsg > 0) {
-if (dma_buf_read(ptr, len, &qsg)) {
+if (unlikely(dma_buf_read(ptr, len, &qsg))) {
+trace_nvme_err_invalid_dma();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_sglist_destroy(&qsg);
 } else {
-if (qemu_iovec_to_buf(&iov, 0, ptr, len) != len) {
+if (unlikely(qemu_iovec_to_buf(&iov, 0, ptr, len) != len)) {
+trace_nvme_err_invalid_dma();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_iovec_destroy(&iov);
@@ -273,7 +295,8 @@ static uint16_t nvme_write_zeros(NvmeCtrl *n, NvmeNamespace 
*ns, NvmeCmd *cmd,
 uint64_t aio_slba = slba << (data_shift - BDRV_SECTOR_BITS);
 uint32_t aio_nlb = nlb << (data_shift - BDRV_SECTOR_BITS);
 
-if (slba + nlb > ns->id_ns.nsze) {
+if (unlikely

[Qemu-block] [PATCH v4] nvme: Add tracing

2017-10-30 Thread Doug Gale
>From 0e27b5dca8f4f32a1b194e1b3544be77dd4f45d9 Mon Sep 17 00:00:00 2001
From: Doug Gale 
Date: Mon, 30 Oct 2017 09:28:43 -0400
Subject: [PATCH] nvme: Add tracing

Add trace output for commands, errors, and undefined behavior.
Add guest error log output for undefined behavior.
Report invalid undefined accesses to MMIO.
Annotate unlikely error checks with unlikely.

Signed-off-by: Doug Gale 
---
 hw/block/nvme.c   | 349 ++
 hw/block/trace-events |  93 ++
 2 files changed, 390 insertions(+), 52 deletions(-)

diff --git a/hw/block/nvme.c b/hw/block/nvme.c
index 441e21ed1f..4d98ed9fba 100644
--- a/hw/block/nvme.c
+++ b/hw/block/nvme.c
@@ -34,8 +34,17 @@
 #include "qapi/visitor.h"
 #include "sysemu/block-backend.h"

+#include "qemu/log.h"
+#include "trace.h"
 #include "nvme.h"

+#define NVME_GUEST_ERR(trace, fmt, ...) \
+do { \
+(trace_##trace)(__VA_ARGS__); \
+qemu_log_mask(LOG_GUEST_ERROR, #trace \
+" in %s: " fmt "\n", __func__, ## __VA_ARGS__); \
+} while (0)
+
 static void nvme_process_sq(void *opaque);

 static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
@@ -86,10 +95,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue *cq)
 {
 if (cq->irq_enabled) {
 if (msix_enabled(&(n->parent_obj))) {
+trace_nvme_irq_msix(cq->vector);
 msix_notify(&(n->parent_obj), cq->vector);
 } else {
+trace_nvme_irq_pin();
 pci_irq_pulse(&n->parent_obj);
 }
+} else {
+trace_nvme_irq_masked();
 }
 }

@@ -100,7 +113,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 trans_len = MIN(len, trans_len);
 int num_prps = (len >> n->page_bits) + 1;

-if (!prp1) {
+if (unlikely(!prp1)) {
+trace_nvme_err_invalid_prp();
 return NVME_INVALID_FIELD | NVME_DNR;
 } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size)) {
@@ -113,7 +127,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 }
 len -= trans_len;
 if (len) {
-if (!prp2) {
+if (unlikely(!prp2)) {
+trace_nvme_err_invalid_prp2_missing();
 goto unmap;
 }
 if (len > n->page_size) {
@@ -128,7 +143,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 uint64_t prp_ent = le64_to_cpu(prp_list[i]);

 if (i == n->max_prp_ents - 1 && len > n->page_size) {
-if (!prp_ent || prp_ent & (n->page_size - 1)) {
+if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
+trace_nvme_err_invalid_prplist_ent(prp_ent);
 goto unmap;
 }

@@ -140,7 +156,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 prp_ent = le64_to_cpu(prp_list[i]);
 }

-if (!prp_ent || prp_ent & (n->page_size - 1)) {
+if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
+trace_nvme_err_invalid_prplist_ent(prp_ent);
 goto unmap;
 }

@@ -154,7 +171,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 i++;
 }
 } else {
-if (prp2 & (n->page_size - 1)) {
+if (unlikely(prp2 & (n->page_size - 1))) {
+trace_nvme_err_invalid_prp2_align(prp2);
 goto unmap;
 }
 if (qsg->nsg) {
@@ -178,16 +196,20 @@ static uint16_t nvme_dma_read_prp(NvmeCtrl *n,
uint8_t *ptr, uint32_t len,
 QEMUIOVector iov;
 uint16_t status = NVME_SUCCESS;

+trace_nvme_dma_read(prp1, prp2);
+
 if (nvme_map_prp(&qsg, &iov, prp1, prp2, len, n)) {
 return NVME_INVALID_FIELD | NVME_DNR;
 }
 if (qsg.nsg > 0) {
-if (dma_buf_read(ptr, len, &qsg)) {
+if (unlikely(dma_buf_read(ptr, len, &qsg))) {
+trace_nvme_err_invalid_dma();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_sglist_destroy(&qsg);
 } else {
-if (qemu_iovec_to_buf(&iov, 0, ptr, len) != len) {
+if (unlikely(qemu_iovec_to_buf(&iov, 0, ptr, len) != len)) {
+trace_nvme_err_invalid_dma();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_iovec_destroy(&iov);
@@ -273,7 +295,8 @@ static uint16_t nvme_write_zeros(NvmeCtrl *n,
NvmeNamespace *ns, NvmeCmd *cmd,
 uint64_t aio_slba = slba << (data_shift - BDRV

Re: [Qemu-block] nvme: Add tracing v3

2017-10-30 Thread Doug Gale
On Fri, Oct 20, 2017 at 4:11 PM, Doug Gale  wrote:

> On Thu, Oct 12, 2017 at 3:07 PM, Doug Gale  wrote:
>
>> From c7f12a5949458fdd195b5e0b52f158e8f114f203 Mon Sep 17 00:00:00 2001
>> From: Doug Gale 
>> Date: Thu, 12 Oct 2017 14:29:07 -0400
>> Subject: [PATCH] nvme: Add tracing
>>
>> Add trace output for commands, errors, and undefined behavior.
>> Add guest error log output for undefined behavior.
>> Report and ignore invalid undefined accesses to MMIO.
>> Annotate unlikely error checks with unlikely.
>>
>> Signed-off-by: Doug Gale 
>> ---
>>  hw/block/nvme.c   | 347 ++
>> 
>>  hw/block/trace-events |  93 ++
>>  2 files changed, 387 insertions(+), 53 deletions(-)
>>
>> diff --git a/hw/block/nvme.c b/hw/block/nvme.c
>> index 9aa32692a3..adac19f5b0 100644
>> --- a/hw/block/nvme.c
>> +++ b/hw/block/nvme.c
>> @@ -34,8 +34,17 @@
>>  #include "qapi/visitor.h"
>>  #include "sysemu/block-backend.h"
>>
>> +#include "qemu/log.h"
>> +#include "trace.h"
>>  #include "nvme.h"
>>
>> +#define NVME_GUEST_ERR(trace, fmt, ...) \
>> +do { \
>> +(trace_##trace)(__VA_ARGS__); \
>> +qemu_log_mask(LOG_GUEST_ERROR, #trace \
>> +" in %s: " fmt "\n", __func__, ## __VA_ARGS__); \
>> +} while (0)
>> +
>>  static void nvme_process_sq(void *opaque);
>>
>>  static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
>> @@ -86,10 +95,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue
>> *cq)
>>  {
>>  if (cq->irq_enabled) {
>>  if (msix_enabled(&(n->parent_obj))) {
>> +trace_nvme_irq_msix(cq->vector);
>>  msix_notify(&(n->parent_obj), cq->vector);
>>  } else {
>> +trace_nvme_irq_pin();
>>  pci_irq_pulse(&n->parent_obj);
>>  }
>> +} else {
>> +trace_nvme_irq_masked();
>>  }
>>  }
>>
>> @@ -100,7 +113,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
>> QEMUIOVector *iov, uint64_t prp1,
>>  trans_len = MIN(len, trans_len);
>>  int num_prps = (len >> n->page_bits) + 1;
>>
>> -if (!prp1) {
>> +if (unlikely(!prp1)) {
>> +trace_nvme_err_invalid_prp();
>>  return NVME_INVALID_FIELD | NVME_DNR;
>>  } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
>> prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size))
>> {
>> @@ -113,7 +127,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
>> QEMUIOVector *iov, uint64_t prp1,
>>  }
>>  len -= trans_len;
>>  if (len) {
>> -if (!prp2) {
>> +if (unlikely(!prp2)) {
>> +trace_nvme_err_invalid_prp2_missing();
>>  goto unmap;
>>  }
>>  if (len > n->page_size) {
>> @@ -128,7 +143,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
>> QEMUIOVector *iov, uint64_t prp1,
>>  uint64_t prp_ent = le64_to_cpu(prp_list[i]);
>>
>>  if (i == n->max_prp_ents - 1 && len > n->page_size) {
>> -if (!prp_ent || prp_ent & (n->page_size - 1)) {
>> +if (unlikely(!prp_ent || prp_ent & (n->page_size -
>> 1))) {
>> +trace_nvme_err_invalid_prplist_ent(prp_ent);
>>  goto unmap;
>>  }
>>
>> @@ -140,7 +156,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
>> QEMUIOVector *iov, uint64_t prp1,
>>  prp_ent = le64_to_cpu(prp_list[i]);
>>  }
>>
>> -if (!prp_ent || prp_ent & (n->page_size - 1)) {
>> +if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
>> +trace_nvme_err_invalid_prplist_ent(prp_ent);
>>  goto unmap;
>>  }
>>
>> @@ -154,7 +171,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
>> QEMUIOVector *iov, uint64_t prp1,
>>  i++;
>>  }
>>  } else {
>> -if (prp2 & (n->page_size - 1)) {
>> +if (unlikely(prp2 & (n->page_size - 1))) {
>> +trace_nvme_err_invalid_prp2_align(prp2);
>>  goto unma

Re: [Qemu-block] nvme: Add tracing v3

2017-10-20 Thread Doug Gale
On Thu, Oct 12, 2017 at 3:07 PM, Doug Gale  wrote:

> From c7f12a5949458fdd195b5e0b52f158e8f114f203 Mon Sep 17 00:00:00 2001
> From: Doug Gale 
> Date: Thu, 12 Oct 2017 14:29:07 -0400
> Subject: [PATCH] nvme: Add tracing
>
> Add trace output for commands, errors, and undefined behavior.
> Add guest error log output for undefined behavior.
> Report and ignore invalid undefined accesses to MMIO.
> Annotate unlikely error checks with unlikely.
>
> Signed-off-by: Doug Gale 
> ---
>  hw/block/nvme.c   | 347 ++
> 
>  hw/block/trace-events |  93 ++
>  2 files changed, 387 insertions(+), 53 deletions(-)
>
> diff --git a/hw/block/nvme.c b/hw/block/nvme.c
> index 9aa32692a3..adac19f5b0 100644
> --- a/hw/block/nvme.c
> +++ b/hw/block/nvme.c
> @@ -34,8 +34,17 @@
>  #include "qapi/visitor.h"
>  #include "sysemu/block-backend.h"
>
> +#include "qemu/log.h"
> +#include "trace.h"
>  #include "nvme.h"
>
> +#define NVME_GUEST_ERR(trace, fmt, ...) \
> +do { \
> +(trace_##trace)(__VA_ARGS__); \
> +qemu_log_mask(LOG_GUEST_ERROR, #trace \
> +" in %s: " fmt "\n", __func__, ## __VA_ARGS__); \
> +} while (0)
> +
>  static void nvme_process_sq(void *opaque);
>
>  static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
> @@ -86,10 +95,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue
> *cq)
>  {
>  if (cq->irq_enabled) {
>  if (msix_enabled(&(n->parent_obj))) {
> +trace_nvme_irq_msix(cq->vector);
>  msix_notify(&(n->parent_obj), cq->vector);
>  } else {
> +trace_nvme_irq_pin();
>  pci_irq_pulse(&n->parent_obj);
>  }
> +} else {
> +trace_nvme_irq_masked();
>  }
>  }
>
> @@ -100,7 +113,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
> QEMUIOVector *iov, uint64_t prp1,
>  trans_len = MIN(len, trans_len);
>  int num_prps = (len >> n->page_bits) + 1;
>
> -if (!prp1) {
> +if (unlikely(!prp1)) {
> +trace_nvme_err_invalid_prp();
>  return NVME_INVALID_FIELD | NVME_DNR;
>  } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
> prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size))
> {
> @@ -113,7 +127,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
> QEMUIOVector *iov, uint64_t prp1,
>  }
>  len -= trans_len;
>  if (len) {
> -if (!prp2) {
> +if (unlikely(!prp2)) {
> +trace_nvme_err_invalid_prp2_missing();
>  goto unmap;
>  }
>  if (len > n->page_size) {
> @@ -128,7 +143,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
> QEMUIOVector *iov, uint64_t prp1,
>  uint64_t prp_ent = le64_to_cpu(prp_list[i]);
>
>  if (i == n->max_prp_ents - 1 && len > n->page_size) {
> -if (!prp_ent || prp_ent & (n->page_size - 1)) {
> +if (unlikely(!prp_ent || prp_ent & (n->page_size -
> 1))) {
> +trace_nvme_err_invalid_prplist_ent(prp_ent);
>  goto unmap;
>  }
>
> @@ -140,7 +156,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
> QEMUIOVector *iov, uint64_t prp1,
>  prp_ent = le64_to_cpu(prp_list[i]);
>  }
>
> -if (!prp_ent || prp_ent & (n->page_size - 1)) {
> +if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
> +trace_nvme_err_invalid_prplist_ent(prp_ent);
>  goto unmap;
>  }
>
> @@ -154,7 +171,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
> QEMUIOVector *iov, uint64_t prp1,
>  i++;
>  }
>  } else {
> -if (prp2 & (n->page_size - 1)) {
> +if (unlikely(prp2 & (n->page_size - 1))) {
> +trace_nvme_err_invalid_prp2_align(prp2);
>  goto unmap;
>  }
>  if (qsg->nsg) {
> @@ -178,16 +196,20 @@ static uint16_t nvme_dma_read_prp(NvmeCtrl *n,
> uint8_t *ptr, uint32_t len,
>  QEMUIOVector iov;
>  uint16_t status = NVME_SUCCESS;
>
> +trace_nvme_dma_read(prp1, prp2);
> +
>  if (nvme_map_prp(&qsg, &iov, prp1, prp2, len, n)) {
>  return NVME_INVALID_FIELD | NVME_DNR;
>  }
>  if (qsg.nsg > 0) {
> -if (dma_buf_read(ptr, len, &q

[Qemu-block] nvme: Add tracing v3

2017-10-12 Thread Doug Gale
>From c7f12a5949458fdd195b5e0b52f158e8f114f203 Mon Sep 17 00:00:00 2001
From: Doug Gale 
Date: Thu, 12 Oct 2017 14:29:07 -0400
Subject: [PATCH] nvme: Add tracing

Add trace output for commands, errors, and undefined behavior.
Add guest error log output for undefined behavior.
Report and ignore invalid undefined accesses to MMIO.
Annotate unlikely error checks with unlikely.

Signed-off-by: Doug Gale 
---
 hw/block/nvme.c   | 347 ++
 hw/block/trace-events |  93 ++
 2 files changed, 387 insertions(+), 53 deletions(-)

diff --git a/hw/block/nvme.c b/hw/block/nvme.c
index 9aa32692a3..adac19f5b0 100644
--- a/hw/block/nvme.c
+++ b/hw/block/nvme.c
@@ -34,8 +34,17 @@
 #include "qapi/visitor.h"
 #include "sysemu/block-backend.h"

+#include "qemu/log.h"
+#include "trace.h"
 #include "nvme.h"

+#define NVME_GUEST_ERR(trace, fmt, ...) \
+do { \
+(trace_##trace)(__VA_ARGS__); \
+qemu_log_mask(LOG_GUEST_ERROR, #trace \
+" in %s: " fmt "\n", __func__, ## __VA_ARGS__); \
+} while (0)
+
 static void nvme_process_sq(void *opaque);

 static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
@@ -86,10 +95,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue *cq)
 {
 if (cq->irq_enabled) {
 if (msix_enabled(&(n->parent_obj))) {
+trace_nvme_irq_msix(cq->vector);
 msix_notify(&(n->parent_obj), cq->vector);
 } else {
+trace_nvme_irq_pin();
 pci_irq_pulse(&n->parent_obj);
 }
+} else {
+trace_nvme_irq_masked();
 }
 }

@@ -100,7 +113,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 trans_len = MIN(len, trans_len);
 int num_prps = (len >> n->page_bits) + 1;

-if (!prp1) {
+if (unlikely(!prp1)) {
+trace_nvme_err_invalid_prp();
 return NVME_INVALID_FIELD | NVME_DNR;
 } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size)) {
@@ -113,7 +127,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 }
 len -= trans_len;
 if (len) {
-if (!prp2) {
+if (unlikely(!prp2)) {
+trace_nvme_err_invalid_prp2_missing();
 goto unmap;
 }
 if (len > n->page_size) {
@@ -128,7 +143,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 uint64_t prp_ent = le64_to_cpu(prp_list[i]);

 if (i == n->max_prp_ents - 1 && len > n->page_size) {
-if (!prp_ent || prp_ent & (n->page_size - 1)) {
+if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
+trace_nvme_err_invalid_prplist_ent(prp_ent);
 goto unmap;
 }

@@ -140,7 +156,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 prp_ent = le64_to_cpu(prp_list[i]);
 }

-if (!prp_ent || prp_ent & (n->page_size - 1)) {
+if (unlikely(!prp_ent || prp_ent & (n->page_size - 1))) {
+trace_nvme_err_invalid_prplist_ent(prp_ent);
 goto unmap;
 }

@@ -154,7 +171,8 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 i++;
 }
 } else {
-if (prp2 & (n->page_size - 1)) {
+if (unlikely(prp2 & (n->page_size - 1))) {
+trace_nvme_err_invalid_prp2_align(prp2);
 goto unmap;
 }
 if (qsg->nsg) {
@@ -178,16 +196,20 @@ static uint16_t nvme_dma_read_prp(NvmeCtrl *n,
uint8_t *ptr, uint32_t len,
 QEMUIOVector iov;
 uint16_t status = NVME_SUCCESS;

+trace_nvme_dma_read(prp1, prp2);
+
 if (nvme_map_prp(&qsg, &iov, prp1, prp2, len, n)) {
 return NVME_INVALID_FIELD | NVME_DNR;
 }
 if (qsg.nsg > 0) {
-if (dma_buf_read(ptr, len, &qsg)) {
+if (unlikely(dma_buf_read(ptr, len, &qsg))) {
+trace_nvme_err_invalid_dma();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_sglist_destroy(&qsg);
 } else {
-if (qemu_iovec_to_buf(&iov, 0, ptr, len) != len) {
+if (unlikely(qemu_iovec_to_buf(&iov, 0, ptr, len) != len)) {
+trace_nvme_err_invalid_dma();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_iovec_destroy(&iov);
@@ -273,7 +295,8 @@ static uint16_t nvme_write_zeros(NvmeCtrl *n,
NvmeNamespace *ns, NvmeCmd *cmd,
 uint64_t aio_slba = slba << 

Re: [Qemu-block] [Qemu-devel] Patch to add helpful tracing output for driver authors in NVMe emulation

2017-10-11 Thread Doug Gale
On Tue, Oct 10, 2017 at 4:02 AM, Kevin Wolf  wrote:
> Am 10.10.2017 um 08:58 hat Markus Armbruster geschrieben:
>> Doug Gale  writes:
>>
>> > I used exclamations as a concise way of indicating that the driver did
>> > something nonsensical, or horribly invalid, like something likely to
>> > cause a memory corruption, trying to start the controller with a
>> > nonsense configuration, providing invalid PRDs or writing to
>> > unrecognized MMIO offsets that might hang or do something extremely
>> > bad on a poorly implemented controller. Exclaiming is not shouting, I
>> > thought shouting was when it was all uppercase.
>> >
>> > If a driver might trash memory or hang a controller, maybe it should
>> > shout at the driver author or person investigating an unstable VM.
>> > None of those messages with exclamations should ever happen. If any of
>> > them are possible when the driver is correct, then I have made a
>> > mistake.
>>
>> Please do not top-quote on this mailing list.
>>
>> Existing tracepoints do not use exclamation marks to signal severity.
>>
>> Consider using assertions for "if this happens, either the program's
>> state is shot (and continuing is unsafe), or the author's mental state
>> was shot (and continuing is probably unsafe, too)" conditions.
>> Tracepoints are for tracing.
>
> Assertions are for checking that assumptions in qemu code hold true.
> Here it's about bad guest code, and you can't let qemu abort for that.
>
> Tracing is the right tool to detect bad guest code, and I think it makes
> sense to mark conditions that shouldn't happen with a correctly
> operating guest driver. I'm not sure if an exclamation mark is the best
> syntax for this, because I wouldn't have intuitively understood what
> it's supposed to tell me.
>
> If we do use the exclamation mark, we should document it somewhere
> (docs/devel/tracing.txt?) and make it a qemu-wide pattern. If not, we
> should choose something else and still document it and use it
> consistently.
>
> Kevin
>

Should I give up on indicating severity for now (removing the
exclamations) and just group together the severe ones with a comment
heading in the trace-events file?
I added "" at the end of some traces to help possibly-incorrect
parsing code find the end of the string reliably. Was that a good idea
or is it okay and expected to end them with something like PRIx64 and
drop the extra ""?
I found a few cases of missing 0x that I will fix in the next version
of this patch. Policy is to have 0x before every hex value, right?

Also, so I'm clear, when I submit the patch I should put the patch
first and put my message after the -- at the end?
And use "nvme: Add tracing" for the commit message,
And put nvme: Add tracing v3 in my subject line in a completely new
email thread?



Re: [Qemu-block] [Qemu-devel] Patch to add helpful tracing output for driver authors in NVMe emulation

2017-10-09 Thread Doug Gale
I used exclamations as a concise way of indicating that the driver did
something nonsensical, or horribly invalid, like something likely to
cause a memory corruption, trying to start the controller with a
nonsense configuration, providing invalid PRDs or writing to
unrecognized MMIO offsets that might hang or do something extremely
bad on a poorly implemented controller. Exclaiming is not shouting, I
thought shouting was when it was all uppercase.

If a driver might trash memory or hang a controller, maybe it should
shout at the driver author or person investigating an unstable VM.
None of those messages with exclamations should ever happen. If any of
them are possible when the driver is correct, then I have made a
mistake.

On Mon, Oct 9, 2017 at 11:52 AM, Eric Blake  wrote:
> On 10/07/2017 02:51 AM, Doug Gale wrote:
>> Completely re-implemented patch, with significant improvements (now
>> specifies values in several places I missed, also reduced the amount
>> of redundant lines). I used the nvme_ as the tracing infrastructure
>> prefix. Tested with -trace nvme_* on the qemu command line, worked for
>> me.
>
> This information belongs...
>
>>
>>>From 166f57458d60d363a10a0933c3e860985531ac96 Mon Sep 17 00:00:00 2001
>> From: Doug Gale 
>> Date: Thu, 5 Oct 2017 19:02:03 -0400
>> Subject: [PATCH] Add tracing output to NVMe emulation to help driver authors.
>>
>> This uses the tracing infrastructure using nvme_ as the prefix.
>>
>> Signed-off-by: Doug Gale 
>> ---
>
> ...here, after the --- separator.  It is useful to the patch reviewer,
> but does not need to be in the 'git log' history.  The maintainers use
> 'git am' to process incoming patches, which automatically prunes review
> comments located in this location.
>
> Also, since this is a version 2 patch, it is best if your subject line
> includes 'v2', and if you send the patch as a new top-level thread
> rather than in-reply-to v1.  This can be done with 'git send-email -v2'.
>
> The subject line is atypical; we tend to prefer 'topic: Short summary',
> where you are missing the topic, you had a trailing dot that is not
> typical, and where your line is longer than usual.  A better subject
> line might be:
>
> nvme: Add tracing output
>
>
> For more helpful information on patch submission:
>
> https://wiki.qemu.org/Contribute/SubmitAPatch
>
> I didn't look closely at the patch itself, but did notice:
>
>> +nvme_mmio_start_failed(void) "setting controller enable bit failed!"
>> +nvme_mmio_start_success(void) "setting controller enable bit succeeded"
>> +nvme_mmio_stopped(void) "cleared controller enable bit"
>> +nvme_mmio_shutdown_set(void) "shutdown bit set"
>> +nvme_mmio_shutdown_cleared(void) "shutdown bit cleared"
>> +nvme_mmio_ignored(uint64_t offset, uint64_t data) "invalid MMIO
>> write, offset=0x%"PRIx64", data=%"PRIx64"!"
>
> You have a couple of traces with a trailing '!'; that is atypical,
> because we don't need our traces to shout at the user.
>
> --
> Eric Blake, Principal Software Engineer
> Red Hat, Inc.   +1-919-301-3266
> Virtualization:  qemu.org | libvirt.org
>



Re: [Qemu-block] [Qemu-devel] Patch to add helpful tracing output for driver authors in NVMe emulation

2017-10-07 Thread Doug Gale
Completely re-implemented patch, with significant improvements (now
specifies values in several places I missed, also reduced the amount
of redundant lines). I used the nvme_ as the tracing infrastructure
prefix. Tested with -trace nvme_* on the qemu command line, worked for
me.

>From 166f57458d60d363a10a0933c3e860985531ac96 Mon Sep 17 00:00:00 2001
From: Doug Gale 
Date: Thu, 5 Oct 2017 19:02:03 -0400
Subject: [PATCH] Add tracing output to NVMe emulation to help driver authors.

This uses the tracing infrastructure using nvme_ as the prefix.

Signed-off-by: Doug Gale 
---
 hw/block/nvme.c   | 158 +-
 hw/block/trace-events |  89 
 2 files changed, 233 insertions(+), 14 deletions(-)

diff --git a/hw/block/nvme.c b/hw/block/nvme.c
index 9aa32692a3..3e3cd820a3 100644
--- a/hw/block/nvme.c
+++ b/hw/block/nvme.c
@@ -34,6 +34,7 @@
 #include "qapi/visitor.h"
 #include "sysemu/block-backend.h"

+#include "trace.h"
 #include "nvme.h"

 static void nvme_process_sq(void *opaque);
@@ -86,10 +87,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue *cq)
 {
 if (cq->irq_enabled) {
 if (msix_enabled(&(n->parent_obj))) {
+trace_nvme_msix_intr(cq->vector);
 msix_notify(&(n->parent_obj), cq->vector);
 } else {
+trace_nvme_pin_intr();
 pci_irq_pulse(&n->parent_obj);
 }
+} else {
+trace_nvme_masked_intr();
 }
 }

@@ -101,6 +106,7 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 int num_prps = (len >> n->page_bits) + 1;

 if (!prp1) {
+trace_nvme_invalid_prp();
 return NVME_INVALID_FIELD | NVME_DNR;
 } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size)) {
@@ -114,6 +120,7 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 len -= trans_len;
 if (len) {
 if (!prp2) {
+trace_nvme_invalid_prp2_missing();
 goto unmap;
 }
 if (len > n->page_size) {
@@ -129,6 +136,7 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,

 if (i == n->max_prp_ents - 1 && len > n->page_size) {
 if (!prp_ent || prp_ent & (n->page_size - 1)) {
+trace_nvme_invalid_prplist_ent(prp_ent);
 goto unmap;
 }

@@ -141,6 +149,7 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 }

 if (!prp_ent || prp_ent & (n->page_size - 1)) {
+trace_nvme_invalid_prplist_ent(prp_ent);
 goto unmap;
 }

@@ -155,6 +164,7 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 }
 } else {
 if (prp2 & (n->page_size - 1)) {
+trace_nvme_invalid_prp2_align(prp2);
 goto unmap;
 }
 if (qsg->nsg) {
@@ -178,16 +188,20 @@ static uint16_t nvme_dma_read_prp(NvmeCtrl *n,
uint8_t *ptr, uint32_t len,
 QEMUIOVector iov;
 uint16_t status = NVME_SUCCESS;

+trace_nvme_dma_read(prp1, prp2);
+
 if (nvme_map_prp(&qsg, &iov, prp1, prp2, len, n)) {
 return NVME_INVALID_FIELD | NVME_DNR;
 }
 if (qsg.nsg > 0) {
 if (dma_buf_read(ptr, len, &qsg)) {
+trace_nvme_dma_too_short();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_sglist_destroy(&qsg);
 } else {
 if (qemu_iovec_to_buf(&iov, 0, ptr, len) != len) {
+trace_nvme_dma_too_short();
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_iovec_destroy(&iov);
@@ -274,6 +288,7 @@ static uint16_t nvme_write_zeros(NvmeCtrl *n,
NvmeNamespace *ns, NvmeCmd *cmd,
 uint32_t aio_nlb = nlb << (data_shift - BDRV_SECTOR_BITS);

 if (slba + nlb > ns->id_ns.nsze) {
+trace_nvme_invalid_lba_range(slba, nlb, ns->id_ns.nsze);
 return NVME_LBA_RANGE | NVME_DNR;
 }

@@ -301,8 +316,11 @@ static uint16_t nvme_rw(NvmeCtrl *n,
NvmeNamespace *ns, NvmeCmd *cmd,
 int is_write = rw->opcode == NVME_CMD_WRITE ? 1 : 0;
 enum BlockAcctType acct = is_write ? BLOCK_ACCT_WRITE : BLOCK_ACCT_READ;

+trace_nvme_rw(is_write ? "write" : "read", nlb, data_size, slba);
+
 if ((slba + nlb) > ns->id_ns.nsze) {
 block_acct_invalid(blk_get_stats(n->conf.blk), acct);
+trace_nvme_invalid_lba_range(slba, nlb, ns->id_ns.nsze);
 return NVME_LBA_RANGE | NVME_DNR;
 }

@@ -337,6 +355,7 @@ static uint16_t nvme_io_cmd(Nv

Re: [Qemu-block] [Qemu-devel] Patch to add helpful tracing output for driver authors in NVMe emulation

2017-10-06 Thread Doug Gale
I tried to get tracing to work before and I have never gotten it
working. I'll give it another try and redo the patch with tracing
infrastructure if necessary. The printf are nice because the dev can
just look at the terminal where qemu is running. Can you view the
trace output in realtime? When their code is sitting at a breakpoint
in their driver, can they see the last thing that was traced right
there? Or do they have to go run some cumbersome command and wade
through it after an entire test run after the vm shut down?


On Fri, Oct 6, 2017 at 9:54 AM, Daniel P. Berrange  wrote:
> On Fri, Oct 06, 2017 at 08:50:31AM -0500, Eric Blake wrote:
>> On 10/05/2017 06:18 PM, Doug Gale wrote:
>> > I added the tracing output in this patch to assist me in implementing
>> > an NVMe driver. It helped tremendously.
>> >
>> >>From 1d19086cdef8d492929852d582cb41dcc5026f71 Mon Sep 17 00:00:00 2001
>> > From: Doug Gale 
>> > Date: Thu, 5 Oct 2017 19:02:03 -0400
>> > Subject: [PATCH] Add tracing output to NVMe emulation to help driver 
>> > authors.
>> >
>> > It is off by default, enable it by uncommenting #define DEBUG_NVME
>> > or through CFLAGS
>> >
>> > Signed-off-by: Doug Gale 
>> > ---
>> >  hw/block/nvme.c | 191 
>> > +++-
>> >  1 file changed, 177 insertions(+), 14 deletions(-)
>> >
>> > diff --git a/hw/block/nvme.c b/hw/block/nvme.c
>> > index 9aa32692a3..74220c0171 100644
>> > --- a/hw/block/nvme.c
>> > +++ b/hw/block/nvme.c
>> > @@ -36,6 +36,14 @@
>> >
>> >  #include "nvme.h"
>> >
>> > +//#define DEBUG_NVME
>> > +
>> > +#ifdef DEBUG_NVME
>> > +#define DPRINTF(fmt, ...) fprintf(stderr, "nvme: " fmt "\n", ## 
>> > __VA_ARGS__)
>> > +#else
>> > +#define DPRINTF(fmt, ...) ((void)0)
>> > +#endif
>>
>> As Kevin said, using trace-events is nicer than fprintf().  But if you
>> absolutely insist on fprintf(), then do NOT do it like this, because
>> this leads to bit-rot.  Instead, do it in a form that lets -Wformat
>> checking work even when tracing is disabled:
>
> [snip]
>
> IMHO using of trace() instead of fprintf() is pretty much mandatory
> at this point. We've been making a concious effort to replace fprintfs
> with trace across code, so shouldn't add more fprintfs. It is just so
> much more useful to be able to enable the debugging without having to
> recompile the binary.
>
> Regards,
> Daniel
> --
> |: https://berrange.com  -o-https://www.flickr.com/photos/dberrange :|
> |: https://libvirt.org -o-https://fstop138.berrange.com :|
> |: https://entangle-photo.org-o-https://www.instagram.com/dberrange :|



[Qemu-block] Patch to add helpful tracing output for driver authors in NVMe emulation

2017-10-06 Thread Doug Gale
I added the tracing output in this patch to assist me in implementing
an NVMe driver. It helped tremendously.

>From 1d19086cdef8d492929852d582cb41dcc5026f71 Mon Sep 17 00:00:00 2001
From: Doug Gale 
Date: Thu, 5 Oct 2017 19:02:03 -0400
Subject: [PATCH] Add tracing output to NVMe emulation to help driver authors.

It is off by default, enable it by uncommenting #define DEBUG_NVME
or through CFLAGS

Signed-off-by: Doug Gale 
---
 hw/block/nvme.c | 191 +++-
 1 file changed, 177 insertions(+), 14 deletions(-)

diff --git a/hw/block/nvme.c b/hw/block/nvme.c
index 9aa32692a3..74220c0171 100644
--- a/hw/block/nvme.c
+++ b/hw/block/nvme.c
@@ -36,6 +36,14 @@

 #include "nvme.h"

+//#define DEBUG_NVME
+
+#ifdef DEBUG_NVME
+#define DPRINTF(fmt, ...) fprintf(stderr, "nvme: " fmt "\n", ## __VA_ARGS__)
+#else
+#define DPRINTF(fmt, ...) ((void)0)
+#endif
+
 static void nvme_process_sq(void *opaque);

 static void nvme_addr_read(NvmeCtrl *n, hwaddr addr, void *buf, int size)
@@ -86,10 +94,14 @@ static void nvme_isr_notify(NvmeCtrl *n, NvmeCQueue *cq)
 {
 if (cq->irq_enabled) {
 if (msix_enabled(&(n->parent_obj))) {
+DPRINTF("raising MSI-X IRQ vector %u", cq->vector);
 msix_notify(&(n->parent_obj), cq->vector);
 } else {
+DPRINTF("pulsing IRQ pin");
 pci_irq_pulse(&n->parent_obj);
 }
+} else {
+DPRINTF("IRQ is masked");
 }
 }

@@ -101,9 +113,11 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,
 int num_prps = (len >> n->page_bits) + 1;

 if (!prp1) {
+DPRINTF("Invalid PRP!");
 return NVME_INVALID_FIELD | NVME_DNR;
 } else if (n->cmbsz && prp1 >= n->ctrl_mem.addr &&
prp1 < n->ctrl_mem.addr + int128_get64(n->ctrl_mem.size)) {
+DPRINTF("PRP in controller memory");
 qsg->nsg = 0;
 qemu_iovec_init(iov, num_prps);
 qemu_iovec_add(iov, (void *)&n->cmbuf[prp1 -
n->ctrl_mem.addr], trans_len);
@@ -168,6 +182,7 @@ static uint16_t nvme_map_prp(QEMUSGList *qsg,
QEMUIOVector *iov, uint64_t prp1,

  unmap:
 qemu_sglist_destroy(qsg);
+DPRINTF("invalid SGL!");
 return NVME_INVALID_FIELD | NVME_DNR;
 }

@@ -178,16 +193,22 @@ static uint16_t nvme_dma_read_prp(NvmeCtrl *n,
uint8_t *ptr, uint32_t len,
 QEMUIOVector iov;
 uint16_t status = NVME_SUCCESS;

+DPRINTF("DMA read, prp1=0x%"PRIx64" prp2=0x%"PRIx64,
+prp1, prp2);
+
 if (nvme_map_prp(&qsg, &iov, prp1, prp2, len, n)) {
+DPRINTF("DMA read invalid PRP field!");
 return NVME_INVALID_FIELD | NVME_DNR;
 }
 if (qsg.nsg > 0) {
 if (dma_buf_read(ptr, len, &qsg)) {
+DPRINTF("DMA read invalid SGL field!");
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_sglist_destroy(&qsg);
 } else {
 if (qemu_iovec_to_buf(&iov, 0, ptr, len) != len) {
+DPRINTF("invalid field!");
 status = NVME_INVALID_FIELD | NVME_DNR;
 }
 qemu_iovec_destroy(&iov);
@@ -274,6 +295,7 @@ static uint16_t nvme_write_zeros(NvmeCtrl *n,
NvmeNamespace *ns, NvmeCmd *cmd,
 uint32_t aio_nlb = nlb << (data_shift - BDRV_SECTOR_BITS);

 if (slba + nlb > ns->id_ns.nsze) {
+DPRINTF("Invalid LBA!");
 return NVME_LBA_RANGE | NVME_DNR;
 }

@@ -301,13 +323,19 @@ static uint16_t nvme_rw(NvmeCtrl *n,
NvmeNamespace *ns, NvmeCmd *cmd,
 int is_write = rw->opcode == NVME_CMD_WRITE ? 1 : 0;
 enum BlockAcctType acct = is_write ? BLOCK_ACCT_WRITE : BLOCK_ACCT_READ;

+DPRINTF("%s %"PRIu32" blocks (%"PRIu64" bytes) from LBA %"PRIu64,
+is_write ? "write" : "read",
+nlb, data_size, slba);
+
 if ((slba + nlb) > ns->id_ns.nsze) {
 block_acct_invalid(blk_get_stats(n->conf.blk), acct);
+DPRINTF("Invalid LBA!");
 return NVME_LBA_RANGE | NVME_DNR;
 }

 if (nvme_map_prp(&req->qsg, &req->iov, prp1, prp2, data_size, n)) {
 block_acct_invalid(blk_get_stats(n->conf.blk), acct);
+DPRINTF("Invalid PRP!");
 return NVME_INVALID_FIELD | NVME_DNR;
 }

@@ -337,6 +365,7 @@ static uint16_t nvme_io_cmd(NvmeCtrl *n, NvmeCmd
*cmd, NvmeRequest *req)
 uint32_t nsid = le32_to_cpu(cmd->nsid);

 if (nsid == 0 || nsid > n->num_namespaces) {
+DPRINTF("Invalid namespace!");
 return NVME_INVALID_NSID | NVME_DNR;
 }

@@ -350,6 +379,7 @@ static uint16_t nvme_io_cmd(NvmeCtrl *n, NvmeCmd
*cmd, NvmeRequest *req)
 case NVME_CMD_READ: