Changeset 89150 in vbox for trunk/src/VBox/ValidationKit/bootsectors

Timestamp:

May 19, 2021 12:54:21 AM (4 years ago)

Author:

vboxsync

Message:

ValKit/bootsectors: Did some more work on the TSC timining test. Added standalone executable version of it. bugref:10009

Location:

trunk/src/VBox/ValidationKit/bootsectors

Files:

• Makefile.kmk (modified) (1 diff)
• bs3-timing-1-32.c32 (modified) (3 diffs)
• bs3-timing-1-exe.c (added)

trunk/src/VBox/ValidationKit/bootsectors/Makefile.kmk

@@ -397 +397 @@
         bs3-timing-1-32.c32
 
+PROGRAMS += bs3-timing-1-exe
+bs3-timing-1-exe_TEMPLATE = VBoxR3Static
+bs3-timing-1-exe_SOURCES  = bs3-timing-1-exe.c
 endif # VBOX_WITH_BS3KIT
 

trunk/src/VBox/ValidationKit/bootsectors/bs3-timing-1-32.c32

@@ -29 +29 @@
 *   Header Files                                                                                                                 *
 *********************************************************************************************************************************/
-#include <bs3kit.h>
+#ifndef STANDALONE_EXECUTABLE
+# include <bs3kit.h>
+#endif
 #include <iprt/asm-amd64-x86.h>
 #include <iprt/asm-math.h>
-
-
-static void bs3Timing1_Tsc_One(void)
-{
-    uint64_t const nsStart     = Bs3TestNow();
-    uint64_t const uTscStart   = ASMReadTSC();
-    uint64_t const nsDeadline  = nsStart + RT_NS_10SEC;
-    uint64_t       cNsElapsed;
-    uint64_t       cTicksElapsed;
-    uint64_t       cTicksMin   = UINT64_MAX;
-    uint64_t       cTicksMax   = 0;
-    uint64_t       cTicksSum   = 0;
-    uint64_t       cBelow512   = 0;
-    uint64_t       cBelow1K    = 0;
-    uint64_t       cBelow4K    = 0;
-    uint64_t       cAbove512K  = 0;
-    uint64_t       cAbove1M    = 0;
-    uint64_t       cAbove10M   = 0;
-    uint64_t       cTotalLoops = 0;
+#include <iprt/asm.h>
+#include <iprt/uint128.h>
+
+
+/*********************************************************************************************************************************
+*   Structures and Typedefs                                                                                                      *
+*********************************************************************************************************************************/
+/** TSC timing results. */
+typedef struct BS3TIMING1RESULT
+{
+    /** Number of nanoseconds elapsed while testing. */
+    uint64_t    cNsElapsed;
+    /** Number of CPU ticks elapsed while testing. */
+    uint64_t    cTicksElapsed;
+    /** The minium number of ticks between TSC reads. */
+    uint64_t    cTicksMin;
+    /** The maximum number of ticks between TSC reads. */
+    uint64_t    cTicksMax;
+    /** The sum of all TSC read deltas. */
+    uint64_t    cTicksSum;
+    /** Number of loops (TSC read deltas). */
+    uint64_t    cTotalLoops;
+    /** Number of times TSC moved backwards. */
+    uint64_t    cBackwards;
+    /** Approx log2(cTicks) distribution. */
+    uint64_t    aDistribution[65];
+} BS3TIMING1RESULT;
+
+
+/*********************************************************************************************************************************
+*   Global Variables                                                                                                             *
+*********************************************************************************************************************************/
+/** The total result. */
+static BS3TIMING1RESULT g_TotalResult;
+
+/** Set if history wrapped (i.e. table is full). */
+static bool     g_fBigHistoryWrapped = false;
+/** The next history entry. */
+static uint32_t g_iBigHistory;
+/** History of large gaps. */
+static struct { uint64_t uTsc, cTicksDelta; } g_aBigHistory[384];
+
+
+
+/**
+ * Pretty prints
+ */
+static void bs3Timing1_PrintTicks(uint64_t cTicks, uint64_t uCpuFreq)
+{
+    if (uCpuFreq > _128M)
+    {
+        if (cTicks >= uCpuFreq * 1000)
+            Bs3TestPrintf("%'RU64s", cTicks / uCpuFreq);
+        else
+        {
+            const char *pszUnit;
+            uint64_t    uValue;
+            if (cTicks >= uCpuFreq)
+            {
+                pszUnit = "s";
+                uValue  = (cTicks * RT_MS_1SEC) / uCpuFreq;
+            }
+            else if (cTicks * RT_MS_1SEC >= uCpuFreq)
+            {
+                pszUnit = "ms";
+                uValue  = (cTicks * RT_US_1SEC) / uCpuFreq;
+            }
+            else if (cTicks * RT_US_1SEC >= uCpuFreq)
+            {
+                pszUnit = "us";
+                uValue  = (cTicks * RT_NS_1SEC) / uCpuFreq;
+            }
+            else if (cTicks * RT_NS_1SEC >= uCpuFreq)
+            {
+                pszUnit = "ns";
+                uValue  = (cTicks * UINT64_C(1000000000000)) / uCpuFreq;
+            }
+            else
+            {
+                Bs3TestPrintf("%'RU64ps", (cTicks * UINT64_C(1000000000000)) / uCpuFreq);
+                return;
+            }
+            Bs3TestPrintf("%u.%03u%s (%'RU64 ticks)", (uint32_t)uValue / 1000, (uint32_t)uValue % 1000, pszUnit, cTicks);
+        }
+    }
+    else
+        Bs3TestPrintf("%'RU64 ticks", cTicks);
+}
+
+
+/**
+ * Prints a result.
+ *
+ * @param   pResult     The result to print.
+ * @param   iRun        The run (loop in qpc parlance).
+ * @param   uVerbosity  The verbosity level.
+ */
+static void bs3Timing1_PrintResult(BS3TIMING1RESULT const *pResult, unsigned iRun, unsigned uVerbosity)
+{
+    uint64_t uCpuFreq;
+
+    /*
+     * Calc CPU frequency.
+     */
+    if (pResult->cNsElapsed > 0 && pResult->cTicksElapsed > 0)
+    {
+#if 1
+        RTUINT128U Tmp1, Divisor, Result;
+        RTUInt128Div(&Result,
+                     RTUInt128MulU64ByU64(&Tmp1, pResult->cTicksElapsed, RT_NS_1SEC),
+                     RTUInt128AssignU64(&Divisor, pResult->cNsElapsed));
+        uCpuFreq = Result.s.Lo;
+#else
+        unsigned const cShift = pResult->cTicksElapsed < UINT64_C(0x000225C17D04) ? 0
+                              : pResult->cTicksElapsed < UINT64_C(0x00225C17D04D) ? 4
+                              : pResult->cTicksElapsed < UINT64_C(0x0225C17D04DA) ? 8
+                              : pResult->cTicksElapsed < UINT64_C(0x225C1D940BF6) ? 12
+                              :                                            16;
+        uCpuFreq = pResult->cTicksElapsed * ((uint64_t)RT_NS_1SEC >> cShift) / (pResult->cNsElapsed >> cShift);
+#endif
+    }
+    else
+        uCpuFreq = 1;
+
+    /*
+     * Report results.
+     *
+     * Note! in 32-bit and 16-bit mode, values 4G or higher gets formatted as
+     *       hexadecimal to avoid 64-bit division.
+     */
+    Bs3TestPrintf("Loop #%u: %'RU64 tests: ", iRun, pResult->cTotalLoops);
+
+    Bs3TestPrintf("average ");
+    bs3Timing1_PrintTicks(pResult->cTicksSum / pResult->cTotalLoops, uCpuFreq);
+    Bs3TestPrintf(", min ");
+    bs3Timing1_PrintTicks(pResult->cTicksMin, uCpuFreq);
+    Bs3TestPrintf(", max ");
+    bs3Timing1_PrintTicks(pResult->cTicksMax, uCpuFreq);
+    Bs3TestPrintf("\n");
+
+    /* Distribution (tick delta log2-ish). */
+    if (uVerbosity > 0)
+    {
+        unsigned iItem = 0;
+        unsigned i;
+        for (i = uVerbosity > 1 ? 0 : 5; i < RT_ELEMENTS(pResult->aDistribution); i++)
+            if (pResult->aDistribution[i] != 0)
+            {
+                if (iItem >= 6)
+                {
+                    iItem = 0;
+                    Bs3TestPrintf("\n");
+                }
+                iItem++;
+                Bs3TestPrintf("  %'11RU64|2^%-2u", pResult->aDistribution[i], i);
+            }
+        if (uVerbosity > 1)
+            Bs3TestPrintf(iItem < 6 ? " (%'RU64 Hz)\n" : "\n  (%'RU64 Hz)\n", uCpuFreq);
+        else
+            Bs3TestPrintf("\n");
+    }
+    if (pResult->cBackwards != 0)
+        Bs3TestFailedF("TSC went backwards %'RU64 time(s)", pResult->cBackwards);
+}
+
+
+/**
+ * Do one TSC timing iteration.
+ *
+ * @param   iRun        The iteration number (loop).
+ * @param   cSecs       The number of seconds to sample TSCs.
+ * @param   uVerbosity  The noise level.
+ * @param   iMinHistory The threshold level to put stuff in g_auTscHistory.
+ */
+static void bs3Timing1_Tsc_One(unsigned iRun, uint32_t cSecs, unsigned uVerbosity, unsigned iMinHistory)
+{
+    uint64_t const      nsStart     = Bs3TestNow();
+    uint64_t const      uTscStart   = ASMReadTSC();
+    uint64_t const      nsDeadline  = nsStart + cSecs * RT_NS_1SEC_64;
+    uint64_t            cNsElapsed;
+    BS3TIMING1RESULT    Result;
+    unsigned            i;
+
+    Bs3MemZero(&Result, sizeof(Result));
+    Result.cTicksMin = UINT64_MAX;
 
     /*
@@ -58 +226 @@
     {
         unsigned cLoops = 100000 + 1;
-        cTotalLoops += cLoops - 1;
+        Result.cTotalLoops += cLoops - 1;
         while (--cLoops != 0)
         {
@@ -64 +232 @@
             uint64_t uTscNow   = ASMReadTSC();
             uint64_t cTicks    = uTscNow - uTscPrev;
+            unsigned iBit;
+
+            /* check that it doesn't go backwards*/
+            if ((int64_t)cTicks < 0)
+                Result.cBackwards++;
 
             /* min/max/avg */
-            cTicksSum += cTicks;
-            if (cTicks < cTicksMin)
-                cTicksMin = cTicks;
-            if (cTicks > cTicksMax)
-                cTicksMax = cTicks;
-
-            /* range. */
-            if (cTicks < _4K)
-            {
-                cBelow4K++;
-                if (cTicks < _1K)
+            Result.cTicksSum += cTicks;
+            if (cTicks < Result.cTicksMin)
+                Result.cTicksMin = cTicks;
+            if (cTicks > Result.cTicksMax)
+                Result.cTicksMax = cTicks;
+
+            /* result distribution by most significant bit. */
+            iBit = ASMBitLastSetU64(cTicks);
+            Result.aDistribution[iBit] += 1;
+            if (iBit < iMinHistory)
+            { /* likely */ }
+            else
+            {
+                g_aBigHistory[g_iBigHistory].uTsc        = uTscPrev;
+                g_aBigHistory[g_iBigHistory].cTicksDelta = cTicks;
+                if (++g_iBigHistory >= RT_ELEMENTS(g_aBigHistory))
                 {
-                    cBelow1K++;
-                    if (cTicks < 512)
-                        cBelow512++;
-                }
-            }
-            else if (cTicks >= _512K)
-            {
-                cAbove512K++;
-                if (cTicks >= _1M)
-                {
-                    cAbove1M++;
-                    if (cTicks >= 10*_1M)
-                        cAbove10M++;
+                    g_iBigHistory        = 0;
+                    g_fBigHistoryWrapped = true;
                 }
             }
         }
     } while ((cNsElapsed = Bs3TestNow()) < nsDeadline);
-    cTicksElapsed  = ASMReadTSC();
-    cTicksElapsed -= uTscStart;
-    cNsElapsed    -= nsStart;
-
-    /*
-     * Report results.
-     *
-     * Note! in 32-bit and 16-bit mode, values 4G or higher gets formatted as
-     *       hexadecimal to avoid 64-bit division.
-     */
-
-    Bs3TestPrintf("%'14RU64 loops in %'RU64 ns / %'RU64 ticks\n", cTotalLoops, cNsElapsed, cTicksElapsed);
-
-    /* Report results in ticks. */
-    Bs3TestPrintf("average %RU64 ticks, min %'RU64, max %'RU64\n",
-                  cTicksSum / cTotalLoops, cTicksMin, cTicksMax);
-    Bs3TestPrintf("%'14RU64 below 512\n", cBelow512);
-    Bs3TestPrintf("%'14RU64 below 1K\n", cBelow1K);
-    Bs3TestPrintf("%'14RU64 below 4K\n", cBelow4K);
-    Bs3TestPrintf("%'14RU64 inbetween\n", cTotalLoops - cBelow4K - cAbove512K);
-    Bs3TestPrintf("%'14RU64 above 512K\n", cAbove512K);
-    Bs3TestPrintf("%'14RU64 above 1M\n", cAbove1M);
-    Bs3TestPrintf("%'14RU64 above 10M\n", cAbove10M);
-
-    /* results in nanoseconds */
-    if (cNsElapsed && cTicksElapsed)
-    {
-        /* Missing ??U8M and the assembly bugger. */
-        //uint64_t const uFreq = ASMMultU64ByU32DivByU32(cTicksElapsed, RT_NS_1SEC, cNsElapsed);
-        //uint64_t const uFreq = cTicksElapsed * (uint64_t)RT_NS_1SEC / cNsElapsed;
-        uint64_t const uFreq = cTicksElapsed / cNsElapsed;
-        Bs3TestPrintf("%RU64 Hz\n", uFreq);
+
+    Result.cTicksElapsed = ASMReadTSC() - uTscStart;
+    Result.cNsElapsed    = cNsElapsed - nsStart;
+
+    bs3Timing1_PrintResult(&Result, iRun, uVerbosity);
+
+    /* Add to total. */
+    g_TotalResult.cNsElapsed        += Result.cNsElapsed;
+    g_TotalResult.cTicksElapsed     += Result.cTicksElapsed;
+    if (Result.cTicksMin < g_TotalResult.cTicksMin || g_TotalResult.cTicksMin == 0)
+        g_TotalResult.cTicksMin      = Result.cTicksMin;
+    if (Result.cTicksMax > g_TotalResult.cTicksMax)
+        g_TotalResult.cTicksMax     += Result.cTicksMax;
+    g_TotalResult.cTicksSum         += Result.cTicksSum;
+    g_TotalResult.cTotalLoops       += Result.cTotalLoops;
+    g_TotalResult.cBackwards        += Result.cBackwards;
+    for (i = 0; i < RT_ELEMENTS(Result.aDistribution); i++)
+        g_TotalResult.aDistribution[i] += Result.aDistribution[i];
+}
+
+
+/**
+ * The TSC test driver.
+ *
+ * @param   cLoops      Number of test iterations.
+ * @param   cSecs       The number of seconds per iteration.
+ * @param   uVerbosity  How noisy we should be.
+ * @param   iMinHistory The threshold for big gap history.
+ */
+static void bs3Timing1_Tsc_Driver(unsigned cLoops, unsigned cSecs, unsigned uVerbosity, unsigned iMinHistory)
+{
+    unsigned iLoop;
+
+#if 1
+    /*
+     * Verify that the first/last bit in U64 works (didn't).
+     */
+    iLoop = ASMBitLastSetU64( UINT64_C(0x1000100010001000)); if (iLoop != 61) Bs3TestFailedF("%d: iLoop=%d\n", __LINE__, iLoop);
+    iLoop = ASMBitFirstSetU64(UINT64_C(0x1000100010001000)); if (iLoop != 13) Bs3TestFailedF("%d: iLoop=%d\n", __LINE__, iLoop);
+    iLoop = ASMBitLastSetU64( UINT64_C(0x000ffff000000000)); if (iLoop != 52) Bs3TestFailedF("%d: iLoop=%d\n", __LINE__, iLoop);
+    iLoop = ASMBitFirstSetU64(UINT64_C(0x000ffff000000000)); if (iLoop != 37) Bs3TestFailedF("%d: iLoop=%d\n", __LINE__, iLoop);
+#endif
+
+    /*
+     * Do the work.
+     */
+    Bs3TestPrintf("Running %u loops, %u second%s each...\n", cLoops, cSecs, cSecs != 1 ? "s" : "");
+    for (iLoop = 1; iLoop <= cLoops; iLoop++)
+        bs3Timing1_Tsc_One(iLoop, cSecs, uVerbosity, iMinHistory);
+
+    /*
+     * Report the total.
+     */
+    Bs3TestPrintf("Total:\n");
+    bs3Timing1_PrintResult(&g_TotalResult, iLoop, uVerbosity + 1);
+
+    /*
+     * Dump the large gap history, if any.
+     */
+    if (g_fBigHistoryWrapped || g_iBigHistory > 0)
+    {
+        uint32_t const  iFirst   = g_fBigHistoryWrapped ? g_iBigHistory : 0;
+        uint32_t const  iEnd     = g_iBigHistory;
+        uint64_t        uTscPrev = g_aBigHistory[iFirst].uTsc;
+        uint32_t        i        = iFirst;
+        Bs3TestPrintf("Big gap history (TSC, prev delta, test delta|level):\n");
+        do
+        {
+            Bs3TestPrintf(" %'RU64: %'14RU64 - %'14RU64|%u\n", g_aBigHistory[i].uTsc, g_aBigHistory[i].uTsc - uTscPrev,
+                          g_aBigHistory[i].cTicksDelta, ASMBitLastSetU64(g_aBigHistory[i].cTicksDelta));
+            uTscPrev = g_aBigHistory[i].uTsc;
+            if (++i >= RT_ELEMENTS(g_aBigHistory))
+                i = 0;
+        } while (i != iEnd);
     }
-}
-
+    else
+        Bs3TestPrintf("No big gap history.\n");
+}
+
+
+#ifndef STANDALONE_EXECUTABLE
 BS3_DECL(void) bs3Timing1_Tsc_pe32(void)
 {
     Bs3TestPrintf("bs3Timing1_Tsc_pe32\n");
-    bs3Timing1_Tsc_One();
-}
+    bs3Timing1_Tsc_Driver(5, 10 /*sec*/, 1 /*uVerbosity*/, 18);
+}
+#endif
 
 /* P.S. don't forget: VBoxManage setextradata bs3-timing-1 VBoxInternal/Devices/VMMDev/0/Config/TestingEnabled 1 */