Index: trunk/src/VBox/GuestHost/OpenGL/util/vboxhgcm.c
===================================================================
--- trunk/src/VBox/GuestHost/OpenGL/util/vboxhgcm.c	(revision 33306)
+++ trunk/src/VBox/GuestHost/OpenGL/util/vboxhgcm.c	(revision 33365)
@@ -46,4 +46,114 @@
 #include <VBox/HostServices/VBoxCrOpenGLSvc.h>
 
+//#if defined(IN_GUEST)
+//#define VBOX_WITH_CRHGSMIPROFILE
+//#endif
+#ifdef VBOX_WITH_CRHGSMIPROFILE
+#include <iprt/time.h>
+#include <stdio.h>
+
+#ifdef VBOX_WITH_CRHGSMI
+#include <VBox/VBoxCrHgsmi.h>
+#endif
+
+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);
+
+#ifdef VBOX_WITH_CRHGSMI
+     VBoxCrHgsmiLog(szBuffer);
+#else
+     OutputDebugString(szBuffer);
+#endif
+}
+
+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("hgcm: 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
+#ifdef IN_GUEST
+#error "should not happen!"
+#endif
+#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;
@@ -95,5 +205,5 @@
 
 /* Some forward declarations */
-static void crVBoxHGCMReceiveMessage(CRConnection *conn);
+static void _crVBoxHGCMReceiveMessage(CRConnection *conn);
 
 #ifndef IN_GUEST
@@ -233,5 +343,5 @@
 }
 
-static void *crVBoxHGCMAlloc(CRConnection *conn)
+static void *_crVBoxHGCMAlloc(CRConnection *conn)
 {
     CRVBOXHGCMBUFFER *buf;
@@ -358,5 +468,14 @@
 }
 
-static void crVBoxHGCMWriteExact(CRConnection *conn, const void *buf, unsigned int len)
+static void *crVBoxHGCMAlloc(CRConnection *conn)
+{
+    void *pvBuff;
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    pvBuff = _crVBoxHGCMAlloc(conn);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+    return pvBuff;
+}
+
+static void _crVBoxHGCMWriteExact(CRConnection *conn, const void *buf, unsigned int len)
 {
     int rc;
@@ -407,4 +526,11 @@
 }
 
+static void crVBoxHGCMWriteExact(CRConnection *conn, const void *buf, unsigned int len)
+{
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    _crVBoxHGCMWriteExact(conn, buf, len);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+}
+
 static void crVBoxHGCMReadExact( CRConnection *conn, const void *buf, unsigned int len )
 {
@@ -441,5 +567,5 @@
 
     if (conn->cbBuffer)
-        crVBoxHGCMReceiveMessage(conn);
+        _crVBoxHGCMReceiveMessage(conn);
 
 }
@@ -517,5 +643,5 @@
 
     if (conn->cbBuffer)
-        crVBoxHGCMReceiveMessage(conn);
+        _crVBoxHGCMReceiveMessage(conn);
 }
 
@@ -524,4 +650,5 @@
 {
     CRVBOXHGCMBUFFER *hgcm_buffer;
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
 
     if (!bufp) /* We're sending a user-allocated buffer. */
@@ -536,4 +663,5 @@
             crVBoxHGCMWriteReadExact(conn, start, len, CR_VBOXHGCM_USERALLOCATED);
 #endif
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
         return;
     }
@@ -553,5 +681,5 @@
     if (conn->u32InjectClientID)
     {
-        crVBoxHGCMWriteExact(conn, start, len);
+        _crVBoxHGCMWriteExact(conn, start, len);
     }
     else
@@ -573,4 +701,6 @@
      */
     *bufp = NULL;
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -611,8 +741,10 @@
 static void crVBoxHGCMSingleRecv(CRConnection *conn, void *buf, unsigned int len)
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     crVBoxHGCMReadExact(conn, buf, len);
-}
-
-static void crVBoxHGCMFree(CRConnection *conn, void *buf)
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+}
+
+static void _crVBoxHGCMFree(CRConnection *conn, void *buf)
 {
     CRVBOXHGCMBUFFER *hgcm_buffer = (CRVBOXHGCMBUFFER *) buf - 1;
@@ -653,5 +785,12 @@
 }
 
-static void crVBoxHGCMReceiveMessage(CRConnection *conn)
+static void crVBoxHGCMFree(CRConnection *conn, void *buf)
+{
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    _crVBoxHGCMFree(conn, buf);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+}
+
+static void _crVBoxHGCMReceiveMessage(CRConnection *conn)
 {
     uint32_t len;
@@ -670,5 +809,5 @@
         CRASSERT(conn->buffer_size >= sizeof(CRMessageRedirPtr));
 
-        hgcm_buffer = (CRVBOXHGCMBUFFER *) crVBoxHGCMAlloc( conn ) - 1;
+        hgcm_buffer = (CRVBOXHGCMBUFFER *) _crVBoxHGCMAlloc( conn ) - 1;
         hgcm_buffer->len = sizeof(CRMessageRedirPtr);
 
@@ -690,5 +829,5 @@
         {
             /* put in pre-allocated buffer */
-            hgcm_buffer = (CRVBOXHGCMBUFFER *) crVBoxHGCMAlloc( conn ) - 1;
+            hgcm_buffer = (CRVBOXHGCMBUFFER *) _crVBoxHGCMAlloc( conn ) - 1;
         }
         else
@@ -728,7 +867,15 @@
         && cached_type != CR_MESSAGE_GATHER)
     {
-        crVBoxHGCMFree(conn, msg);
-    }
-}
+        _crVBoxHGCMFree(conn, msg);
+    }
+}
+
+static void crVBoxHGCMReceiveMessage(CRConnection *conn)
+{
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    _crVBoxHGCMReceiveMessage(conn);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
+}
+
 
 /*
@@ -737,8 +884,10 @@
 static void crVBoxHGCMAccept( CRConnection *conn, const char *hostname, unsigned short port )
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     CRASSERT(conn && conn->pHostBuffer);
 #ifdef IN_GUEST
     CRASSERT(FALSE);
 #endif
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -786,4 +935,6 @@
 #ifdef RT_OS_WINDOWS
     DWORD cbReturned;
+
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
 
     if (g_crvboxhgcm.hGuestDrv == INVALID_HANDLE_VALUE)
@@ -802,8 +953,10 @@
         {
             crDebug("could not open VBox Guest Additions driver! rc = %d\n", GetLastError());
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
             return FALSE;
         }
     }
 #else
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     if (g_crvboxhgcm.iGuestDrv == INVALID_HANDLE_VALUE)
     {
@@ -812,4 +965,5 @@
         {
             crDebug("could not open Guest Additions kernel module! rc = %d\n", errno);
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
             return FALSE;
         }
@@ -847,4 +1001,5 @@
             crDebug("HGCM connect was successful: client id =0x%x\n", conn->u32ClientID);
 
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
             return crVBoxHGCMSetVersion(conn, CR_PROTOCOL_VERSION_MAJOR, CR_PROTOCOL_VERSION_MINOR);
         }
@@ -852,4 +1007,6 @@
         {
             crDebug("HGCM connect failed with rc=0x%x\n", info.result);
+
+            VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
             return FALSE;
         }
@@ -862,7 +1019,9 @@
         crDebug("IOCTL for HGCM connect failed with rc=0x%x\n", errno);
 #endif
+        VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
         return FALSE;
     }
 
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
     return TRUE;
 
@@ -884,4 +1043,6 @@
     int i;
 #endif
+
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
 
     if (conn->pHostBuffer)
@@ -964,15 +1125,21 @@
     }
 #endif /* IN_GUEST */
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
 static void crVBoxHGCMInstantReclaim(CRConnection *conn, CRMessage *mess)
 {
-    crVBoxHGCMFree(conn, mess);
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+    _crVBoxHGCMFree(conn, mess);
     CRASSERT(FALSE);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
 static void crVBoxHGCMHandleNewMessage( CRConnection *conn, CRMessage *msg, unsigned int len )
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     CRASSERT(FALSE);
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 }
 
@@ -987,4 +1154,6 @@
         return;
     }
+
+    VBOXCRHGSMIPROFILE_INIT();
 
     g_crvboxhgcm.initialized = 1;
@@ -1142,4 +1311,6 @@
     int32_t i;
 
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
+
 #ifdef IN_GUEST
     /* we're on guest side, poll host if it got something for us */
@@ -1167,7 +1338,9 @@
         if (conn->cbBuffer>0)
         {
-            crVBoxHGCMReceiveMessage(conn);
-        }
-    }
+            _crVBoxHGCMReceiveMessage(conn);
+        }
+    }
+
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
 
     return 0;
Index: trunk/src/VBox/GuestHost/OpenGL/util/vboxhgsmi.c
===================================================================
--- trunk/src/VBox/GuestHost/OpenGL/util/vboxhgsmi.c	(revision 33306)
+++ trunk/src/VBox/GuestHost/OpenGL/util/vboxhgsmi.c	(revision 33365)
@@ -1457,5 +1457,12 @@
 
     if (!bHasHGSMI)
+    {
+#ifdef DEBUG_misha
+        AssertRelease(0);
+#endif
         return false;
+    }
+
+    return false;
 
     g_crvboxhgsmi.recv_list = rfl;
@@ -1588,4 +1595,5 @@
 {
     int32_t i;
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
 
 #ifdef IN_GUEST
@@ -1620,4 +1628,5 @@
     }
 
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
     return 0;
 }
@@ -1625,7 +1634,9 @@
 CRConnection** crVBoxHGSMIDump( int *num )
 {
+    VBOXCRHGSMIPROFILE_FUNC_PROLOGUE();
     Assert(0);
     *num = g_crvboxhgsmi.num_conns;
 
+    VBOXCRHGSMIPROFILE_FUNC_EPILOGUE();
     return g_crvboxhgsmi.conns;
 }
