Changeset 80596 in vbox for trunk/src/VBox/Devices/VirtIO

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/src/VBox/Devices/VirtIO

Files:

• Virtio_1_0.cpp (modified) (19 diffs)
• Virtio_1_0.h (modified) (2 diffs)
• Virtio_1_0_impl.h (modified) (2 diffs)

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++ ? " | " : ""));
     }
 }