Index: trunk/src/VBox/GuestHost/OpenGL/util/vboxhgsmi.c
===================================================================
--- trunk/src/VBox/GuestHost/OpenGL/util/vboxhgsmi.c	(revision 33280)
+++ trunk/src/VBox/GuestHost/OpenGL/util/vboxhgsmi.c	(revision 33306)
@@ -60,4 +60,102 @@
 #endif
 
+#define VBOX_WITH_CRHGSMIPROFILE
+#ifdef VBOX_WITH_CRHGSMIPROFILE
+#include <iprt/time.h>
+#include <stdio.h>
+
+typedef struct VBOXCRHGSMIPROFILE
+{
+    uint64_t cStartTime;
+    uint64_t cStepsTime;
+    uint64_t cSteps;
+} VBOXCRHGSMIPROFILE, *PVBOXCRHGSMIPROFILE;
+
+#define VBOXCRHGSMIPROFILE_GET_TIME_NANO() RTTimeNanoTS()
+#define VBOXCRHGSMIPROFILE_GET_TIME_MILLI() RTTimeMilliTS()
+
+/* 10 sec */
+#define VBOXCRHGSMIPROFILE_LOG_STEP_TIME (10000000000.)
+
+DECLINLINE(void) vboxCrHgsmiProfileStart(PVBOXCRHGSMIPROFILE pProfile)
+{
+    pProfile->cStepsTime = 0;
+    pProfile->cSteps = 0;
+    pProfile->cStartTime = VBOXCRHGSMIPROFILE_GET_TIME_NANO();
+}
+
+DECLINLINE(void) vboxCrHgsmiProfileStep(PVBOXCRHGSMIPROFILE pProfile, uint64_t cStepTime)
+{
+    pProfile->cStepsTime += cStepTime;
+    ++pProfile->cSteps;
+}
+
+typedef struct VBOXCRHGSMIPROFILE_SCOPE
+{
+    uint64_t cStartTime;
+//    bool bDisable;
+} VBOXCRHGSMIPROFILE_SCOPE, *PVBOXCRHGSMIPROFILE_SCOPE;
+
+static VBOXCRHGSMIPROFILE g_VBoxProfile;
+
+static void vboxCrHgsmiLog(char * szString, ...)
+{
+    char szBuffer[4096] = {0};
+     va_list pArgList;
+     va_start(pArgList, szString);
+     _vsnprintf(szBuffer, sizeof(szBuffer) / sizeof(szBuffer[0]), szString, pArgList);
+     va_end(pArgList);
+
+     VBoxCrHgsmiLog(szBuffer);
+}
+
+DECLINLINE(void) vboxCrHgsmiProfileLog(PVBOXCRHGSMIPROFILE pProfile, uint64_t cTime)
+{
+    uint64_t profileTime = cTime - pProfile->cStartTime;
+    double percent = ((double)100.0) * pProfile->cStepsTime / profileTime;
+    double cps = ((double)1000000000.) * pProfile->cSteps / profileTime;
+    vboxCrHgsmiLog("hgsmi: cps: %.1f, host %.1f%%\n", cps, percent);
+}
+
+DECLINLINE(void) vboxCrHgsmiProfileScopeEnter(PVBOXCRHGSMIPROFILE_SCOPE pScope)
+{
+//    pScope->bDisable = false;
+    pScope->cStartTime = VBOXCRHGSMIPROFILE_GET_TIME_NANO();
+}
+
+DECLINLINE(void) vboxCrHgsmiProfileScopeExit(PVBOXCRHGSMIPROFILE_SCOPE pScope)
+{
+//    if (!pScope->bDisable)
+    {
+        uint64_t cTime = VBOXCRHGSMIPROFILE_GET_TIME_NANO();
+        vboxCrHgsmiProfileStep(&g_VBoxProfile, cTime - pScope->cStartTime);
+        if (VBOXCRHGSMIPROFILE_LOG_STEP_TIME < cTime - g_VBoxProfile.cStartTime)
+        {
+            vboxCrHgsmiProfileLog(&g_VBoxProfile, cTime);
+            vboxCrHgsmiProfileStart(&g_VBoxProfile);
+        }
+    }
+}
+
+
+#define VBOXCRHGSMIPROFILE_INIT() vboxCrHgsmiProfileStart(&g_VBoxProfile)
+#define VBOXCRHGSMIPROFILE_TERM() do {} while (0)
+
+#define VBOXCRHGSMIPROFILE_FUNC_PROLOGUE() \
+        VBOXCRHGSMIPROFILE_SCOPE __vboxCrHgsmiProfileScope; \
+        vboxCrHgsmiProfileScopeEnter(&__vboxCrHgsmiProfileScope);
+
+#define VBOXCRHGSMIPROFILE_FUNC_EPILOGUE() \
+        vboxCrHgsmiProfileScopeExit(&__vboxCrHgsmiProfileScope); \
+
+
+#else
+#define VBOXCRHGSMIPROFILE_INIT() do {} while (0)
+#define VBOXCRHGSMIPROFILE_TERM() do {} while (0)
+#define VBOXCRHGSMIPROFILE_FUNC_PROLOGUE() do {} while (0)
+#define VBOXCRHGSMIPROFILE_FUNC_EPILOGUE() do {} while (0)
+#endif
+
+
 typedef struct {
     int                  initialized;
@@ -443,7 +541,15 @@
 static void *crVBoxHGSMIAlloc(CRConnection *conn)
 {
-    PCRVBOXHGSMI_CLIENT pClient = _crVBoxHGSMIClientGet();
-    void *pvBuf = _crVBoxHGSMIDoAlloc(pClient, conn->buffer_size);
+    PCRVBOXHGSMI_CLIENT pClient;
+    void *pvBuf;
+
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+
+    pClient = _crVBoxHGSMIClientGet();
+    pvBuf = _crVBoxHGSMIDoAlloc(pClient, conn->buffer_size);
     Assert(pvBuf);
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+
     return pvBuf;
 }
@@ -456,8 +562,8 @@
     pSubm->fFlags.Value = 0;
     pSubm->fFlags.bDoNotRetire = 1;
-    pSubm->fFlags.bDoNotSignalCompletion = 1; /* <- we do not need that actually since
-                                                       * in case we want completion,
-                                                       * we will block in _crVBoxHGSMICmdBufferGetRc (when locking the buffer)
-                                                       * which is needed for getting the result */
+//    pSubm->fFlags.bDoNotSignalCompletion = 1; /* <- we do not need that actually since
+//                                                       * in case we want completion,
+//                                                       * we will block in _crVBoxHGSMICmdBufferGetRc (when locking the buffer)
+//                                                       * which is needed for getting the result */
 }
 
@@ -467,4 +573,10 @@
 # error "Port Me!!"
 #endif
+
+DECLINLINE(void) _crVBoxHGSMIWaitCmd(PCRVBOXHGSMI_CLIENT pClient)
+{
+    int rc = CRVBOXHGSMI_BUF_WAIT(pClient->pCmdBuffer);
+    Assert(rc == 0);
+}
 
 static void _crVBoxHGSMIWriteExact(CRConnection *conn, PCRVBOXHGSMI_CLIENT pClient, PVBOXUHGSMI_BUFFER pBuf, uint32_t offStart, unsigned int len)
@@ -506,4 +618,5 @@
         if (RT_SUCCESS(rc))
         {
+            _crVBoxHGSMIWaitCmd(pClient);
                 /* @todo: do we need to wait for completion actually?
                  * NOTE: in case we do not need completion,
@@ -539,4 +652,5 @@
         if (RT_SUCCESS(rc))
         {
+            _crVBoxHGSMIWaitCmd(pClient);
                 /* @todo: do we need to wait for completion actually?
                  * NOTE: in case we do not need completion,
@@ -556,4 +670,5 @@
 static void crVBoxHGSMIWriteExact(CRConnection *conn, const void *buf, unsigned int len)
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     Assert(0);
 
@@ -566,4 +681,5 @@
 //    _crVBoxHGSMIWriteExact(conn, pClient, pBuf, 0, len);
 //    _crVBoxHGSMIBufFree(pClient, pBuf);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -609,4 +725,6 @@
         return;
     }
+
+    _crVBoxHGSMIWaitCmd(pClient);
 
     parms = (CRVBOXHGSMIREAD *)_crVBoxHGSMICmdBufferLockRo(pClient, sizeof (*parms));
@@ -733,4 +851,6 @@
             break;
         }
+
+        _crVBoxHGSMIWaitCmd(pClient);
 
         parms = (CRVBOXHGSMIWRITEREAD *)_crVBoxHGSMICmdBufferLockRo(pClient, sizeof (*parms));
@@ -799,4 +919,6 @@
     PVBOXUHGSMI_BUFFER pBuf;
 
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+
     if (!bufp) /* We're sending a user-allocated buffer. */
     {
@@ -811,4 +933,5 @@
         _crVBoxHGSMIWriteReadExact(conn, pClient, (void*)start, 0, len, false);
 #endif
+        VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
         return;
     }
@@ -822,5 +945,8 @@
     Assert(pBuf);
     if (!pBuf)
+    {
+        VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
         return;
+    }
 
     pClient = (PCRVBOXHGSMI_CLIENT)pBuf->pvUserData;
@@ -847,4 +973,6 @@
      */
     *bufp = NULL;
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -852,15 +980,21 @@
 {
     PCRVBOXHGSMI_CLIENT pClient;
-    PVBOXUHGSMI_BUFFER pBuf = _crVBoxHGSMIBufFromMemPtr(buf);
+    PVBOXUHGSMI_BUFFER pBuf;
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    pBuf = _crVBoxHGSMIBufFromMemPtr(buf);
     Assert(pBuf);
     Assert(0);
     CRASSERT(0);
     if (!pBuf)
+    {
+        VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
         return;
+    }
     pClient = (PCRVBOXHGSMI_CLIENT)pBuf->pvUserData;
     _crVBoxHGSMIReadExact(conn, pClient);
-}
-
-static void crVBoxHGSMIFree(CRConnection *conn, void *buf)
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+}
+
+static void _crVBoxHGSMIFree(CRConnection *conn, void *buf)
 {
     CRVBOXHGSMIBUFFER *hgsmi_buffer = (CRVBOXHGSMIBUFFER *) buf - 1;
@@ -888,4 +1022,10 @@
 #endif
     }
+}
+static void crVBoxHGSMIFree(CRConnection *conn, void *buf)
+{
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    _crVBoxHGSMIFree(conn, buf);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -967,5 +1107,5 @@
         && cached_type != CR_MESSAGE_GATHER)
     {
-        crVBoxHGSMIFree(conn, msg);
+        _crVBoxHGSMIFree(conn, msg);
     }
 }
@@ -973,5 +1113,8 @@
 static void crVBoxHGSMIReceiveMessage(CRConnection *conn)
 {
-    PCRVBOXHGSMI_CLIENT pClient = _crVBoxHGSMIClientGet();
+    PCRVBOXHGSMI_CLIENT pClient;
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+
+    pClient = _crVBoxHGSMIClientGet();
 
     Assert(pClient);
@@ -979,4 +1122,5 @@
 
     _crVBoxHGSMIReceiveMessage(conn, pClient);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 /*
@@ -985,4 +1129,5 @@
 static void crVBoxHGSMIAccept( CRConnection *conn, const char *hostname, unsigned short port )
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     Assert(0);
 
@@ -991,4 +1136,5 @@
     CRASSERT(FALSE);
 #endif
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -1038,4 +1184,5 @@
 #ifdef RT_OS_WINDOWS
     DWORD cbReturned;
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
 
     if (g_crvboxhgsmi.hGuestDrv == INVALID_HANDLE_VALUE)
@@ -1055,8 +1202,11 @@
             Assert(0);
             crDebug("could not open VBox Guest Additions driver! rc = %d\n", GetLastError());
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
             return FALSE;
         }
     }
 #else
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+
     if (g_crvboxhgsmi.iGuestDrv == INVALID_HANDLE_VALUE)
     {
@@ -1065,4 +1215,5 @@
         {
             crDebug("could not open Guest Additions kernel module! rc = %d\n", errno);
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
             return FALSE;
         }
@@ -1097,8 +1248,11 @@
         if (info.result == VINF_SUCCESS)
         {
+            int rc;
             conn->u32ClientID = info.u32ClientID;
             crDebug("HGCM connect was successful: client id =0x%x\n", conn->u32ClientID);
 
-            return crVBoxHGSMISetVersion(conn, CR_PROTOCOL_VERSION_MAJOR, CR_PROTOCOL_VERSION_MINOR);
+            rc = crVBoxHGSMISetVersion(conn, CR_PROTOCOL_VERSION_MAJOR, CR_PROTOCOL_VERSION_MINOR);
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+            return rc;
         }
         else
@@ -1116,4 +1270,6 @@
 #endif
     }
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 
     return FALSE;
@@ -1135,4 +1291,5 @@
     int i;
 #endif
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
 
     if (conn->pHostBuffer)
@@ -1214,4 +1371,5 @@
 # endif
     }
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 #endif /* IN_GUEST */
 }
@@ -1219,15 +1377,20 @@
 static void crVBoxHGSMIInstantReclaim(CRConnection *conn, CRMessage *mess)
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     Assert(0);
 
-    crVBoxHGSMIFree(conn, mess);
+    _crVBoxHGSMIFree(conn, mess);
     CRASSERT(FALSE);
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
 static void crVBoxHGSMIHandleNewMessage( CRConnection *conn, CRMessage *msg, unsigned int len )
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     Assert(0);
 
     CRASSERT(FALSE);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -1241,5 +1404,6 @@
         pClient->pHgsmi = pHgsmi;
         rc = pHgsmi->pfnBufferCreate(pHgsmi, CRVBOXHGSMI_PAGE_ALIGN(1),
-                                VBOXUHGSMI_SYNCHOBJECT_TYPE_SEMAPHORE, NULL,
+                                VBOXUHGSMI_SYNCHOBJECT_TYPE_EVENT,
+                                NULL,
                                 &pClient->pCmdBuffer);
         AssertRC(rc);
@@ -1247,5 +1411,6 @@
         {
             rc = pHgsmi->pfnBufferCreate(pHgsmi, CRVBOXHGSMI_PAGE_ALIGN(0x800000),
-                                            VBOXUHGSMI_SYNCHOBJECT_TYPE_SEMAPHORE, NULL,
+                                            VBOXUHGSMI_SYNCHOBJECT_TYPE_EVENT,
+                                            NULL,
                                             &pClient->pHGBuffer);
             AssertRC(rc);
