Index: trunk/src/VBox/VMM/VMMR3/PDM.cpp
===================================================================
--- trunk/src/VBox/VMM/VMMR3/PDM.cpp	(revision 38736)
+++ trunk/src/VBox/VMM/VMMR3/PDM.cpp	(revision 38749)
@@ -278,4 +278,12 @@
 #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,4 +1489,6 @@
         if (pDrvIns->pReg->pfnSuspend)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDrvIns->Internal.s.pfnAsyncNotify)
             {
@@ -1496,4 +1506,10 @@
                          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,14 +1538,16 @@
         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,4 +1557,9 @@
                 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,4 +1581,6 @@
         if (pDevIns->pReg->pfnSuspend)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDevIns->Internal.s.pfnAsyncNotify)
             {
@@ -1575,4 +1600,9 @@
                 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,4 +1621,5 @@
     LogFlow(("PDMR3Suspend:\n"));
     VM_ASSERT_EMT0(pVM);
+    uint64_t cNsElapsed = RTTimeNanoTS();
 
     /*
@@ -1658,5 +1689,6 @@
     pdmR3ThreadSuspendAll(pVM);
 
-    LogFlow(("PDMR3Suspend: returns void\n"));
+    cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+    LogRel(("PDMR3Suspend: %'llu ns run time\n", cNsElapsed));
 }
 
@@ -1814,4 +1846,6 @@
         if (pDrvIns->pReg->pfnPowerOff)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDrvIns->Internal.s.pfnAsyncNotify)
             {
@@ -1829,4 +1863,10 @@
                          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,14 +1896,16 @@
         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,4 +1915,10 @@
                 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,4 +1940,6 @@
         if (pDevIns->pReg->pfnPowerOff)
         {
+            uint64_t cNsElapsed = RTTimeNanoTS();
+
             if (!pDevIns->Internal.s.pfnAsyncNotify)
             {
@@ -1909,4 +1959,9 @@
                 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,4 +1978,5 @@
 {
     LogFlow(("PDMR3PowerOff:\n"));
+    uint64_t cNsElapsed = RTTimeNanoTS();
 
     /*
@@ -1985,5 +2041,6 @@
     pdmR3ThreadSuspendAll(pVM);
 
-    LogFlow(("PDMR3PowerOff: returns void\n"));
+    cNsElapsed = RTTimeNanoTS() - cNsElapsed;
+    LogRel(("PDMR3PowerOff: %'llu ns run time\n", cNsElapsed));
 }
 
