Changeset 8663 in vbox

Timestamp:

May 7, 2008 3:15:05 PM (17 years ago)

Author:

vboxsync

Message:

New logger prefix: lockcnts Output: read/write

Location:

trunk

Files:

• include/iprt/log.h (modified) (1 diff)
• src/VBox/Runtime/common/log/log.cpp (modified) (6 diffs)

trunk/include/iprt/log.h

@@ -292 +292 @@
 {
     /** The logger instance is disabled for normal output. */
-    RTLOGFLAGS_DISABLED         = 0x00000001,
+    RTLOGFLAGS_DISABLED             = 0x00000001,
     /** The logger instance is using buffered output. */
-    RTLOGFLAGS_BUFFERED         = 0x00000002,
+    RTLOGFLAGS_BUFFERED             = 0x00000002,
     /** The logger instance expands LF to CR/LF. */
-    RTLOGFLAGS_USECRLF          = 0x00000010,
+    RTLOGFLAGS_USECRLF              = 0x00000010,
     /** Show relative timestamps with PREFIX_TSC and PREFIX_TS */
-    RTLOGFLAGS_REL_TS           = 0x00000020,
+    RTLOGFLAGS_REL_TS               = 0x00000020,
     /** Show decimal timestamps with PREFIX_TSC and PREFIX_TS */
-    RTLOGFLAGS_DECIMAL_TS       = 0x00000040,
-    /** New lines should be reprefixed with the CPU id (ApicID on intel/amd). */
-    RTLOGFLAGS_PREFIX_CPUID     = 0x00010000,
+    RTLOGFLAGS_DECIMAL_TS           = 0x00000040,
+    /** New lines should be prefixed with the write and read lock counts. */
+    RTLOGFLAGS_PREFIX_LOCK_COUNTS   = 0x00008000,
+    /** New lines should be prefixed with the CPU id (ApicID on intel/amd). */
+    RTLOGFLAGS_PREFIX_CPUID         = 0x00010000,
     /** New lines should be prefixed with the native process id. */
-    RTLOGFLAGS_PREFIX_PID       = 0x00020000,
+    RTLOGFLAGS_PREFIX_PID           = 0x00020000,
     /** New lines should be prefixed with group flag number causing the output. */
-    RTLOGFLAGS_PREFIX_FLAG_NO   = 0x00040000,
+    RTLOGFLAGS_PREFIX_FLAG_NO       = 0x00040000,
     /** New lines should be prefixed with group flag name causing the output. */
-    RTLOGFLAGS_PREFIX_FLAG      = 0x00080000,
+    RTLOGFLAGS_PREFIX_FLAG          = 0x00080000,
     /** New lines should be prefixed with group number. */
-    RTLOGFLAGS_PREFIX_GROUP_NO  = 0x00100000,
+    RTLOGFLAGS_PREFIX_GROUP_NO      = 0x00100000,
     /** New lines should be prefixed with group name. */
-    RTLOGFLAGS_PREFIX_GROUP     = 0x00200000,
+    RTLOGFLAGS_PREFIX_GROUP         = 0x00200000,
     /** New lines should be prefixed with the native thread id. */
-    RTLOGFLAGS_PREFIX_TID       = 0x00400000,
+    RTLOGFLAGS_PREFIX_TID           = 0x00400000,
     /** New lines should be prefixed with thread name. */
-    RTLOGFLAGS_PREFIX_THREAD    = 0x00800000,
+    RTLOGFLAGS_PREFIX_THREAD        = 0x00800000,
     /** New lines should be prefixed with formatted timestamp since program start. */
-    RTLOGFLAGS_PREFIX_TIME_PROG = 0x04000000,
+    RTLOGFLAGS_PREFIX_TIME_PROG     = 0x04000000,
     /** New lines should be prefixed with formatted timestamp (UCT). */
-    RTLOGFLAGS_PREFIX_TIME      = 0x08000000,
+    RTLOGFLAGS_PREFIX_TIME          = 0x08000000,
     /** New lines should be prefixed with milliseconds since program start. */
-    RTLOGFLAGS_PREFIX_MS_PROG   = 0x10000000,
+    RTLOGFLAGS_PREFIX_MS_PROG       = 0x10000000,
     /** New lines should be prefixed with timestamp. */
-    RTLOGFLAGS_PREFIX_TSC       = 0x20000000,
+    RTLOGFLAGS_PREFIX_TSC           = 0x20000000,
     /** New lines should be prefixed with timestamp. */
-    RTLOGFLAGS_PREFIX_TS        = 0x40000000,
+    RTLOGFLAGS_PREFIX_TS            = 0x40000000,
     /** The prefix mask. */
-    RTLOGFLAGS_PREFIX_MASK      = 0x7cff0000
+    RTLOGFLAGS_PREFIX_MASK          = 0x7cff8000
 } RTLOGFLAGS;
 

trunk/src/VBox/Runtime/common/log/log.cpp

@@ -103 +103 @@
 static PRTLOGGER                    g_pRelLogger;
 #endif /* !IN_GC */
+#ifdef IN_RING3
+/** The RTThreadGetWriteLockCount() change caused by the logger mutex semaphore. */
+static uint32_t volatile            g_cLoggerLockCount;
+#endif
 #ifdef IN_RING0
 /** Number of per-thread loggers. */
@@ -413 +417 @@
 
             /*
-             * Create mutex.
+             * Create mutex and check how much it counts when entering the lock
+             * so that we can report the values for RTLOGFLAGS_PREFIX_LOCK_COUNTS.
              */
             if (RT_SUCCESS(rc))
@@ -420 +425 @@
                 if (RT_SUCCESS(rc))
                 {
+#ifdef IN_RING3 /** @todo do counters in ring-0 too? */
+                    RTTHREAD Thread = RTThreadSelf();
+                    if (Thread != NIL_RTTHREAD)
+                    {
+                        int32_t c = RTThreadGetWriteLockCount(Thread);
+                        RTSemFastMutexRequest(pLogger->MutexSem);
+                        c = RTThreadGetWriteLockCount(Thread) - c;
+                        RTSemFastMutexRelease(pLogger->MutexSem);
+                        ASMAtomicWriteU32(&g_cLoggerLockCount, c);
+                    }
+#endif
                     *ppLogger = pLogger;
                     return VINF_SUCCESS;
                 }
-                else if (pszErrorMsg)
+
+                if (pszErrorMsg)
                     RTStrPrintf(pszErrorMsg, cchErrorMsg, "failed to create sempahore");
             }
@@ -1214 +1231 @@
             { "dec",          sizeof("dec"         ) - 1,   RTLOGFLAGS_DECIMAL_TS,          false },
             { "hex",          sizeof("hex"         ) - 1,   RTLOGFLAGS_DECIMAL_TS,          true  },
+            { "lockcnts",     sizeof("lockcnts"    ) - 1,   RTLOGFLAGS_PREFIX_LOCK_COUNTS,  false },
             { "cpuid",        sizeof("cpuid"       ) - 1,   RTLOGFLAGS_PREFIX_CPUID,        false },
             { "pid",          sizeof("pid"         ) - 1,   RTLOGFLAGS_PREFIX_PID,          false },
@@ -1917 +1935 @@
                 /*
                  * Flush the buffer if there isn't enough room for the maximum prefix config.
-                 * Max is 214, add a couple of extra bytes.
+                 * Max is 224, add a couple of extra bytes.
                  */
-                if (cb < 214 + 16)
+                if (cb < 224 + 16)
                 {
                     rtlogFlush(pLogger);
@@ -2093 +2111 @@
                     psz += RTStrFormatNumber(psz, idCpu, 16, sizeof(idCpu) * 2, 0, RTSTR_F_ZEROPAD);
                     *psz++ = ' ';                                                               /* +17 */
+                }
+                if (pLogger->fFlags & RTLOGFLAGS_PREFIX_LOCK_COUNTS)
+                {
+#ifdef IN_RING3 /** @todo implement these counters in ring-0 too? */
+                    RTTHREAD Thread = RTThreadSelf();
+                    if (Thread != NIL_RTTHREAD)
+                    {
+                        uint32_t cReadLocks  = RTThreadGetReadLockCount(Thread);
+                        uint32_t cWriteLocks = RTThreadGetWriteLockCount(Thread) - g_cLoggerLockCount;
+                        cReadLocks  = RT_MIN(0xfff, cReadLocks);
+                        cWriteLocks = RT_MIN(0xfff, cWriteLocks);
+                        psz += RTStrFormatNumber(psz, cReadLocks,  16, 3, 0, RTSTR_F_ZEROPAD);
+                        *psz++ = '/';
+                        psz += RTStrFormatNumber(psz, cWriteLocks, 16, 3, 0, RTSTR_F_ZEROPAD);
+                    }
+                    else
+#endif
+                    {
+                        *psz++ = '0';
+                        *psz++ = '0';
+                        *psz++ = '0';
+                        *psz++ = '/';
+                        *psz++ = '0';
+                        *psz++ = '0';
+                        *psz++ = '0';
+                    }
+                    *psz++ = ' ';                                                               /* +8 */
                 }
                 if (pLogger->fFlags & RTLOGFLAGS_PREFIX_FLAG_NO)