Changeset 38749 in vbox for trunk/src/VBox

Timestamp:

Sep 14, 2011 12:19:14 PM (13 years ago)

Author:

vboxsync

Message:

PDM: Warn if devices/drivers take too long to suspend or power off. Also log the total time spent suspending and powering off.

File:

• trunk/src/VBox/VMM/VMMR3/PDM.cpp (modified) (17 diffs)

trunk/src/VBox/VMM/VMMR3/PDM.cpp

@@ -278 +278 @@
 #define PDM_SAVED_STATE_VERSION             4
 #define PDM_SAVED_STATE_VERSION_PRE_NMI_FF  3
+
+/** The number of nanoseconds a suspend callback needs to take before
+ * PDMR3Suspend warns about it taking too long. */
+#define PDMSUSPEND_WARN_AT_NS               UINT64_C(1200000000)
+
+/** The number of nanoseconds a suspend callback needs to take before
+ * PDMR3PowerOff warns about it taking too long. */
+#define PDMPOWEROFF_WARN_AT_NS              UINT64_C( 900000000)
 
 
@@ -1481 +1489 @@
         if (pDrvIns->pReg->pfnSuspend)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDrvIns->Internal.s.pfnAsyncNotify)
             {
@@ -1496 +1506 @@
                          pDrvIns->pReg->szName, pDrvIns->iInstance, iLun, pszDevName, iDevInstance));
             }
+
+            cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+            if (cNsElapsed >= PDMSUSPEND_WARN_AT_NS)
+                LogRel(("PDMR3Suspend: Driver '%s'/%d on LUN#%d of device '%s'/%d took %'llu ns to suspend\n",
+                        pDrvIns->pReg->szName, pDrvIns->iInstance, iLun, pszDevName, iDevInstance, cNsElapsed));
+
             if (pDrvIns->Internal.s.pfnAsyncNotify)
             {
@@ -1522 +1538 @@
         if (pUsbIns->pReg->pfnVMSuspend)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pUsbIns->Internal.s.pfnAsyncNotify)
             {
-                LogFlow(("PDMR3Suspend: Notifying - device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
+                LogFlow(("PDMR3Suspend: Notifying - USB device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
                 pUsbIns->pReg->pfnVMSuspend(pUsbIns);
                 if (pUsbIns->Internal.s.pfnAsyncNotify)
-                    LogFlow(("PDMR3Suspend: Async notification started - device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
+                    LogFlow(("PDMR3Suspend: Async notification started - USB device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
             }
             else if (pUsbIns->Internal.s.pfnAsyncNotify(pUsbIns))
             {
-                LogFlow(("PDMR3Suspend: Async notification completed - device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
+                LogFlow(("PDMR3Suspend: Async notification completed - USB device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
                 pUsbIns->Internal.s.pfnAsyncNotify = NULL;
             }
@@ -1539 +1557 @@
                 pdmR3NotifyAsyncAdd(pAsync, pUsbIns->Internal.s.pUsbDev->pReg->szName, pUsbIns->iInstance);
             }
+
+            cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+            if (cNsElapsed >= PDMSUSPEND_WARN_AT_NS)
+                LogRel(("PDMR3Suspend: USB device '%s'/%d took %'llu ns to suspend\n",
+                        pUsbIns->pReg->szName, pUsbIns->iInstance, cNsElapsed));
         }
     }
@@ -1558 +1581 @@
         if (pDevIns->pReg->pfnSuspend)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDevIns->Internal.s.pfnAsyncNotify)
             {
@@ -1575 +1600 @@
                 pdmR3NotifyAsyncAdd(pAsync, pDevIns->Internal.s.pDevR3->pReg->szName, pDevIns->iInstance);
             }
+
+            cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+            if (cNsElapsed >= PDMSUSPEND_WARN_AT_NS)
+                LogRel(("PDMR3Suspend: device '%s'/%d took %'llu ns to suspend\n",
+                        pDevIns->pReg->szName, pDevIns->iInstance, cNsElapsed));
         }
     }
@@ -1591 +1621 @@
     LogFlow(("PDMR3Suspend:\n"));
     VM_ASSERT_EMT0(pVM);
+    uint64_t cNsElapsed = RTTimeNanoTS();
 
     /*
@@ -1658 +1689 @@
     pdmR3ThreadSuspendAll(pVM);
 
-    LogFlow(("PDMR3Suspend: returns void\n"));
+    cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+    LogRel(("PDMR3Suspend: %'llu ns run time\n", cNsElapsed));
 }
 
@@ -1814 +1846 @@
         if (pDrvIns->pReg->pfnPowerOff)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDrvIns->Internal.s.pfnAsyncNotify)
             {
@@ -1829 +1863 @@
                          pDrvIns->pReg->szName, pDrvIns->iInstance, iLun, pszDevName, iDevInstance));
             }
+
+            cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+            if (cNsElapsed >= PDMPOWEROFF_WARN_AT_NS)
+                LogRel(("PDMR3PowerOff: Driver '%s'/%d on LUN#%d of device '%s'/%d took %'llu ns to power off\n",
+                        pDrvIns->pReg->szName, pDrvIns->iInstance, iLun, pszDevName, iDevInstance, cNsElapsed));
+
             if (pDrvIns->Internal.s.pfnAsyncNotify)
             {
@@ -1856 +1896 @@
         if (pUsbIns->pReg->pfnVMPowerOff)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pUsbIns->Internal.s.pfnAsyncNotify)
             {
-                LogFlow(("PDMR3PowerOff: Notifying - device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
+                LogFlow(("PDMR3PowerOff: Notifying - USB device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
                 pUsbIns->pReg->pfnVMPowerOff(pUsbIns);
                 if (pUsbIns->Internal.s.pfnAsyncNotify)
-                    LogFlow(("PDMR3PowerOff: Async notification started - device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
+                    LogFlow(("PDMR3PowerOff: Async notification started - USB device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
             }
             else if (pUsbIns->Internal.s.pfnAsyncNotify(pUsbIns))
             {
-                LogFlow(("PDMR3PowerOff: Async notification completed - device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
+                LogFlow(("PDMR3PowerOff: Async notification completed - USB device '%s'/%d\n", pUsbIns->pReg->szName, pUsbIns->iInstance));
                 pUsbIns->Internal.s.pfnAsyncNotify = NULL;
             }
@@ -1873 +1915 @@
                 pdmR3NotifyAsyncAdd(pAsync, pUsbIns->Internal.s.pUsbDev->pReg->szName, pUsbIns->iInstance);
             }
+
+            cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+            if (cNsElapsed >= PDMPOWEROFF_WARN_AT_NS)
+                LogRel(("PDMR3PowerOff: USB device '%s'/%d took %'llu ns to power off\n",
+                        pUsbIns->pReg->szName, pUsbIns->iInstance, cNsElapsed));
+
         }
     }
@@ -1892 +1940 @@
         if (pDevIns->pReg->pfnPowerOff)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDevIns->Internal.s.pfnAsyncNotify)
             {
@@ -1909 +1959 @@
                 pdmR3NotifyAsyncAdd(pAsync, pDevIns->Internal.s.pDevR3->pReg->szName, pDevIns->iInstance);
             }
+
+            cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+            if (cNsElapsed >= PDMPOWEROFF_WARN_AT_NS)
+                LogFlow(("PDMR3PowerOff: Device '%s'/%d took %'llu ns to power off\n",
+                         pDevIns->pReg->szName, pDevIns->iInstance, cNsElapsed));
         }
     }
@@ -1923 +1978 @@
 {
     LogFlow(("PDMR3PowerOff:\n"));
+    uint64_t cNsElapsed = RTTimeNanoTS();
 
     /*
@@ -1985 +2041 @@
     pdmR3ThreadSuspendAll(pVM);
 
-    LogFlow(("PDMR3PowerOff: returns void\n"));
+    cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+    LogRel(("PDMR3PowerOff: %'llu ns run time\n", cNsElapsed));
 }