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 <doug16k@gmail.com>
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 <doug16k@gmail.com>
---
 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:
         return nvme_rw(n, ns, cmd, req);
     default:
+        DPRINTF("Invalid opcode!");
         return NVME_INVALID_OPCODE | NVME_DNR;
     }
 }
@@ -374,9 +404,12 @@ static uint16_t nvme_del_sq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qid = le16_to_cpu(c->qid);

     if (!qid || nvme_check_sqid(n, qid)) {
+        DPRINTF("invalid submission queue deletion! qid=%u", qid);
         return NVME_INVALID_QID | NVME_DNR;
     }

+    DPRINTF("submission queue deleted, qid=%u", qid);
+
     sq = n->sq[qid];
     while (!QTAILQ_EMPTY(&sq->out_req_list)) {
         req = QTAILQ_FIRST(&sq->out_req_list);
@@ -439,21 +472,31 @@ static uint16_t nvme_create_sq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qflags = le16_to_cpu(c->sq_flags);
     uint64_t prp1 = le64_to_cpu(c->prp1);

+    DPRINTF("attempting to create submission queue"
+            ", addr=0x%"PRIx64", cqid=%u, size=%u",
+            prp1, cqid, qsize);
+
     if (!cqid || nvme_check_cqid(n, cqid)) {
+        DPRINTF("...invalid completion queue id!");
         return NVME_INVALID_CQID | NVME_DNR;
     }
     if (!sqid || !nvme_check_sqid(n, sqid)) {
+        DPRINTF("...invalid submission queue id!");
         return NVME_INVALID_QID | NVME_DNR;
     }
     if (!qsize || qsize > NVME_CAP_MQES(n->bar.cap)) {
+        DPRINTF("...invalid queue size!");
         return NVME_MAX_QSIZE_EXCEEDED | NVME_DNR;
     }
     if (!prp1 || prp1 & (n->page_size - 1)) {
+        DPRINTF("...invalid address!");
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     if (!(NVME_SQ_FLAGS_PC(qflags))) {
+        DPRINTF("...invalid flags!");
         return NVME_INVALID_FIELD | NVME_DNR;
     }
+    DPRINTF("...success");
     sq = g_malloc0(sizeof(*sq));
     nvme_init_sq(sq, n, prp1, sqid, cqid, qsize + 1);
     return NVME_SUCCESS;
@@ -477,13 +520,16 @@ static uint16_t nvme_del_cq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qid = le16_to_cpu(c->qid);

     if (!qid || nvme_check_cqid(n, qid)) {
+        DPRINTF("Invalid completion queue ID!");
         return NVME_INVALID_CQID | NVME_DNR;
     }

     cq = n->cq[qid];
     if (!QTAILQ_EMPTY(&cq->sq_list)) {
+        DPRINTF("invalid completion queue deletion! id=%u", qid);
         return NVME_INVALID_QUEUE_DEL;
     }
+    DPRINTF("deleted completion queue, id=%u", qid);
     nvme_free_cq(cq, n);
     return NVME_SUCCESS;
 }
@@ -516,21 +562,32 @@ static uint16_t nvme_create_cq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qflags = le16_to_cpu(c->cq_flags);
     uint64_t prp1 = le64_to_cpu(c->prp1);

+    DPRINTF("attempting to create completion queue"
+            ", addr=0x%"PRIx64", cqid=%u"
+            ", vector=%u, size=%u, intr_en=%u",
+            prp1, cqid, vector, qsize, NVME_CQ_FLAGS_IEN(qflags));
+
     if (!cqid || !nvme_check_cqid(n, cqid)) {
+        DPRINTF("...invalid completion queue id!");
         return NVME_INVALID_CQID | NVME_DNR;
     }
     if (!qsize || qsize > NVME_CAP_MQES(n->bar.cap)) {
+        DPRINTF("...invalid queue size!");
         return NVME_MAX_QSIZE_EXCEEDED | NVME_DNR;
     }
     if (!prp1) {
+        DPRINTF("...invalid address!");
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     if (vector > n->num_queues) {
+        DPRINTF("...invalid interrupt vector!");
         return NVME_INVALID_IRQ_VECTOR | NVME_DNR;
     }
     if (!(NVME_CQ_FLAGS_PC(qflags))) {
+        DPRINTF("...invalid flags!");
         return NVME_INVALID_FIELD | NVME_DNR;
     }
+    DPRINTF("...success");

     cq = g_malloc0(sizeof(*cq));
     nvme_init_cq(cq, n, prp1, cqid, vector, qsize + 1,
@@ -555,10 +612,16 @@ static uint16_t nvme_identify_ns(NvmeCtrl *n,
NvmeIdentify *c)
     uint64_t prp2 = le64_to_cpu(c->prp2);

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

     ns = &n->namespaces[nsid - 1];
+
+    DPRINTF("identify namespace, nlbaf=%u", ns->id_ns.nlbaf);
+    DPRINTF("identify namespace, lbaf[0]=0x%"PRIx32,
+            *(uint32_t*)&ns->id_ns.lbaf[0]);
+
     return nvme_dma_read_prp(n, (uint8_t *)&ns->id_ns, sizeof(ns->id_ns),
         prp1, prp2);
 }
@@ -595,12 +658,18 @@ static uint16_t nvme_identify(NvmeCtrl *n, NvmeCmd *cmd)

     switch (le32_to_cpu(c->cns)) {
     case 0x00:
+        DPRINTF("...identify namespace %u",
+                le32_to_cpu(c->nsid));
         return nvme_identify_ns(n, c);
     case 0x01:
+        DPRINTF("...identify controller");
         return nvme_identify_ctrl(n, c);
     case 0x02:
+        DPRINTF("...identify namespace list, after %u",
+                le32_to_cpu(c->nsid));
         return nvme_identify_nslist(n, c);
     default:
+        DPRINTF("...invalid CNS: %u!", le32_to_cpu(c->cns));
         return NVME_INVALID_FIELD | NVME_DNR;
     }
 }
@@ -618,6 +687,7 @@ static uint16_t nvme_get_feature(NvmeCtrl *n,
NvmeCmd *cmd, NvmeRequest *req)
         result = cpu_to_le32((n->num_queues - 2) | ((n->num_queues -
2) << 16));
         break;
     default:
+        DPRINTF("Invalid field!");
         return NVME_INVALID_FIELD | NVME_DNR;
     }

@@ -635,10 +705,15 @@ static uint16_t nvme_set_feature(NvmeCtrl *n,
NvmeCmd *cmd, NvmeRequest *req)
         blk_set_enable_write_cache(n->conf.blk, dw11 & 1);
         break;
     case NVME_NUMBER_OF_QUEUES:
+        DPRINTF("Requested cq_count=%u, sq_count=%u,"
+                " responding with cq_count=%u, sq_count=%u",
+                (dw11 & 0xFFFF) + 1, ((dw11 >> 16) & 0xFFFF) + 1,
+                n->num_queues - 1, n->num_queues - 1);
         req->cqe.result =
             cpu_to_le32((n->num_queues - 2) | ((n->num_queues - 2) << 16));
         break;
     default:
+        DPRINTF("Invalid field!");
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     return NVME_SUCCESS;
@@ -648,20 +723,28 @@ static uint16_t nvme_admin_cmd(NvmeCtrl *n,
NvmeCmd *cmd, NvmeRequest *req)
 {
     switch (cmd->opcode) {
     case NVME_ADM_CMD_DELETE_SQ:
+        DPRINTF("received admin command: delete submission queue");
         return nvme_del_sq(n, cmd);
     case NVME_ADM_CMD_CREATE_SQ:
+        DPRINTF("received admin command: create submission queue");
         return nvme_create_sq(n, cmd);
     case NVME_ADM_CMD_DELETE_CQ:
+        DPRINTF("received admin command: delete completion queue");
         return nvme_del_cq(n, cmd);
     case NVME_ADM_CMD_CREATE_CQ:
+        DPRINTF("received admin command: create completion queue");
         return nvme_create_cq(n, cmd);
     case NVME_ADM_CMD_IDENTIFY:
+        DPRINTF("received admin command: identify");
         return nvme_identify(n, cmd);
     case NVME_ADM_CMD_SET_FEATURES:
+        DPRINTF("received admin command: set features");
         return nvme_set_feature(n, cmd, req);
     case NVME_ADM_CMD_GET_FEATURES:
+        DPRINTF("received admin command: get features");
         return nvme_get_feature(n, cmd, req);
     default:
+        DPRINTF("received admin command: invalid opcode!");
         return NVME_INVALID_OPCODE | NVME_DNR;
     }
 }
@@ -721,15 +804,70 @@ static int nvme_start_ctrl(NvmeCtrl *n)
     uint32_t page_bits = NVME_CC_MPS(n->bar.cc) + 12;
     uint32_t page_size = 1 << page_bits;

-    if (n->cq[0] || n->sq[0] || !n->bar.asq || !n->bar.acq ||
-            n->bar.asq & (page_size - 1) || n->bar.acq & (page_size - 1) ||
-            NVME_CC_MPS(n->bar.cc) < NVME_CAP_MPSMIN(n->bar.cap) ||
-            NVME_CC_MPS(n->bar.cc) > NVME_CAP_MPSMAX(n->bar.cap) ||
-            NVME_CC_IOCQES(n->bar.cc) < NVME_CTRL_CQES_MIN(n->id_ctrl.cqes) ||
-            NVME_CC_IOCQES(n->bar.cc) > NVME_CTRL_CQES_MAX(n->id_ctrl.cqes) ||
-            NVME_CC_IOSQES(n->bar.cc) < NVME_CTRL_SQES_MIN(n->id_ctrl.sqes) ||
-            NVME_CC_IOSQES(n->bar.cc) > NVME_CTRL_SQES_MAX(n->id_ctrl.sqes) ||
-            !NVME_AQA_ASQS(n->bar.aqa) || !NVME_AQA_ACQS(n->bar.aqa)) {
+    if (n->cq[0]) {
+        DPRINTF("nvme_start_ctrl failed because cq[0]");
+        return -1;
+    }
+    if (n->sq[0]) {
+        DPRINTF("nvme_start_ctrl failed because sq[0]");
+        return -1;
+    }
+    if (!n->bar.asq) {
+        DPRINTF("nvme_start_ctrl failed because !bar.asq");
+        return -1;
+    }
+    if (!n->bar.acq) {
+        DPRINTF("nvme_start_ctrl failed because !bar.acq");
+        return -1;
+    }
+    if (n->bar.asq & (page_size - 1)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " bar.asq is not page aligned");
+        return -1;
+    }
+    if (n->bar.acq & (page_size - 1)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " bar.acq is not page aligned");
+        return -1;
+    }
+    if (NVME_CC_MPS(n->bar.cc) < NVME_CAP_MPSMIN(n->bar.cap)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " page size is too small");
+        return -1;
+    }
+    if (NVME_CC_MPS(n->bar.cc) > NVME_CAP_MPSMAX(n->bar.cap)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " page size is too large");
+        return -1;
+    }
+    if (NVME_CC_IOCQES(n->bar.cc) < NVME_CTRL_CQES_MIN(n->id_ctrl.cqes)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " completion queue entry size is too small");
+        return -1;
+    }
+    if (NVME_CC_IOCQES(n->bar.cc) > NVME_CTRL_CQES_MAX(n->id_ctrl.cqes)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " completion queue entry size is too large");
+        return -1;
+    }
+    if (NVME_CC_IOSQES(n->bar.cc) < NVME_CTRL_SQES_MIN(n->id_ctrl.sqes)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " submit queue entry size is too small");
+        return -1;
+    }
+    if (NVME_CC_IOSQES(n->bar.cc) > NVME_CTRL_SQES_MAX(n->id_ctrl.sqes)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " submit queue entry size is too large");
+        return -1;
+    }
+    if (!NVME_AQA_ASQS(n->bar.aqa)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " admin submit queue size is zero");
+        return -1;
+    }
+    if (!NVME_AQA_ACQS(n->bar.aqa)) {
+        DPRINTF("nvme_start_ctrl failed because"
+                " admin completion queue size is zero");
         return -1;
     }

@@ -749,16 +887,25 @@ static int nvme_start_ctrl(NvmeCtrl *n)
 static void nvme_write_bar(NvmeCtrl *n, hwaddr offset, uint64_t data,
     unsigned size)
 {
+    DPRINTF("wrote pci config offset=0x%"PRIx64" data=0x%"PRIx64"",
+            offset, data);
+
     switch (offset) {
     case 0xc:
+        DPRINTF("...interrupt mask set 0x%"PRIx64"",
+                data & 0xffffffff);
         n->bar.intms |= data & 0xffffffff;
         n->bar.intmc = n->bar.intms;
         break;
     case 0x10:
+        DPRINTF("...interrupt mask clr 0x%"PRIx64"",
+                data & 0xffffffff);
         n->bar.intms &= ~(data & 0xffffffff);
         n->bar.intmc = n->bar.intms;
         break;
     case 0x14:
+        DPRINTF("...controller config 0x%"PRIx64"",
+                data & 0xffffffff);
         /* Windows first sends data, then sends enable bit */
         if (!NVME_CC_EN(data) && !NVME_CC_EN(n->bar.cc) &&
             !NVME_CC_SHN(data) && !NVME_CC_SHN(n->bar.cc))
@@ -769,39 +916,55 @@ static void nvme_write_bar(NvmeCtrl *n, hwaddr
offset, uint64_t data,
         if (NVME_CC_EN(data) && !NVME_CC_EN(n->bar.cc)) {
             n->bar.cc = data;
             if (nvme_start_ctrl(n)) {
+                DPRINTF("...nvme_start_ctrl failed!");
                 n->bar.csts = NVME_CSTS_FAILED;
             } else {
+                DPRINTF("...nvme_start_ctrl success, now ready!");
                 n->bar.csts = NVME_CSTS_READY;
             }
         } else if (!NVME_CC_EN(data) && NVME_CC_EN(n->bar.cc)) {
+            DPRINTF("...enable bit cleared");
             nvme_clear_ctrl(n);
             n->bar.csts &= ~NVME_CSTS_READY;
         }
         if (NVME_CC_SHN(data) && !(NVME_CC_SHN(n->bar.cc))) {
-                nvme_clear_ctrl(n);
-                n->bar.cc = data;
-                n->bar.csts |= NVME_CSTS_SHST_COMPLETE;
+            DPRINTF("...shutdown complete");
+            nvme_clear_ctrl(n);
+            n->bar.cc = data;
+            n->bar.csts |= NVME_CSTS_SHST_COMPLETE;
         } else if (!NVME_CC_SHN(data) && NVME_CC_SHN(n->bar.cc)) {
-                n->bar.csts &= ~NVME_CSTS_SHST_COMPLETE;
-                n->bar.cc = data;
+            DPRINTF("...no shutdown, normal operation");
+            n->bar.csts &= ~NVME_CSTS_SHST_COMPLETE;
+            n->bar.cc = data;
         }
         break;
     case 0x24:
+        DPRINTF("...admin queue attributes set to %u",
+                (uint32_t)(data & 0xffffffff));
         n->bar.aqa = data & 0xffffffff;
         break;
     case 0x28:
+        DPRINTF("...admin submission queue address set to %"PRIx64,
+                data);
         n->bar.asq = data;
         break;
     case 0x2c:
+        DPRINTF("...admin submission queue high half of address set to %x",
+                (uint32_t)(data & 0xffffffff));
         n->bar.asq |= data << 32;
         break;
     case 0x30:
+        DPRINTF("...admin completion queue address set to %"PRIx64,
+                data);
         n->bar.acq = data;
         break;
     case 0x34:
+        DPRINTF("...admin completion queue high half of address set to %x",
+                (uint32_t)(data & 0xffffffff));
         n->bar.acq |= data << 32;
         break;
     default:
+        DPRINTF("...ignored!");
         break;
     }
 }
-- 
2.11.0

Am 06.10.2017 um 01:18 hat Doug Gale geschrieben:
> 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 <doug16k@gmail.com>
> 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 <doug16k@gmail.com>

I think it's generally preferable to use the actual tracing
infrastructure instead of fprintf. This would allow to enable the trace
points with the command line options instead of only at compile time and
also to get machine-readable output if necessary.

The tracing infrastructure is documented in docs/devel/tracing.txt.

Kevin

On Fri, Oct 06, 2017 at 11:49:56AM +0200, Kevin Wolf wrote:
> Am 06.10.2017 um 01:18 hat Doug Gale geschrieben:
> > 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 <doug16k@gmail.com>
> > 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 <doug16k@gmail.com>
> 
> I think it's generally preferable to use the actual tracing
> infrastructure instead of fprintf. This would allow to enable the trace
> points with the command line options instead of only at compile time and
> also to get machine-readable output if necessary.
> 
> The tracing infrastructure is documented in docs/devel/tracing.txt.

Here is a quick example of enabling trace events whose name starts with
"cpu_":

  $ x86_64-softmmu/qemu-system-x86_64 -trace enable=cpu_\*
  7996@1507297762.170096:cpu_get_apic_base 0x00000000fee00900

The default trace backend prints to QEMU's log (stderr).  This makes it
easy to get at tracing output during development.

In order to add trace events to nvme.c you need to edit
hw/block/trace-events.  I suggest naming them with a "nvme_" prefix.

Stefan

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 <doug16k@gmail.com>
> 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 <doug16k@gmail.com>
> ---
>  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:

#ifdef DEBUG_NVME
# define DEBUG_NVME_PRINT 1
#else
# define DEBUG_NVME_PRINT 0
#endif
#define DPRINTF(fmt, ...) \
    do { \
        if (DEBUG_NVME_PRINT) { \
            fprintf(stderr, "nvme: " fmt "\n", ## __VA_ARGS__); \
        } \
    while (0)

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

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 <doug16k@gmail.com>
> > 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 <doug16k@gmail.com>
> > ---
> >  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 :|

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 <berrange@redhat.com> 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 <doug16k@gmail.com>
>> > 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 <doug16k@gmail.com>
>> > ---
>> >  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 :|

On Fri, Oct 06, 2017 at 09:58:33AM -0400, Doug Gale wrote:
> 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?

There's a variety of trace backends available. By default QEMU enables
the 'log' backend these days. So with a default build of QEMU you can
use the '-d' arg to turn on printing: eg.:

   qemu-system-x86_64 ...args...    -d trace:qio*

and that'll turn on every tracepoint with 'qio' as a prefix. The
trace messages will be printed straight to the console. eg:

$ qemu-system-x86_64 -d trace:qio* -serial unix:/tmp/foo,server
15774@1507298448.842745:qio_channel_socket_new Socket new ioc=0x5598b0565d60
15774@1507298448.842757:qio_channel_socket_listen_sync Socket listen sync ioc=0x5598b0565d60 addr=0x5598b0565c50
15774@1507298448.842803:qio_channel_socket_listen_complete Socket listen complete ioc=0x5598b0565d60 fd=16
qemu-system-x86_64: -serial unix:/tmp/foo,server: info: QEMU waiting for connection on: disconnected:unix:/tmp/foo,server
15774@1507298448.842818:qio_channel_socket_new Socket new ioc=0x5598b0564060
15774@1507298448.842820:qio_channel_socket_accept Socket accept start ioc=0x5598b0565d60


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

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 <doug16k@gmail.com>
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 <doug16k@gmail.com>
---
 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(NvmeCtrl *n, NvmeCmd
*cmd, NvmeRequest *req)
     uint32_t nsid = le32_to_cpu(cmd->nsid);

     if (nsid == 0 || nsid > n->num_namespaces) {
+        trace_nvme_invalid_ns(nsid, n->num_namespaces);
         return NVME_INVALID_NSID | NVME_DNR;
     }

@@ -350,6 +369,7 @@ static uint16_t nvme_io_cmd(NvmeCtrl *n, NvmeCmd
*cmd, NvmeRequest *req)
     case NVME_CMD_READ:
         return nvme_rw(n, ns, cmd, req);
     default:
+        trace_nvme_invalid_opc(cmd->opcode);
         return NVME_INVALID_OPCODE | NVME_DNR;
     }
 }
@@ -374,9 +394,12 @@ static uint16_t nvme_del_sq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qid = le16_to_cpu(c->qid);

     if (!qid || nvme_check_sqid(n, qid)) {
+        trace_nvme_del_sq_invalid(qid);
         return NVME_INVALID_QID | NVME_DNR;
     }

+    trace_nvme_del_sq(qid);
+
     sq = n->sq[qid];
     while (!QTAILQ_EMPTY(&sq->out_req_list)) {
         req = QTAILQ_FIRST(&sq->out_req_list);
@@ -439,19 +462,26 @@ static uint16_t nvme_create_sq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qflags = le16_to_cpu(c->sq_flags);
     uint64_t prp1 = le64_to_cpu(c->prp1);

+    trace_nvme_create_sq(prp1, sqid, cqid, qsize, qflags);
+
     if (!cqid || nvme_check_cqid(n, cqid)) {
+        trace_nvme_create_sq_invalid_cqid(cqid);
         return NVME_INVALID_CQID | NVME_DNR;
     }
     if (!sqid || !nvme_check_sqid(n, sqid)) {
+        trace_nvme_create_sq_invalid_sqid(sqid);
         return NVME_INVALID_QID | NVME_DNR;
     }
     if (!qsize || qsize > NVME_CAP_MQES(n->bar.cap)) {
+        trace_nvme_create_sq_invalid_size(qsize);
         return NVME_MAX_QSIZE_EXCEEDED | NVME_DNR;
     }
     if (!prp1 || prp1 & (n->page_size - 1)) {
+        trace_nvme_create_sq_invalid_addr(prp1);
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     if (!(NVME_SQ_FLAGS_PC(qflags))) {
+        trace_nvme_create_sq_invalid_qflags(NVME_SQ_FLAGS_PC(qflags));
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     sq = g_malloc0(sizeof(*sq));
@@ -477,13 +507,16 @@ static uint16_t nvme_del_cq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qid = le16_to_cpu(c->qid);

     if (!qid || nvme_check_cqid(n, qid)) {
+        trace_nvme_del_cq_invalid_cqid(qid);
         return NVME_INVALID_CQID | NVME_DNR;
     }

     cq = n->cq[qid];
     if (!QTAILQ_EMPTY(&cq->sq_list)) {
+        trace_nvme_del_cq_invalid_notempty(qid);
         return NVME_INVALID_QUEUE_DEL;
     }
+    trace_nvme_del_cq(qid);
     nvme_free_cq(cq, n);
     return NVME_SUCCESS;
 }
@@ -516,19 +549,27 @@ static uint16_t nvme_create_cq(NvmeCtrl *n, NvmeCmd *cmd)
     uint16_t qflags = le16_to_cpu(c->cq_flags);
     uint64_t prp1 = le64_to_cpu(c->prp1);

+    trace_nvme_create_cq(prp1, cqid, vector, qsize, qflags,
+                         NVME_CQ_FLAGS_IEN(qflags) != 0);
+
     if (!cqid || !nvme_check_cqid(n, cqid)) {
+        trace_nvme_create_cq_invalid_cqid(cqid);
         return NVME_INVALID_CQID | NVME_DNR;
     }
     if (!qsize || qsize > NVME_CAP_MQES(n->bar.cap)) {
+        trace_nvme_create_cq_invalid_size(qsize);
         return NVME_MAX_QSIZE_EXCEEDED | NVME_DNR;
     }
     if (!prp1) {
+        trace_nvme_create_cq_invalid_addr(prp1);
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     if (vector > n->num_queues) {
+        trace_nvme_create_cq_invalid_vector(vector);
         return NVME_INVALID_IRQ_VECTOR | NVME_DNR;
     }
     if (!(NVME_CQ_FLAGS_PC(qflags))) {
+        trace_nvme_create_cq_invalid_qflags(NVME_CQ_FLAGS_PC(qflags));
         return NVME_INVALID_FIELD | NVME_DNR;
     }

@@ -543,6 +584,8 @@ static uint16_t nvme_identify_ctrl(NvmeCtrl *n,
NvmeIdentify *c)
     uint64_t prp1 = le64_to_cpu(c->prp1);
     uint64_t prp2 = le64_to_cpu(c->prp2);

+    trace_nvme_identify_ctrl();
+
     return nvme_dma_read_prp(n, (uint8_t *)&n->id_ctrl, sizeof(n->id_ctrl),
         prp1, prp2);
 }
@@ -554,11 +597,15 @@ static uint16_t nvme_identify_ns(NvmeCtrl *n,
NvmeIdentify *c)
     uint64_t prp1 = le64_to_cpu(c->prp1);
     uint64_t prp2 = le64_to_cpu(c->prp2);

+    trace_nvme_identify_ns(nsid);
+
     if (nsid == 0 || nsid > n->num_namespaces) {
+        trace_nvme_invalid_ns(nsid, n->num_namespaces);
         return NVME_INVALID_NSID | NVME_DNR;
     }

     ns = &n->namespaces[nsid - 1];
+
     return nvme_dma_read_prp(n, (uint8_t *)&ns->id_ns, sizeof(ns->id_ns),
         prp1, prp2);
 }
@@ -573,6 +620,8 @@ static uint16_t nvme_identify_nslist(NvmeCtrl *n,
NvmeIdentify *c)
     uint16_t ret;
     int i, j = 0;

+    trace_nvme_identify_nslist(min_nsid);
+
     list = g_malloc0(data_len);
     for (i = 0; i < n->num_namespaces; i++) {
         if (i < min_nsid) {
@@ -601,6 +650,7 @@ static uint16_t nvme_identify(NvmeCtrl *n, NvmeCmd *cmd)
     case 0x02:
         return nvme_identify_nslist(n, c);
     default:
+        trace_nvme_identify_invalid_cns(le32_to_cpu(c->cns));
         return NVME_INVALID_FIELD | NVME_DNR;
     }
 }
@@ -613,11 +663,14 @@ static uint16_t nvme_get_feature(NvmeCtrl *n,
NvmeCmd *cmd, NvmeRequest *req)
     switch (dw10) {
     case NVME_VOLATILE_WRITE_CACHE:
         result = blk_enable_write_cache(n->conf.blk);
+        trace_nvme_getfeat_vwcache(result ? "enabled" : "disabled");
         break;
     case NVME_NUMBER_OF_QUEUES:
         result = cpu_to_le32((n->num_queues - 2) | ((n->num_queues -
2) << 16));
+        trace_nvme_getfeat_numq(result);
         break;
     default:
+        trace_nvme_getfeat_invalid(dw10);
         return NVME_INVALID_FIELD | NVME_DNR;
     }

@@ -635,10 +688,13 @@ static uint16_t nvme_set_feature(NvmeCtrl *n,
NvmeCmd *cmd, NvmeRequest *req)
         blk_set_enable_write_cache(n->conf.blk, dw11 & 1);
         break;
     case NVME_NUMBER_OF_QUEUES:
+        trace_nvme_setfeat_numq((dw11 & 0xFFFF) + 1, ((dw11 >> 16) &
0xFFFF) + 1,
+                                n->num_queues - 1, n->num_queues - 1);
         req->cqe.result =
             cpu_to_le32((n->num_queues - 2) | ((n->num_queues - 2) << 16));
         break;
     default:
+        trace_nvme_setfeat_invalid(dw10);
         return NVME_INVALID_FIELD | NVME_DNR;
     }
     return NVME_SUCCESS;
@@ -662,6 +718,7 @@ static uint16_t nvme_admin_cmd(NvmeCtrl *n,
NvmeCmd *cmd, NvmeRequest *req)
     case NVME_ADM_CMD_GET_FEATURES:
         return nvme_get_feature(n, cmd, req);
     default:
+        trace_nvme_invalid_admin_opc(cmd->opcode);
         return NVME_INVALID_OPCODE | NVME_DNR;
     }
 }
@@ -721,15 +778,72 @@ static int nvme_start_ctrl(NvmeCtrl *n)
     uint32_t page_bits = NVME_CC_MPS(n->bar.cc) + 12;
     uint32_t page_size = 1 << page_bits;

-    if (n->cq[0] || n->sq[0] || !n->bar.asq || !n->bar.acq ||
-            n->bar.asq & (page_size - 1) || n->bar.acq & (page_size - 1) ||
-            NVME_CC_MPS(n->bar.cc) < NVME_CAP_MPSMIN(n->bar.cap) ||
-            NVME_CC_MPS(n->bar.cc) > NVME_CAP_MPSMAX(n->bar.cap) ||
-            NVME_CC_IOCQES(n->bar.cc) < NVME_CTRL_CQES_MIN(n->id_ctrl.cqes) ||
-            NVME_CC_IOCQES(n->bar.cc) > NVME_CTRL_CQES_MAX(n->id_ctrl.cqes) ||
-            NVME_CC_IOSQES(n->bar.cc) < NVME_CTRL_SQES_MIN(n->id_ctrl.sqes) ||
-            NVME_CC_IOSQES(n->bar.cc) > NVME_CTRL_SQES_MAX(n->id_ctrl.sqes) ||
-            !NVME_AQA_ASQS(n->bar.aqa) || !NVME_AQA_ACQS(n->bar.aqa)) {
+    if (n->cq[0]) {
+        trace_nvme_startfail_cq();
+        return -1;
+    }
+    if (n->sq[0]) {
+        trace_nvme_startfail_sq();
+        return -1;
+    }
+    if (!n->bar.asq) {
+        trace_nvme_startfail_nbarasq();
+        return -1;
+    }
+    if (!n->bar.acq) {
+        trace_nvme_startfail_nbaracq();
+        return -1;
+    }
+    if (n->bar.asq & (page_size - 1)) {
+        trace_nvme_startfail_asq_misaligned(n->bar.asq);
+        return -1;
+    }
+    if (n->bar.acq & (page_size - 1)) {
+        trace_nvme_startfail_acq_misaligned(n->bar.asq);
+        return -1;
+    }
+    if (NVME_CC_MPS(n->bar.cc) < NVME_CAP_MPSMIN(n->bar.cap)) {
+        trace_nvme_startfail_page_too_small(
+                    NVME_CC_MPS(n->bar.cc),
+                    NVME_CAP_MPSMIN(n->bar.cap));
+        return -1;
+    }
+    if (NVME_CC_MPS(n->bar.cc) > NVME_CAP_MPSMAX(n->bar.cap)) {
+        trace_nvme_startfail_page_too_large(
+                    NVME_CC_MPS(n->bar.cc),
+                    NVME_CAP_MPSMAX(n->bar.cap));
+        return -1;
+    }
+    if (NVME_CC_IOCQES(n->bar.cc) < NVME_CTRL_CQES_MIN(n->id_ctrl.cqes)) {
+        trace_nvme_startfail_cqent_too_small(
+                    NVME_CC_IOCQES(n->bar.cc),
+                    NVME_CTRL_CQES_MIN(n->bar.cap));
+        return -1;
+    }
+    if (NVME_CC_IOCQES(n->bar.cc) > NVME_CTRL_CQES_MAX(n->id_ctrl.cqes)) {
+        trace_nvme_startfail_cqent_too_large(
+                    NVME_CC_IOCQES(n->bar.cc),
+                    NVME_CTRL_CQES_MAX(n->bar.cap));
+        return -1;
+    }
+    if (NVME_CC_IOSQES(n->bar.cc) < NVME_CTRL_SQES_MIN(n->id_ctrl.sqes)) {
+        trace_nvme_startfail_sqent_too_small(
+                    NVME_CC_IOSQES(n->bar.cc),
+                    NVME_CTRL_SQES_MIN(n->bar.cap));
+        return -1;
+    }
+    if (NVME_CC_IOSQES(n->bar.cc) > NVME_CTRL_SQES_MAX(n->id_ctrl.sqes)) {
+        trace_nvme_startfail_sqent_too_large(
+                    NVME_CC_IOSQES(n->bar.cc),
+                    NVME_CTRL_SQES_MAX(n->bar.cap));
+        return -1;
+    }
+    if (!NVME_AQA_ASQS(n->bar.aqa)) {
+        trace_nvme_startfail_asqent_sz_zero();
+        return -1;
+    }
+    if (!NVME_AQA_ACQS(n->bar.aqa)) {
+        trace_nvme_startfail_acqent_sz_zero();
         return -1;
     }

@@ -753,12 +867,17 @@ static void nvme_write_bar(NvmeCtrl *n, hwaddr
offset, uint64_t data,
     case 0xc:
         n->bar.intms |= data & 0xffffffff;
         n->bar.intmc = n->bar.intms;
+        trace_nvme_mmio_intm_set(data & 0xffffffff,
+                                 n->bar.intmc);
         break;
     case 0x10:
         n->bar.intms &= ~(data & 0xffffffff);
         n->bar.intmc = n->bar.intms;
+        trace_nvme_mmio_intm_clr(data & 0xffffffff,
+                                 n->bar.intmc);
         break;
     case 0x14:
+        trace_nvme_mmio_cfg(data & 0xffffffff);
         /* Windows first sends data, then sends enable bit */
         if (!NVME_CC_EN(data) && !NVME_CC_EN(n->bar.cc) &&
             !NVME_CC_SHN(data) && !NVME_CC_SHN(n->bar.cc))
@@ -769,39 +888,50 @@ static void nvme_write_bar(NvmeCtrl *n, hwaddr
offset, uint64_t data,
         if (NVME_CC_EN(data) && !NVME_CC_EN(n->bar.cc)) {
             n->bar.cc = data;
             if (nvme_start_ctrl(n)) {
+                trace_nvme_mmio_start_failed();
                 n->bar.csts = NVME_CSTS_FAILED;
             } else {
+                trace_nvme_mmio_start_success();
                 n->bar.csts = NVME_CSTS_READY;
             }
         } else if (!NVME_CC_EN(data) && NVME_CC_EN(n->bar.cc)) {
+            trace_nvme_mmio_stopped();
             nvme_clear_ctrl(n);
             n->bar.csts &= ~NVME_CSTS_READY;
         }
         if (NVME_CC_SHN(data) && !(NVME_CC_SHN(n->bar.cc))) {
-                nvme_clear_ctrl(n);
-                n->bar.cc = data;
-                n->bar.csts |= NVME_CSTS_SHST_COMPLETE;
+            trace_nvme_mmio_shutdown_set();
+            nvme_clear_ctrl(n);
+            n->bar.cc = data;
+            n->bar.csts |= NVME_CSTS_SHST_COMPLETE;
         } else if (!NVME_CC_SHN(data) && NVME_CC_SHN(n->bar.cc)) {
-                n->bar.csts &= ~NVME_CSTS_SHST_COMPLETE;
-                n->bar.cc = data;
+            trace_nvme_mmio_shutdown_cleared();
+            n->bar.csts &= ~NVME_CSTS_SHST_COMPLETE;
+            n->bar.cc = data;
         }
         break;
     case 0x24:
+        trace_nvme_mmio_aqattr(data & 0xffffffff);
         n->bar.aqa = data & 0xffffffff;
         break;
     case 0x28:
+        trace_nvme_mmio_asqaddr(data);
         n->bar.asq = data;
         break;
     case 0x2c:
         n->bar.asq |= data << 32;
+        trace_nvme_mmio_asqaddr_hi(data, n->bar.asq);
         break;
     case 0x30:
+        trace_nvme_mmio_acqaddr(data);
         n->bar.acq = data;
         break;
     case 0x34:
         n->bar.acq |= data << 32;
+        trace_nvme_mmio_acqaddr_hi(data, n->bar.acq);
         break;
     default:
+        trace_nvme_mmio_ignored(offset, data);
         break;
     }
 }
diff --git a/hw/block/trace-events b/hw/block/trace-events
index cb6767b3ee..d246339336 100644
--- a/hw/block/trace-events
+++ b/hw/block/trace-events
@@ -10,3 +10,92 @@ virtio_blk_submit_multireq(void *vdev, void *mrb,
int start, int num_reqs, uint6
 # hw/block/hd-geometry.c
 hd_geometry_lchs_guess(void *blk, int cyls, int heads, int secs) "blk
%p LCHS %d %d %d"
 hd_geometry_guess(void *blk, uint32_t cyls, uint32_t heads, uint32_t
secs, int trans) "blk %p CHS %u %u %u trans %d"
+
+# hw/block/nvme.c
+nvme_msix_intr(uint32_t vector) "raising MSI-X IRQ vector %u"
+nvme_pin_intr(void) "pulsing IRQ pin"
+nvme_masked_intr(void) "IRQ is masked"
+
+nvme_dma_read(uint64_t prp1, uint64_t prp2) "DMA read,
prp1=0x%"PRIx64" prp2=0x%"PRIx64""
+nvme_rw(char const *verb, uint32_t blk_count, uint64_t byte_count,
uint64_t lba) "%s %"PRIu32" blocks (%"PRIu64" bytes) from LBA
%"PRIu64""
+
+nvme_dma_too_short(void) "PRP/SGL is too small for transfer size"
+nvme_invalid_prplist_ent(uint64_t prplist) "PRP list entry is null or
not page aligned: 0x%"PRIx64"!"
+nvme_invalid_prp2_align(uint64_t prp2) "PRP2 is not page aligned: %"PRIx64"!"
+nvme_invalid_prp2_missing(void) "PRP2 is null and more data to be transferred!"
+nvme_invalid_field(void) "invalid field!"
+nvme_invalid_prp(void) "invalid PRP!"
+nvme_invalid_sgl(void) "invalid SGL!"
+nvme_invalid_ns(uint32_t ns, uint32_t limit) "invalid namespace %u
not within 1-%u!"
+nvme_invalid_opc(uint8_t opc) "invalid opcode 0x%"PRIx8"!"
+nvme_invalid_admin_opc(uint8_t opc) "invalid admin opcode 0x%"PRIx8"!"
+nvme_invalid_lba_range(uint64_t start, uint64_t len, uint64_t limit)
"Invalid LBA start=%"PRIu64" len=%"PRIu64" limit=%"PRIu64""
+
+nvme_del_sq(uint16_t qid) "deleting submission queue sqid=%"PRIu16""
+nvme_del_sq_invalid(uint16_t qid) "invalid submission queue deletion,
sid=%"PRIu16""
+
+nvme_create_sq(uint64_t addr, uint16_t sqid, uint16_t cqid, uint16_t
qsize, uint16_t qflags) "create submission queue, addr=0x%"PRIx64",
sqid=%"PRIu16", cqid=%"PRIu16", qsize=%"PRIu16", qflags=%"PRIu16""
+nvme_create_sq_invalid_cqid(uint16_t cqid) "failed creating
submission queue, invalid cqid=%"PRIu16"!"
+nvme_create_sq_invalid_sqid(uint16_t sqid) "failed creating
submission queue, invalid sqid=%"PRIu16"!"
+nvme_create_sq_invalid_size(uint16_t qsize) "failed creating
submission queue, invalid qsize=%"PRIu16"!"
+nvme_create_sq_invalid_addr(uint64_t addr) "failed creating
submission queue, addr=0x%"PRIx64"!"
+nvme_create_sq_invalid_qflags(uint16_t qflags) "failed creating
submission queue, qflags=%"PRIu16"!"
+
+nvme_del_cq_invalid_cqid(uint16_t cqid) "failed deleting completion
queue, cqid=%"PRIu16"!"
+nvme_del_cq_invalid_notempty(uint16_t cqid) "failed deleting
completion queue, it is not empty, cqid=%"PRIu16"!"
+nvme_del_cq(uint16_t cqid) "deleted completion queue, sqid=%"PRIu16""
+
+nvme_create_cq(uint64_t addr, uint16_t cqid, uint16_t vector,
uint16_t size, uint16_t qflags, int ien) "create completion queue,
addr=0x%"PRIx64", cqid=%"PRIu16", vector=%"PRIu16", qsize=%"PRIu16",
qflags=%"PRIu16", ien=%d"
+nvme_create_cq_invalid_cqid(uint16_t cqid) "failed creating
completion queue, cqid=%"PRIu16"!"
+nvme_create_cq_invalid_size(uint16_t size) "failed creating
completion queue, size=%"PRIu16"!"
+nvme_create_cq_invalid_addr(uint64_t addr) "failed creating
completion queue, addr=0x%"PRIx64"!"
+nvme_create_cq_invalid_vector(uint16_t vector) "failed creating
completion queue, vector=%"PRIu16"!"
+nvme_create_cq_invalid_qflags(uint16_t qflags) "failed creating
completion queue, qflags=%"PRIu16"!"
+
+nvme_identify_ctrl(void) "identify controller"
+nvme_identify_ns(uint16_t ns) "identify namespace, nsid=%"PRIu16""
+nvme_identify_nslist(uint16_t ns) "identify namespace list, nsid=%"PRIu16""
+nvme_identify_invalid_cns(uint16_t cns) "identify, invalid cns=0x%"PRIx16"!"
+
+nvme_getfeat_vwcache(char const* result) "get feature volatile write
cache, result=%s"
+nvme_getfeat_numq(int result) "get feature number of queues, result=%d"
+nvme_getfeat_invalid(int dw10) "invalid get features, dw10=%"PRIx32"!"
+nvme_setfeat_numq(int reqcq, int reqsq, int gotcq, int gotsq)
"requested cq_count=%d sq_count=%d, responding with cq_count=%d
sq_count=%d"
+nvme_setfeat_invalid(uint32_t dw10) "invalid set features, dw10=%"PRIx32"!"
+
+nvme_startfail_cq(void) "nvme_start_ctrl failed because there are
non-admin completion queues!"
+nvme_startfail_sq(void) "nvme_start_ctrl failed because there are
non-admin submission queues!"
+
+nvme_startfail_nbarasq(void) "nvme_start_ctrl failed because the
admin submission queue address is null!"
+nvme_startfail_nbaracq(void) "nvme_start_ctrl failed because the
admin completion queue address is null!"
+
+nvme_startfail_asq_misaligned(uint64_t addr) "nvme_start_ctrl failed
because the admin submission queue address is misaligned:
0x%"PRIx64"!"
+nvme_startfail_acq_misaligned(uint64_t addr) "nvme_start_ctrl failed
because the admin completion queue address is misaligned:
0x%"PRIx64"!"
+
+nvme_startfail_page_too_small(uint8_t log2ps, uint8_t maxlog2ps)
"nvme_start_ctrl failed because the page size is too small:
log2size=%u, min=%u"
+nvme_startfail_page_too_large(uint8_t log2ps, uint8_t maxlog2ps)
"nvme_start_ctrl failed because the page size is too large:
log2size=%u, max=%u"
+
+nvme_startfail_sqent_too_small(uint8_t log2ps, uint8_t maxlog2ps)
"nvme_start_ctrl failed because the submission queue entry size is too
small: log2size=%u, min=%u"
+nvme_startfail_sqent_too_large(uint8_t log2ps, uint8_t maxlog2ps)
"nvme_start_ctrl failed because the submission queue entry size is too
large: log2size=%u, max=%u"
+
+nvme_startfail_cqent_too_small(uint8_t log2ps, uint8_t maxlog2ps)
"nvme_start_ctrl failed because the completion queue entry size is too
small: log2size=%u, min=%u"
+nvme_startfail_cqent_too_large(uint8_t log2ps, uint8_t maxlog2ps)
"nvme_start_ctrl failed because the completion queue entry size is too
large: log2size=%u, max=%u"
+
+nvme_startfail_acqent_sz_zero(void) "nvme_start_ctrl failed because
the admin completion queue size is zero"
+nvme_startfail_asqent_sz_zero(void) "nvme_start_ctrl failed because
the admin submission queue size is zero"
+
+nvme_mmio_intm_set(uint64_t data, uint64_t new_mask) "wrote MMIO,
interrupt mask set, data=0x%"PRIx64", new_mask=0x%"PRIx64""
+nvme_mmio_intm_clr(uint64_t data, uint64_t new_mask) "wrote MMIO,
interrupt mask clr, data=0x%"PRIx64", new_mask=0x%"PRIx64""
+nvme_mmio_cfg(uint64_t data) "wrote MMIO, config controller config=0x%"PRIx64""
+nvme_mmio_aqattr(uint64_t data) "wrote MMIO, admin queue
attributes=0x%"PRIx64""
+nvme_mmio_asqaddr(uint64_t data) "wrote MMIO, admin submission queue
address=0x%"PRIx64""
+nvme_mmio_acqaddr(uint64_t data) "wrote MMIO, admin completion queue
address=0x%"PRIx64""
+nvme_mmio_asqaddr_hi(uint64_t data, uint64_t new_addr) "wrote MMIO,
admin submission queue high half=0x%"PRIx64", new_address=%"PRIx64""
+nvme_mmio_acqaddr_hi(uint64_t data, uint64_t new_addr) "wrote MMIO,
admin completion queue high half=0x%"PRIx64", new_address=%"PRIx64""
+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"!"
+
-- 
2.11.0

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 <doug16k@gmail.com>
> 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 <doug16k@gmail.com>
> ---

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

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 <eblake@redhat.com> 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 <doug16k@gmail.com>
>> 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 <doug16k@gmail.com>
>> ---
>
> ...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
>

Doug Gale <doug16k@gmail.com> 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.

> On Mon, Oct 9, 2017 at 11:52 AM, Eric Blake <eblake@redhat.com> 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 <doug16k@gmail.com>
>>> 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 <doug16k@gmail.com>
>>> ---
>>
>> ...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.

Am 10.10.2017 um 08:58 hat Markus Armbruster geschrieben:
> Doug Gale <doug16k@gmail.com> 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

> > On Mon, Oct 9, 2017 at 11:52 AM, Eric Blake <eblake@redhat.com> 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 <doug16k@gmail.com>
> >>> 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 <doug16k@gmail.com>
> >>> ---
> >>
> >> ...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.

On Tue, Oct 10, 2017 at 4:02 AM, Kevin Wolf <kwolf@redhat.com> wrote:
> Am 10.10.2017 um 08:58 hat Markus Armbruster geschrieben:
>> Doug Gale <doug16k@gmail.com> 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?

On 10 October 2017 at 09:02, Kevin Wolf <kwolf@redhat.com> wrote:
> 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.

We have qemu_log_mask(LOG_GUEST_ERROR, ...) for logging guest errors,
so I think we should use that.

thanks
-- PMM

On 11/10/2017 15:08, Peter Maydell wrote:
>> 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.
> We have qemu_log_mask(LOG_GUEST_ERROR, ...) for logging guest errors,
> so I think we should use that.

LOG_GUEST_ERROR is something different too.  It means something that is
undefined according to the data sheet more or less, such as accessing a
non-existent reference.

Here the driver does some validation of the values that were written in
the registers, and tells the guest if the validation fails (by putting
something in another registers).  Using a tracepoint sounds like the
right thing to do.

Paolo