Changeset 80596 in vbox

Timestamp:

Sep 5, 2019 7:12:46 AM (5 years ago)

Author:

vboxsync

Message:

Storage/DevVirtioSCSI.cpp: Added code to incorporate aeichner's changes (see bugref:9440, Comment #72). Tested new response status code and discovered it's more accurate to trust sense over rcReq values. Also changed some logging levels to reinstate the option to get hexdumps (with some filtering)

Location:

trunk

Files:

• include/VBox/scsi.h (modified) (1 diff)
• src/VBox/Devices/Storage/DevVirtioSCSI.cpp (modified) (27 diffs)
• src/VBox/Devices/VirtIO/Virtio_1_0.cpp (modified) (19 diffs)
• src/VBox/Devices/VirtIO/Virtio_1_0.h (modified) (2 diffs)
• src/VBox/Devices/VirtIO/Virtio_1_0_impl.h (modified) (2 diffs)

trunk/include/VBox/scsi.h

@@ -238 +238 @@
 #define SCSI_ASCQ_UNKNOWN_FORMAT                            0x01
 #define SCSI_ASCQ_INCOMPATIBLE_FORMAT                       0x02
+#define SCSI_ASCQ_COPY_TARGET_DEVICE_DATA_OVERRUN           0x0d
 
 /** @name SCSI_INQUIRY

trunk/src/VBox/Devices/Storage/DevVirtioSCSI.cpp

@@ -106 +106 @@
 #define CBQUEUENAME(qIdx) RTStrNLen(QUEUENAME(qIdx), sizeof(QUEUENAME(qIdx)))
 
+
 #define IS_REQ_QUEUE(qIdx) (qIdx >= VIRTQ_REQ_BASE && qIdx < VIRTIOSCSI_QUEUE_CNT)
 /**
@@ -463 +464 @@
 /**
  * Request structure for IMediaEx (Associated Interfaces implemented by DrvSCSI)
+ * (NOTE: cbIn, cbOUt, cbDataOut mostly for debugging)
  */
 typedef struct VIRTIOSCSIREQ
@@ -469 +471 @@
     PVIRTIOSCSITARGET              pTarget;                  /**< Target                                            */
     uint16_t                       qIdx;                     /**< Index of queue this request arrived on            */
+    size_t                         cbIn;                     /**< Size of input descriptor chain                    */
+    size_t                         cbOut;                    /**< Size of output descriptor chain                   */
     size_t                         cbPiOut;                  /**< Size of T10 pi in buffer                          */
     uint8_t                       *pbPiOut;                  /**< Address of pi out buffer                          */
     uint8_t                       *pbDataOut;                /**< dataout                                           */
+    size_t                         cbDataOut;                /**< size of dataout buffer                            */
     size_t                         cbPiIn;                   /**< Size of T10 pi buffer                             */
     uint8_t                       *pbPiIn;                   /**< Address of pi in buffer                           */
@@ -477 +482 @@
     uint8_t                       *pbDataIn;                 /**< datain                                            */
     size_t                         cbSense;                  /**< Size of sense buffer                              */
+    size_t                         uSenseLen;                /**< Receives # bytes written into sense buffer        */
     uint8_t                       *pbSense;                  /**< Pointer to R3 sense buffer                        */
+    PDMMEDIAEXIOREQSCSITXDIR       enmTxDir;                 /**< Receives transfer direction of I/O req            */
     uint8_t                        uStatus;                  /**< SCSI status code                                  */
     PRTSGBUF                       pInSgBuf;                 /**< Buf vector to return PDM result to VirtIO Guest   */
@@ -487 +494 @@
 #define SET_LUN_BUF(target, lun, out) \
      out[0] = 0x01;  out[1] = target; out[2] = (lun >> 8) & 0x40;  out[3] = lun & 0xff;  *((uint16_t *)out + 4) = 0;
+
+
+DECLINLINE(bool) isBufZero(uint8_t *pv, size_t cb)
+{
+    for (uint32_t i = 0; i < cb; i++)
+        if (pv[i])
+            return false;
+    return true;
+}
+
+DECLINLINE(const char *) virtioGetTxDirText(uint32_t enmTxDir)
+{
+    switch (enmTxDir)
+    {
+        case PDMMEDIAEXIOREQSCSITXDIR_UNKNOWN:          return "<UNKNOWN>";
+        case PDMMEDIAEXIOREQSCSITXDIR_FROM_DEVICE:      return "<DEV-TO-GUEST>";
+        case PDMMEDIAEXIOREQSCSITXDIR_TO_DEVICE:        return "<GUEST-TO-DEV>";
+        case PDMMEDIAEXIOREQSCSITXDIR_NONE:             return "<NONE>";
+        default:                                        return "<BAD ENUM>";
+    }
+}
 
 
@@ -610 +638 @@
     }
 
-
+#define VIRTIO_IN_DIRECTION(pMediaExTxDirEnumValue) \
+            pMediaExTxDirEnumValue == PDMMEDIAEXIOREQSCSITXDIR_FROM_DEVICE
+
+#define VIRTIO_OUT_DIRECTION(pMediaExTxDirEnumValue) \
+            pMediaExTxDirEnumValue == PDMMEDIAEXIOREQSCSITXDIR_TO_DEVICE
 
 typedef struct VIRTIOSCSIREQ *PVIRTIOSCSIREQ;
@@ -765 +797 @@
 
     return VINF_SUCCESS;
-
-}
+}
+
+/**
+ * This is called to complete a request immediately
+ *
+ * @param pThis     - PDM driver instance state
+ * @param qIdx      - Queue index
+ * @param pRespHdr  - Response header
+ * @param pbSense   - Pointer to sense buffer or NULL if none.
+ *
+ * @returns virtual box status code
+ */
+static int virtioScsiReqErr(PVIRTIOSCSI pThis, uint16_t qIdx, struct REQ_RESP_HDR *pRespHdr, uint8_t *pbSense)
+{
+    uint8_t *abSenseBuf = (uint8_t *)RTMemAllocZ(pThis->virtioScsiConfig.uSenseSize);
+    AssertReturn(abSenseBuf, VERR_NO_MEMORY);
+
+    Log2Func(("   status: %s    response: %s\n",
+              SCSIStatusText(pRespHdr->uStatus),  virtioGetReqRespText(pRespHdr->uResponse)));
+
+    RTSGSEG aReqSegs[2];
+    aReqSegs[0].cbSeg = sizeof(pRespHdr);
+    aReqSegs[0].pvSeg = pRespHdr;
+    aReqSegs[1].cbSeg = pThis->virtioScsiConfig.uSenseSize;
+    aReqSegs[1].pvSeg = abSenseBuf;
+
+    if (pbSense && pRespHdr->uSenseLen)
+        memcpy(abSenseBuf, pbSense, pRespHdr->uSenseLen);
+    else
+        pRespHdr->uSenseLen = 0;
+
+    RTSGBUF reqSegBuf;
+    RTSgBufInit(&reqSegBuf, aReqSegs, RT_ELEMENTS(aReqSegs));
+
+    virtioQueuePut(pThis->hVirtio, qIdx, &reqSegBuf, true /* fFence */);
+    virtioQueueSync(pThis->hVirtio, qIdx);
+
+    RTMemFree(abSenseBuf);
+
+    Log(("---------------------------------------------------------------------------------\n"));
+
+    return VINF_SUCCESS;
+}
+
 /** TBD: VirtIO 1.0 spec 5.6.6.1.1 requires some request actions on reset that are
  *       not implemented.  Specifically either canceling outstanding I/O or
@@ -795 +869 @@
     #define SHOULD_FIX_VSCSI_TO_RETURN_SENSE_LEN 32
     struct REQ_RESP_HDR respHdr = { 0 };
-    respHdr.uSenseLen = pReq->uStatus == SCSI_STATUS_CHECK_CONDITION ? SHOULD_FIX_VSCSI_TO_RETURN_SENSE_LEN : 0;
+    respHdr.uSenseLen = pReq->pbSense[2] == SCSI_SENSE_NONE ? 0 : pReq->uSenseLen;
     respHdr.uResidual = cbResidual;
     respHdr.uStatus   = pReq->uStatus;
@@ -810 +884 @@
                 break;
             }
-            /* fallthrough */
-        case SCSI_STATUS_BUSY:
-            respHdr.uResponse = VIRTIOSCSI_S_BUSY;
-            break;
-        case SCSI_STATUS_DATA_UNDEROVER_RUN:
-            respHdr.uResponse = VIRTIOSCSI_S_OVERRUN;
-            break;
-        case SCSI_STATUS_TASK_ABORTED:
-            respHdr.uResponse = VIRTIOSCSI_S_ABORTED;
-            break;
         case SCSI_STATUS_CHECK_CONDITION:
             {
@@ -838 +902 @@
                         break;
                     case SCSI_SENSE_NOT_READY:
-                        respHdr.uResponse = VIRTIOSCSI_S_BUSY; /* e.g. try again */
+                        respHdr.uResponse = VIRTIOSCSI_S_BUSY; /* e.g. re-tryable */
                         break;
                     default:
@@ -852 +916 @@
     }
 
-    Log2Func(("status: %s,   response: (%x) %s\n",
-              SCSIStatusText(pReq->uStatus), respHdr.uResponse, virtioGetReqRespText(respHdr.uResponse)));
+    Log2Func(("status: (%d) %s,   response: (%d) %s\n",
+              pReq->uStatus, SCSIStatusText(pReq->uStatus), respHdr.uResponse, virtioGetReqRespText(respHdr.uResponse)));
 
     if (RT_FAILURE(rcReq))
         Log2Func(("rcReq:  %s\n", RTErrGetDefine(rcReq)));
 
-    Log3Func(("status:%02x/resp:%02x, xfer=%d, residual: %u, sense (len=%d, alloc=%d)\n",
-              pReq->uStatus, respHdr.uResponse, cbXfer, cbResidual,
-              respHdr.uSenseLen, pThis->virtioScsiConfig.uSenseSize));
+    if (LogIs3Enabled())
+    {
+        LogFunc(("cbDataIn = %u, cbDataOut = %u (cbIn = %u, cbOut = %u)\n",
+                  pReq->cbDataIn, pReq->cbDataOut, pReq->cbIn, pReq->cbOut));
+        LogFunc(("xfer = %d, residual = %u\n", cbXfer, cbResidual));
+        LogFunc(("xfer direction: %s, sense written = %d, sense size = %d\n",
+             virtioGetTxDirText(pReq->enmTxDir), respHdr.uSenseLen, pThis->virtioScsiConfig.uSenseSize));
+    }
 
     if (respHdr.uSenseLen && LogIs2Enabled())
     {
-        Log2Func(("Sense: %s\n", SCSISenseText(pReq->pbSense[2])));
-        Log2Func(("Sense Ext3: %s\n", SCSISenseExtText(pReq->pbSense[12], pReq->pbSense[13])));
+        LogFunc(("Sense: %s\n", SCSISenseText(pReq->pbSense[2])));
+        LogFunc(("Sense Ext3: %s\n", SCSISenseExtText(pReq->pbSense[12], pReq->pbSense[13])));
+    }
+
+    if (LogIsItEnabled(RTLOGGRPFLAGS_LEVEL_12, LOG_GROUP))
+    {
+        size_t cb = RT_MIN(cbXfer, 256);
+        if (VIRTIO_IN_DIRECTION(pReq->enmTxDir))
+        {
+            Log(("datain[256 of %d total bytes xferred]:\n", cbXfer));
+            if (!isBufZero(pReq->pbDataIn, cb))
+                VIRTIO_HEX_DUMP(RTLOGGRPFLAGS_LEVEL_12, pReq->pbDataIn,  cb,  0, 0);
+            else
+                Log12(("-- %d zeroes --\n", cb));
+        }
+        else
+        if (VIRTIO_OUT_DIRECTION(pReq->enmTxDir))
+        {
+            Log(("dataout[256 of %d total bytes xferred]:\n", cbXfer));
+            if (!isBufZero(pReq->pbDataOut, cb))
+                VIRTIO_HEX_DUMP(RTLOGGRPFLAGS_LEVEL_12, pReq->pbDataOut, cb, 0, 0);
+            else
+                Log12(("-- %d zeroes --\n", cb));
+        }
     }
 
     int cSegs = 0;
 
-
-//    Assert(pReq->cbDataIn >= cbXfer);
-    Assert(pReq->pbSense != NULL);
-
-    RTSGSEG aReqSegs[4];
-    aReqSegs[cSegs].pvSeg   = &respHdr;
-    aReqSegs[cSegs++].cbSeg = sizeof(respHdr);
-
-    aReqSegs[cSegs].pvSeg   = pReq->pbSense;
-    aReqSegs[cSegs++].cbSeg = pReq->cbSense; /* VirtIO 1.0 spec 5.6.4/5.6.6.1 */
-
-    if (pReq->cbPiIn)
-    {
-        aReqSegs[cSegs].pvSeg   = pReq->pbPiIn;
-        aReqSegs[cSegs++].cbSeg = pReq->cbPiIn;
-    }
-    if (pReq->cbDataIn)
-    {
-        aReqSegs[cSegs].pvSeg   = pReq->pbDataIn;
-        aReqSegs[cSegs++].cbSeg = cbXfer;
-    }
-    RTSGBUF reqSegBuf;
-    RTSgBufInit(&reqSegBuf, aReqSegs, cSegs);
-
-    /**
-     * Fill in the request queue current descriptor chain's IN queue entry/entries
-     * (phys. memory) with the Req response data in virtual memory.
-     */
-    size_t cbReqSgBuf = RTSgBufCalcTotalLength(&reqSegBuf);
-    size_t cbInSgBuf  = RTSgBufCalcTotalLength(pReq->pInSgBuf);
-    AssertMsgReturn(cbReqSgBuf <= cbInSgBuf,
-                   ("Guest expected less req data (space needed: %d, avail: %d)\n", cbReqSgBuf, cbInSgBuf),
-                   VERR_BUFFER_OVERFLOW);
-
-    /**
-     * Following doesn't put up memory barrier (fence).
-     * VirtIO 1.0 Spec requires mem. barrier for ctrl cmds
-     * but doesn't mention fences in regard to requests. */
-    virtioQueuePut(pThis->hVirtio, pReq->qIdx, &reqSegBuf, true /* fFence TBD */);
-    virtioQueueSync(pThis->hVirtio, pReq->qIdx);
-
-    Log(("-----------------------------------------------------------------------------------------\n"));
-
+    if (   (VIRTIO_IN_DIRECTION(pReq->enmTxDir)  && cbXfer > pReq->cbDataIn)
+        || (VIRTIO_OUT_DIRECTION(pReq->enmTxDir) && cbXfer > pReq->cbDataOut))
+    {
+        /** TBD try to figure out optimal sense info to send back besides response of VIRTIOSCSI_S_OVERRUN */
+        Log2Func((" * * * * Data overrun, returning sense\n"));
+        uint8_t abSense[] = { RT_BIT(7) | SCSI_SENSE_RESPONSE_CODE_CURR_FIXED,
+                              0, SCSI_SENSE_ILLEGAL_REQUEST, 0, 0, 0, 0, 10, 0, 0, 0 };
+        respHdr.uSenseLen = sizeof(abSense);
+        respHdr.uStatus   = SCSI_STATUS_CHECK_CONDITION;
+        respHdr.uResponse = VIRTIOSCSI_S_OVERRUN;
+        respHdr.uResidual = pReq->cbDataIn;
+        virtioScsiReqErr(pThis, pReq->qIdx, &respHdr, abSense);
+    }
+    else
+    {
+        Assert(pReq->pbSense != NULL);
+
+        RTSGSEG aReqSegs[4];
+        aReqSegs[cSegs].pvSeg   = &respHdr;
+        aReqSegs[cSegs++].cbSeg = sizeof(respHdr);
+
+        aReqSegs[cSegs].pvSeg   = pReq->pbSense;
+        aReqSegs[cSegs++].cbSeg = pReq->cbSense; /* VirtIO 1.0 spec 5.6.4/5.6.6.1 */
+
+        if (pReq->cbPiIn)
+        {
+            aReqSegs[cSegs].pvSeg   = pReq->pbPiIn;
+            aReqSegs[cSegs++].cbSeg = pReq->cbPiIn;
+        }
+        if (pReq->cbDataIn)
+        {
+            aReqSegs[cSegs].pvSeg   = pReq->pbDataIn;
+            aReqSegs[cSegs++].cbSeg = cbXfer;
+        }
+        RTSGBUF reqSegBuf;
+        RTSgBufInit(&reqSegBuf, aReqSegs, cSegs);
+
+        /**
+         * Fill in the request queue current descriptor chain's IN queue entry/entries
+         * (phys. memory) with the Req response data in virtual memory.
+         */
+        size_t cbReqSgBuf = RTSgBufCalcTotalLength(&reqSegBuf);
+        size_t cbInSgBuf  = RTSgBufCalcTotalLength(pReq->pInSgBuf);
+        AssertMsgReturn(cbReqSgBuf <= cbInSgBuf,
+                       ("Guest expected less req data (space needed: %d, avail: %d)\n", cbReqSgBuf, cbInSgBuf),
+                       VERR_BUFFER_OVERFLOW);
+
+        virtioQueuePut(pThis->hVirtio, pReq->qIdx, &reqSegBuf, true /* fFence TBD */);
+        virtioQueueSync(pThis->hVirtio, pReq->qIdx);
+
+        Log(("-----------------------------------------------------------------------------------------\n"));
+
+    }
     RTMemFree(pReq->pbSense);
     RTMemFree(pReq->pbDataIn);
@@ -926 +1027 @@
 }
 
-/**
- * This is called to complete a request immediately
- *
- * @param pThis     - PDM driver instance state
- * @param qIdx      - Queue index
- * @param pRespHdr  - Response header
- * @param pbSense   - Pointer to sense buffer or NULL if none.
- *
- * @returns virtual box status code
- */
-static int virtioScsiReqFinish(PVIRTIOSCSI pThis, uint16_t qIdx, struct REQ_RESP_HDR *pRespHdr, uint8_t *pbSense)
-{
-    uint8_t *abSenseBuf = (uint8_t *)RTMemAllocZ(pThis->virtioScsiConfig.uSenseSize);
-    AssertReturn(abSenseBuf, VERR_NO_MEMORY);
-
-    Log2Func(("status: %s    response: %s\n",
-              SCSIStatusText(pRespHdr->uStatus),  virtioGetReqRespText(pRespHdr->uResponse)));
-
-    RTSGSEG aReqSegs[2];
-    aReqSegs[0].cbSeg = sizeof(pRespHdr);
-    aReqSegs[0].pvSeg = pRespHdr;
-    aReqSegs[1].cbSeg = pThis->virtioScsiConfig.uSenseSize;
-    aReqSegs[1].pvSeg = abSenseBuf;
-
-    if (pbSense && pRespHdr->uSenseLen)
-        memcpy(abSenseBuf, pbSense, pRespHdr->uSenseLen);
-    else
-        pRespHdr->uSenseLen = 0;
-
-    RTSGBUF reqSegBuf;
-    RTSgBufInit(&reqSegBuf, aReqSegs, RT_ELEMENTS(aReqSegs));
-
-    virtioQueuePut(pThis->hVirtio, qIdx, &reqSegBuf, true /* fFence */);
-    virtioQueueSync(pThis->hVirtio, qIdx);
-
-    RTMemFree(abSenseBuf);
-
-    Log(("---------------------------------------------------------------------------------\n"));
-
-    return VINF_SUCCESS;
-}
-
 static int virtioScsiReqSubmit(PVIRTIOSCSI pThis, uint16_t qIdx, PRTSGBUF pInSgBuf, PRTSGBUF pOutSgBuf)
 {
@@ -975 +1034 @@
     size_t cbIn  = RTSgBufCalcTotalLength(pInSgBuf);
 
-    AssertMsgReturn(cbOut >= sizeof(REQ_CMD_HDR) + pThis->virtioScsiConfig.uCdbSize,
-                        ("Req too short"), VERR_BUFFER_UNDERFLOW);
-
-    PVIRTIOSCSI_REQ_CMD_T pVirtqReq = (PVIRTIOSCSI_REQ_CMD_T)RTMemAlloc(cbOut);
+    /** MAKE THIS NON-ZERO MALLOCING AFTER DEBUG */
+    PVIRTIOSCSI_REQ_CMD_T pVirtqReq = (PVIRTIOSCSI_REQ_CMD_T)RTMemAllocZ(cbOut);
     AssertReturn(pVirtqReq, VERR_NO_MEMORY);
 
@@ -992 +1049 @@
     }
 
+//    VIRTIO_HEX_DUMP(RTLOGGRPFLAGS_LEVEL_12, (uint8_t *)pVirtqReq,  cbOut,  0, "\npVirtqReq");
+
     uint8_t  uTarget =  pVirtqReq->cmdHdr.uLUN[1];
     uint32_t uLUN    = (pVirtqReq->cmdHdr.uLUN[2] << 8 | pVirtqReq->cmdHdr.uLUN[3]) & 0x3fff;
@@ -997 +1056 @@
     LogFunc(("[%s] (Target: %d LUN: %d)  CDB: %.*Rhxs\n",
         SCSICmdText(pVirtqReq->uCdb[0]), uTarget, uLUN,
-        virtioScsiEstimateCdbLen(pVirtqReq->uCdb[0], pThis->virtioScsiConfig.uCdbSize), pVirtqReq->uCdb));
-
-    Log3Func(("   id: %RX64, attr: %x, prio: %d, crn: %x\n",
+        virtioScsiEstimateCdbLen(pVirtqReq->uCdb[0],
+        pThis->virtioScsiConfig.uCdbSize), pVirtqReq->uCdb));
+
+    Log3Func(("id: %RX64, attr: %x, prio: %d, crn: %x\n",
         pVirtqReq->cmdHdr.uId, pVirtqReq->cmdHdr.uTaskAttr, pVirtqReq->cmdHdr.uPrio, pVirtqReq->cmdHdr.uCrn));
 
@@ -1016 +1076 @@
     }
 
-    off_t   uDataOutOff = sizeof(REQ_CMD_HDR)  + pThis->virtioScsiConfig.uCdbSize + cbPiHdr;
+    off_t   uDataOutOff = sizeof(REQ_CMD_HDR)  + pThis->virtioScsiConfig.uCdbSize   + cbPiHdr;
     off_t   uDataInOff  = sizeof(REQ_RESP_HDR) + pThis->virtioScsiConfig.uSenseSize + cbPiIn;
     uint8_t *pbDataOut = (uint8_t *)((uint64_t)pVirtqReq + uDataOutOff);
@@ -1032 +1092 @@
         respHdr.uResponse = (uTarget > pThis->cTargets) ? VIRTIOSCSI_S_BAD_TARGET : VIRTIOSCSI_S_OK;
         respHdr.uResidual = cbDataOut + cbDataIn;
-        virtioScsiReqFinish(pThis, qIdx, &respHdr, abSense);
+        virtioScsiReqErr(pThis, qIdx, &respHdr, abSense);
         return VINF_SUCCESS;
     }
@@ -1048 +1108 @@
         respHdr.uResponse = VIRTIOSCSI_S_TARGET_FAILURE;
         respHdr.uResidual = cbDataIn + cbDataOut;
-        virtioScsiReqFinish(pThis, qIdx, &respHdr, abSense);
+        virtioScsiReqErr(pThis, qIdx, &respHdr, abSense);
         RTMemFree(pVirtqReq);
         return VINF_SUCCESS;
@@ -1074 +1134 @@
     pReq->pTarget   = pTarget;
     pReq->qIdx      = qIdx;
+    pReq->cbIn      = cbIn;
+    pReq->cbOut     = cbOut;
     pReq->pbDataOut = pbDataOut;
+    pReq->cbDataOut = cbDataOut;
     pReq->pVirtqReq = pVirtqReq;
     pReq->pInSgBuf  = pInSgBuf;
@@ -1092 +1155 @@
     rc = pIMediaEx->pfnIoReqSendScsiCmd(pIMediaEx, pReq->hIoReq, uLUN,
                                         pVirtqReq->uCdb, pThis->virtioScsiConfig.uCdbSize,
-                                        PDMMEDIAEXIOREQSCSITXDIR_UNKNOWN, NULL, cbDataIn,
-                                        pReq->pbSense, pReq->cbSense, NULL,
+                                        PDMMEDIAEXIOREQSCSITXDIR_UNKNOWN, &pReq->enmTxDir, cbDataIn,
+                                        pReq->pbSense, pReq->cbSense, &pReq->uSenseLen,
                                         &pReq->uStatus, 30 * RT_MS_1SEC);
 
@@ -1124 +1187 @@
         respHdr.uResponse = VIRTIOSCSI_S_FAILURE;
         respHdr.uResidual = cbDataIn + cbDataOut;
-        virtioScsiReqFinish(pThis, qIdx, &respHdr, abSense);
+        virtioScsiReqErr(pThis, qIdx, &respHdr, abSense);
         RTMemFree(pReq->pbSense);
         RTMemFree(pReq->pbDataIn);
@@ -1336 +1399 @@
             if (!fNotificationSent)
             {
-                Log3Func(("%s worker sleeping...\n", QUEUENAME(qIdx)));
+                Log6Func(("%s worker sleeping...\n", QUEUENAME(qIdx)));
                 Assert(ASMAtomicReadBool(&pWorker->fSleeping));
                 rc = SUPSemEventWaitNoResume(pThis->pSupDrvSession, pWorker->hEvtProcess, RT_INDEFINITE_WAIT);
@@ -1342 +1405 @@
                 if (RT_UNLIKELY(pThread->enmState != PDMTHREADSTATE_RUNNING))
                     break;
-                Log3Func(("%s worker woken\n", QUEUENAME(qIdx)));
+                Log6Func(("%s worker woken\n", QUEUENAME(qIdx)));
                 ASMAtomicWriteBool(&pWorker->fNotified, false);
             }
             ASMAtomicWriteBool(&pWorker->fSleeping, false);
         }
-        Log3Func(("fetching next descriptor chain from %s\n", QUEUENAME(qIdx)));
+        Log6Func(("fetching next descriptor chain from %s\n", QUEUENAME(qIdx)));
         rc = virtioQueueGet(pThis->hVirtio, qIdx, true, &pInSgBuf, &pOutSgBuf);
         if (rc == VERR_NOT_AVAILABLE)
@@ -1576 +1639 @@
     if (qIdx == CONTROLQ_IDX || IS_REQ_QUEUE(qIdx))
     {
-        Log3Func(("%s has available data\n", QUEUENAME(qIdx)));
+        Log6Func(("%s has available data\n", QUEUENAME(qIdx)));
         /** Wake queue's worker thread up if sleeping */
         if (!ASMAtomicXchgBool(&pWorker->fNotified, true))
@@ -1582 +1645 @@
             if (ASMAtomicReadBool(&pWorker->fSleeping))
             {
-                Log3Func(("waking %s worker.\n", QUEUENAME(qIdx)));
+                Log6Func(("waking %s worker.\n", QUEUENAME(qIdx)));
                 int rc = SUPSemEventSignal(pThis->pSupDrvSession, pWorker->hEvtProcess);
                 AssertRC(rc);
@@ -2145 +2208 @@
         return PDMDEV_SET_ERROR(pDevIns, rc, N_("virtio-scsi: failed to initialize VirtIO"));
 
-
     RTStrCopy((char *)pThis->szQueueNames[CONTROLQ_IDX], VIRTIO_MAX_QUEUE_NAME_SIZE, "controlq");
     RTStrCopy((char *)pThis->szQueueNames[EVENTQ_IDX],   VIRTIO_MAX_QUEUE_NAME_SIZE, "eventq");
@@ -2152 +2214 @@
             "requestq<%d>", qIdx - VIRTQ_REQ_BASE);
 
-    /**
-     * Create one worker per incoming-work-related queue (eventq is outgoing status to guest,
-     * wherein guest is supposed to keep the queue loaded-up with buffer vectors the host
-     * can quickly fill-in send back). Should be light-duty and fast enough to be handled on
-     * requestq or controlq thread.  The Linux virtio_scsi driver limits the number of request
-     * queues to MIN(<# Guest CPUs>, <Device's req queue max>), so queue count is ultimately
-     * constrained from host side at negotiation time and initialization and later through
-     * bounds-checking.
-     */
     for (uint16_t qIdx = 0; qIdx < VIRTIOSCSI_QUEUE_CNT; qIdx++)
     {

trunk/src/VBox/Devices/VirtIO/Virtio_1_0.cpp

@@ -81 +81 @@
             if (pszDepiction[i] == ' ' && first++)
                 pszDepiction[i] = '.';
-        Log3Func(("%s: Guest %s %s 0x%s\n",
+        Log6Func(("%s: Guest %s %s 0x%s\n",
                   pszFunc, fWrite ? "wrote" : "read ", pszDepiction, pszFormattedVal));
     }
     else /* odd number or oversized access, ... log inline hex-dump style */
     {
-        Log3Func(("%s: Guest %s %s%s[%d:%d]: %.*Rhxs\n",
+        Log6Func(("%s: Guest %s %s%s[%d:%d]: %.*Rhxs\n",
               pszFunc, fWrite ? "wrote" : "read ", pszMember,
               pszIdx, uOffset, uOffset + cb, cb, pv));
@@ -199 +199 @@
     uint16_t uDescIdx = pDescChain->uHeadIdx;
 
-    Log3Func(("%s DESC CHAIN: (head) desc_idx=%u [avail_idx=%u]\n",
+    Log6Func(("%s DESC CHAIN: (head) desc_idx=%u [avail_idx=%u]\n",
             pVirtqProxy->szVirtqName, pDescChain->uHeadIdx, pVirtqProxy->uAvailIdx));
 
@@ -238 +238 @@
         if (desc.fFlags & VIRTQ_DESC_F_WRITE)
         {
-            Log3Func(("%s IN  desc_idx=%u seg=%u addr=%RGp cb=%u\n",
+            Log6Func(("%s IN  desc_idx=%u seg=%u addr=%RGp cb=%u\n",
                 QUEUENAME(qIdx), uDescIdx, pDescChain->cSegsIn, desc.pGcPhysBuf, desc.cb));
             cbIn += desc.cb;
@@ -245 +245 @@
         else
         {
-            Log3Func(("%s OUT desc_idx=%u seg=%u addr=%RGp cb=%u\n",
+            Log6Func(("%s OUT desc_idx=%u seg=%u addr=%RGp cb=%u\n",
                 QUEUENAME(qIdx), uDescIdx, pDescChain->cSegsOut, desc.pGcPhysBuf, desc.cb));
             cbOut += desc.cb;
@@ -261 +261 @@
 
     if (ppInSegs)
-        *ppInSegs  = &pVirtqProxy->inSgBuf;
+        *ppInSegs = &pVirtqProxy->inSgBuf;
 
     if (ppOutSegs)
         *ppOutSegs = &pVirtqProxy->outSgBuf;
 
-    Log3Func(("%s -- segs OUT: %u (%u bytes)   IN: %u (%u bytes) --\n",
+    Log6Func(("%s -- segs OUT: %u (%u bytes)   IN: %u (%u bytes) --\n",
               pVirtqProxy->szVirtqName, pDescChain->cSegsOut, cbOut, pDescChain->cSegsIn, cbIn));
 
@@ -292 +292 @@
     size_t cbRemain = RTSgBufCalcTotalLength(pBufSrc);
     uint16_t uUsedIdx = virtioReadUsedRingIdx(pVirtio, qIdx);
-    Log3Func(("Copying client data to %s, desc chain (head desc_idx %d)\n",
+    Log6Func(("Copying client data to %s, desc chain (head desc_idx %d)\n",
                QUEUENAME(qIdx), uUsedIdx));
 
@@ -328 +328 @@
         size_t cbInSgBuf = RTSgBufCalcTotalLength(pBufDst);
         size_t cbWritten = cbInSgBuf - RTSgBufCalcLengthLeft(pBufDst);
-        Log2Func(("Copied %u bytes to %u byte buffer, residual=%d\n",
+        Log2Func((".... Copied %u bytes to %u byte buffer, residual=%d\n",
              cbWritten, cbInSgBuf, cbInSgBuf - cbWritten));
     }
-    Log3Func(("Write ahead used_idx=%d, %s used_idx=%d\n",
+    Log6Func(("Write ahead used_idx=%d, %s used_idx=%d\n",
          pVirtqProxy->uUsedIdx,  QUEUENAME(qIdx), uUsedIdx));
 
@@ -351 +351 @@
 
     uint16_t uIdx = virtioReadUsedRingIdx(pVirtio, qIdx);
-    Log3Func(("Updating %s used_idx from %u to %u\n",
+    Log6Func(("Updating %s used_idx from %u to %u\n",
               QUEUENAME(qIdx), uIdx, pVirtqProxy->uUsedIdx));
 
@@ -368 +368 @@
 
     PVIRTQ_PROXY_T pVirtqProxy = &pVirtio->virtqProxy[qIdx];
-    Log3Func(("%s\n", pVirtqProxy->szVirtqName));
+    Log6Func(("%s\n", pVirtqProxy->szVirtqName));
 
 
@@ -398 +398 @@
                 return;
             }
-            Log3Func(("...skipping interrupt: VIRTIO_F_EVENT_IDX set but threshold not reached\n"));
+            Log6Func(("...skipping interrupt: VIRTIO_F_EVENT_IDX set but threshold not reached\n"));
         }
         else
@@ -408 +408 @@
                 return;
             }
-            Log3Func(("...skipping interrupt. Guest flagged VIRTQ_AVAIL_F_NO_INTERRUPT for queue\n"));
+            Log6Func(("...skipping interrupt. Guest flagged VIRTQ_AVAIL_F_NO_INTERRUPT for queue\n"));
 
         }
@@ -456 +456 @@
 {
    if (uCause == VIRTIO_ISR_VIRTQ_INTERRUPT)
-       Log3Func(("reason: buffer added to 'used' ring.\n"));
+       Log6Func(("reason: buffer added to 'used' ring.\n"));
    else
    if (uCause == VIRTIO_ISR_DEVICE_CONFIG)
-       Log3Func(("reason: device config change\n"));
+       Log6Func(("reason: device config change\n"));
 
     pVirtio->uISR |= uCause;
@@ -642 +642 @@
         {
             pVirtio->uDeviceStatus = *(uint8_t *)pv;
-            Log3Func(("Guest wrote uDeviceStatus ................ ("));
+            Log6Func(("Guest wrote uDeviceStatus ................ ("));
             virtioLogDeviceStatus(pVirtio->uDeviceStatus);
-            Log3((")\n"));
+            Log6((")\n"));
             if (pVirtio->uDeviceStatus == 0)
                 virtioGuestResetted(pVirtio);
@@ -659 +659 @@
         else /* Guest READ pCommonCfg->uDeviceStatus */
         {
-            Log3Func(("Guest read  uDeviceStatus ................ ("));
+            Log6Func(("Guest read  uDeviceStatus ................ ("));
             *(uint32_t *)pv = pVirtio->uDeviceStatus;
             virtioLogDeviceStatus(pVirtio->uDeviceStatus);
-            Log3((")\n"));
+            Log6((")\n"));
         }
     }
@@ -764 +764 @@
         {
             ++pVirtio->uConfigGeneration;
-            Log3Func(("Bumped cfg. generation to %d because %s%s\n",
+            Log6Func(("Bumped cfg. generation to %d because %s%s\n",
                 pVirtio->uConfigGeneration,
                 fDevSpecificFieldChanged ? "<dev cfg changed> " : "",
@@ -781 +781 @@
     {
         *(uint8_t *)pv = pVirtio->uISR;
-        Log3Func(("Read and clear ISR\n"));
+        Log6Func(("Read and clear ISR\n"));
         pVirtio->uISR = 0; /** VirtIO specification requires reads of ISR to clear it */
         virtioLowerInterrupt(pVirtio);
@@ -832 +832 @@
     {
         pVirtio->uISR = *(uint8_t *)pv;
-        Log3Func(("Setting uISR = 0x%02x (virtq interrupt: %d, dev confg interrupt: %d)\n",
+        Log6Func(("Setting uISR = 0x%02x (virtq interrupt: %d, dev confg interrupt: %d)\n",
               pVirtio->uISR & 0xff,
               pVirtio->uISR & VIRTIO_ISR_VIRTQ_INTERRUPT,
@@ -1045 +1045 @@
 
     int rc = VINF_SUCCESS;
-
 
     PVIRTIOSTATE pVirtio = (PVIRTIOSTATE)RTMemAllocZ(sizeof(VIRTIOSTATE));
@@ -1463 +1462 @@
 }
 
+ /**
+  * Do a hex dump of a buffer.
+  *
+  * @param   pv       Pointer to array to dump
+  * @param   cb       Number of characters to dump
+  * @param   uBase    Base address of offset addresses displayed
+  * @param   pszTitle Header line/title for the dump
+  *
+  */
+ void virtioHexDump(uint8_t *pv, size_t cb, uint32_t uBase, const char *pszTitle)
+ {
+     if (pszTitle)
+         Log(("%s [%d bytes]:\n", pszTitle, cb));
+     for (uint32_t row = 0; row < RT_MAX(1, (cb / 16) + 1); row++)
+     {
+         uint32_t uAddr = row * 16 + uBase;
+         Log(("%x%x%x%x: ", (uAddr >> 12) & 0xf, (uAddr >> 8) & 0xf, (uAddr >> 4) & 0xf, uAddr & 0xf));
+         for (int col = 0; col < 16; col++)
+         {
+            uint32_t idx = row * 16 + col;
+            uint8_t u8 = pv[idx];
+            if (idx >= cb)
+                Log(("-- %s", (col + 1) % 8 ? "" : "  "));
+            else
+                Log(("%x%x %s", u8 >> 4 & 0xf, u8 & 0xf, (col + 1) % 8 ? "" : "  "));
+         }
+         for (int col = 0; col < 16; col++)
+         {
+            uint32_t idx = row * 16 + col;
+            uint8_t u8 = pv[idx];
+            if (idx >= cb)
+                Log((" "));
+            else
+                Log(("%c", u8 >= 0x20 && u8 <= 0x7e ? u8 : '.'));
+         }
+         Log(("\n"));
+    }
+    Log(("\n"));
+ }
 
 #endif /* IN_RING3 */

trunk/src/VBox/Devices/VirtIO/Virtio_1_0.h

@@ -41 +41 @@
 #define VIRTIOSCSI_REGION_PORT_IO           1                    /**< BAR for PORT I/O (impl specific)         */
 #define VIRTIOSCSI_REGION_PCI_CAP           2                    /**< BAR for VirtIO Cap. MMIO (impl specific) */
+
+#define VIRTIO_HEX_DUMP(logLevel, pv, cb, base, title) \
+    do { \
+        if (LogIsItEnabled(logLevel, LOG_GROUP)) \
+            virtioHexDump((pv), (cb), (base), (title)); \
+    } while (0)
 
 /**
@@ -320 +326 @@
                             bool fWrite, bool fHasIndex, uint32_t idx);
 
+/**
+ * Does a formatted hex dump using Log(()), recommend using VIRTIO_HEX_DUMP() macro to
+ * control enabling of logging efficiently.
+ *
+ * @param   pv          - pointer to buffer to dump contents of
+ * @param   cb          - count of characters to dump from buffer
+ * @param   uBase       - base address of per-row address prefixing of hex output
+ * @param   pszTitle    - Optional title. If present displays title that lists
+ *                        provided text with value of cb to indicate size next to it.
+ */
+void virtioHexDump(uint8_t *pv, size_t cb, uint32_t uBase, const char *pszTitle);
 
 #endif /* !VBOX_INCLUDED_SRC_VirtIO_Virtio_1_0_h */

trunk/src/VBox/Devices/VirtIO/Virtio_1_0_impl.h

@@ -409 +409 @@
                       pVirtio->pGcPhysQueueAvail[qIdx] + RT_UOFFSETOF(VIRTQ_AVAIL_T, uIdx),
                       &uIdx, sizeof(uIdx));
-    Log3Func(("%s actual avail_idx=%d\n", pVirtio->virtqProxy[qIdx].szVirtqName, uIdx));
     return uIdx;
 }
@@ -512 +511 @@
 {
     if (status == 0)
-        Log3(("RESET"));
+        Log6(("RESET"));
     else
     {
         int primed = 0;
         if (status & VIRTIO_STATUS_ACKNOWLEDGE)
-            Log3(("ACKNOWLEDGE",   primed++));
+            Log6(("ACKNOWLEDGE",   primed++));
         if (status & VIRTIO_STATUS_DRIVER)
-            Log3(("%sDRIVER",      primed++ ? " | " : ""));
+            Log6(("%sDRIVER",      primed++ ? " | " : ""));
         if (status & VIRTIO_STATUS_FEATURES_OK)
-            Log3(("%sFEATURES_OK", primed++ ? " | " : ""));
+            Log6(("%sFEATURES_OK", primed++ ? " | " : ""));
         if (status & VIRTIO_STATUS_DRIVER_OK)
-            Log3(("%sDRIVER_OK",   primed++ ? " | " : ""));
+            Log6(("%sDRIVER_OK",   primed++ ? " | " : ""));
         if (status & VIRTIO_STATUS_FAILED)
-            Log3(("%sFAILED",      primed++ ? " | " : ""));
+            Log6(("%sFAILED",      primed++ ? " | " : ""));
         if (status & VIRTIO_STATUS_DEVICE_NEEDS_RESET)
-            Log3(("%sNEEDS_RESET", primed++ ? " | " : ""));
+            Log6(("%sNEEDS_RESET", primed++ ? " | " : ""));
     }
 }