VirtualBox

Changeset 90975 in vbox for trunk/src/VBox


Ignore:
Timestamp:
Aug 28, 2021 11:35:23 PM (4 years ago)
Author:
vboxsync
svn:sync-xref-src-repo-rev:
146614
Message:

VMM: Ensure proper log flush order by going to ring-0 to wait for the flusher thread to complete. bugref:10086

Location:
trunk/src/VBox/VMM
Files:
3 edited

Legend:

Unmodified
Added
Removed

  • trunk/src/VBox/VMM/VMMR0/VMMR0.cpp

    r90972 r90975  
    147147static int  vmmR0UpdateLoggers(PGVM pGVM, VMCPUID idCpu, PVMMR0UPDATELOGGERSREQ pReq, size_t idxLogger);
    148148static int  vmmR0LogFlusher(PGVM pGVM);
     149static int  vmmR0LogWaitFlushed(PGVM pGVM, VMCPUID idCpu, size_t idxLogger);
    149150static int  vmmR0InitLoggers(PGVM pGVM);
    150151static void vmmR0CleanupLoggers(PGVM pGVM);
    … …  
    19841985
    19851986        /*
     1987         * Wait for the flush to finish with all the buffers for the given logger.
     1988         */
     1989        case VMMR0_DO_VMMR0_LOG_WAIT_FLUSHED:
     1990            if (idCpu == NIL_VMCPUID)
     1991                return VERR_INVALID_CPU_ID;
     1992            if (u64Arg < VMMLOGGER_IDX_MAX  && pReqHdr == NULL)
     1993                rc = vmmR0LogWaitFlushed(pGVM, idCpu /*idCpu*/, (size_t)u64Arg);
     1994            else
     1995                return VERR_INVALID_PARAMETER;
     1996            VMM_CHECK_SMAP_CHECK2(pGVM, RT_NOTHING);
     1997            break;
     1998
     1999        /*
    19862000         * Attempt to enable hm mode and check the current setting.
    19872001         */
    … …  
    30993113
    31003114
     3115/**
     3116 * VMMR0_DO_VMMR0_LOG_WAIT_FLUSHED: Waits for the flusher thread to finish all
     3117 * buffers for logger @a idxLogger.
     3118 *
     3119 * @returns VBox status code.
     3120 * @param   pGVM            The global (ring-0) VM structure.
     3121 * @param   idCpu           The ID of the calling EMT.
     3122 * @param   idxLogger       Which logger to wait on.
     3123 * @thread  EMT(idCpu)
     3124 */
     3125static int vmmR0LogWaitFlushed(PGVM pGVM, VMCPUID idCpu, size_t idxLogger)
     3126{
     3127    /*
     3128     * Check sanity.  First we require EMT to be calling us.
     3129     */
     3130    AssertReturn(idCpu < pGVM->cCpus, VERR_INVALID_CPU_ID);
     3131    PGVMCPU pGVCpu = &pGVM->aCpus[idCpu];
     3132    AssertReturn(pGVCpu->hEMT == RTThreadNativeSelf(), VERR_INVALID_CPU_ID);
     3133    AssertReturn(idxLogger < VMMLOGGER_IDX_MAX, VERR_OUT_OF_RANGE);
     3134    PVMMR0PERVCPULOGGER const pR0Log = &pGVCpu->vmmr0.s.u.aLoggers[idxLogger];
     3135
     3136    /*
     3137     * Do the waiting.
     3138     */
     3139    uint64_t const nsStart   = RTTimeNanoTS();
     3140    int            rc        = VINF_SUCCESS;
     3141
     3142    RTSpinlockAcquire(pGVM->vmmr0.s.LogFlusher.hSpinlock);
     3143    uint32_t       cFlushing = pR0Log->cFlushing;
     3144    while (cFlushing > 0)
     3145    {
     3146        pR0Log->fEmtWaiting = true;
     3147        RTSpinlockRelease(pGVM->vmmr0.s.LogFlusher.hSpinlock);
     3148
     3149        rc = RTSemEventWaitNoResume(pR0Log->hEventFlushWait, RT_MS_5MIN);
     3150
     3151        RTSpinlockAcquire(pGVM->vmmr0.s.LogFlusher.hSpinlock);
     3152        pR0Log->fEmtWaiting = false;
     3153        if (RT_SUCCESS(rc))
     3154        {
     3155            /* Read the new count, make sure it decreased before looping.  That
     3156               way we can guarentee that we will only wait more than 5 min * buffers. */
     3157            uint32_t const cPrevFlushing = cFlushing;
     3158            cFlushing = pR0Log->cFlushing;
     3159            if (cFlushing < cPrevFlushing)
     3160                continue;
     3161            rc = VERR_INTERNAL_ERROR_3;
     3162        }
     3163        break;
     3164    }
     3165    RTSpinlockRelease(pGVM->vmmr0.s.LogFlusher.hSpinlock);
     3166    return rc;
     3167}
     3168
     3169
     3170/**
     3171 * Inner worker for vmmR0LoggerFlushCommon.
     3172 */
    31013173static bool vmmR0LoggerFlushInner(PGVM pGVM, PGVMCPU pGVCpu, uint32_t idxLogger, size_t idxBuffer, uint32_t cbToFlush)
    31023174{
    … …  
    31473219    if (enmAction != kJustSignal)
    31483220    {
    3149         int rc = VMMR0EmtPrepareToBlock(pGVCpu, VINF_SUCCESS, "vmmR0LoggerFlushCommon", pR0Log->hEventFlushWait, &Ctx);
     3221        int rc = VMMR0EmtPrepareToBlock(pGVCpu, VINF_SUCCESS, "vmmR0LoggerFlushInner", pR0Log->hEventFlushWait, &Ctx);
    31503222        if (RT_SUCCESS(rc))
    31513223        { /* likely */ }

  • trunk/src/VBox/VMM/VMMR3/VMM.cpp

    r90974 r90975  
    151151
    152152/** Macro for flushing the ring-0 logging. */
    153 #define VMM_FLUSH_R0_LOG(a_pLogger, a_pR3Logger) \
     153#define VMM_FLUSH_R0_LOG(a_pVM, a_pVCpu, a_pLogger, a_pR3Logger) \
    154154    do { \
    155155        size_t const idxBuf = (a_pLogger)->idxBuf % VMMLOGGER_BUFFER_COUNT; \
    … …  
    158158        { /* likely? */ } \
    159159        else \
    160             vmmR3LogReturnFlush(a_pLogger, idxBuf, a_pR3Logger); \
     160            vmmR3LogReturnFlush(a_pVM, a_pVCpu, a_pLogger, idxBuf, a_pR3Logger); \
    161161    } while (0)
    162162
    … …  
    176176static int                  vmmR3ServiceCallRing3Request(PVM pVM, PVMCPU pVCpu);
    177177static FNRTTHREAD           vmmR3LogFlusher;
    178 static void                 vmmR3LogReturnFlush(PVMMR3CPULOGGER pShared, size_t idxBuf, PRTLOGGER pDstLogger);
     178static void                 vmmR3LogReturnFlush(PVM pVM, PVMCPU pVCpu, PVMMR3CPULOGGER pShared, size_t idxBuf,
     179                                                PRTLOGGER pDstLogger);
    179180static DECLCALLBACK(void)   vmmR3InfoFF(PVM pVM, PCDBGFINFOHLP pHlp, const char *pszArgs);
    180181
    … …  
    476477        STAMR3RegisterF(pVM, &pShared->StatFlushes,     STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Reg", i);
    477478        STAMR3RegisterF(pVM, &pShared->StatCannotBlock, STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Reg/CannotBlock", i);
    478         STAMR3RegisterF(pVM, &pShared->StatRaces,       STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Reg/Races", i);
    479         STAMR3RegisterF(pVM, &pShared->StatRacesReal,   STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Reg/RacesReal", i);
    480479        STAMR3RegisterF(pVM, &pShared->StatWait,        STAMTYPE_PROFILE, STAMVISIBILITY_USED, STAMUNIT_TICKS_PER_CALL, "", "/VMM/LogFlush/CPU%u/Reg/Wait", i);
     480        STAMR3RegisterF(pVM, &pShared->StatRaces,       STAMTYPE_PROFILE, STAMVISIBILITY_USED, STAMUNIT_TICKS_PER_CALL, "", "/VMM/LogFlush/CPU%u/Reg/Races", i);
     481        STAMR3RegisterF(pVM, &pShared->StatRacesToR0,   STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Reg/RacesToR0", i);
    481482        STAMR3RegisterF(pVM, &pShared->cbDropped,       STAMTYPE_U32,     STAMVISIBILITY_USED, STAMUNIT_BYTES,          "", "/VMM/LogFlush/CPU%u/Reg/cbDropped", i);
    482483        STAMR3RegisterF(pVM, &pShared->cbBuf,           STAMTYPE_U32,     STAMVISIBILITY_USED, STAMUNIT_BYTES,          "", "/VMM/LogFlush/CPU%u/Reg/cbBuf", i);
    … …  
    486487        STAMR3RegisterF(pVM, &pShared->StatFlushes,     STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Rel", i);
    487488        STAMR3RegisterF(pVM, &pShared->StatCannotBlock, STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Rel/CannotBlock", i);
    488         STAMR3RegisterF(pVM, &pShared->StatRaces,       STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Rel/Races", i);
    489         STAMR3RegisterF(pVM, &pShared->StatRacesReal,   STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Rel/RacesReal", i);
    490489        STAMR3RegisterF(pVM, &pShared->StatWait,        STAMTYPE_PROFILE, STAMVISIBILITY_USED, STAMUNIT_TICKS_PER_CALL, "", "/VMM/LogFlush/CPU%u/Rel/Wait", i);
     490        STAMR3RegisterF(pVM, &pShared->StatRaces,       STAMTYPE_PROFILE, STAMVISIBILITY_USED, STAMUNIT_TICKS_PER_CALL, "", "/VMM/LogFlush/CPU%u/Rel/Races", i);
     491        STAMR3RegisterF(pVM, &pShared->StatRacesToR0,   STAMTYPE_COUNTER, STAMVISIBILITY_USED, STAMUNIT_OCCURENCES,     "", "/VMM/LogFlush/CPU%u/Rel/RacesToR0", i);
    491492        STAMR3RegisterF(pVM, &pShared->cbDropped,       STAMTYPE_U32,     STAMVISIBILITY_USED, STAMUNIT_BYTES,          "", "/VMM/LogFlush/CPU%u/Rel/cbDropped", i);
    492493        STAMR3RegisterF(pVM, &pShared->cbBuf,           STAMTYPE_U32,     STAMVISIBILITY_USED, STAMUNIT_BYTES,          "", "/VMM/LogFlush/CPU%u/Rel/cbBuf", i);
    … …  
    544545         */
    545546#ifdef LOG_ENABLED
    546         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.Logger, NULL);
    547 #endif
    548         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
     547        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.Logger, NULL);
     548#endif
     549        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
    549550        if (rc != VINF_VMM_CALL_HOST)
    550551            break;
    … …  
    677678         */
    678679#ifdef LOG_ENABLED
    679         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.Logger, NULL);
    680 #endif
    681         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
     680        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.Logger, NULL);
     681#endif
     682        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
    682683        if (rc != VINF_VMM_CALL_HOST)
    683684            break;
    … …  
    942943 * Helper for VMM_FLUSH_R0_LOG that does the flushing.
    943944 *
     945 * @param   pVM         The cross context VM structure.
     946 * @param   pVCpu       The cross context virtual CPU structure of the calling
     947 *                      EMT.
    944948 * @param   pShared     The shared logger data.
    945949 * @param   idxBuf      The buffer to flush.
    946950 * @param   pDstLogger  The destination IPRT logger.
    947951 */
    948 static void vmmR3LogReturnFlush(PVMMR3CPULOGGER pShared, size_t idxBuf, PRTLOGGER pDstLogger)
     952static void vmmR3LogReturnFlush(PVM pVM, PVMCPU pVCpu, PVMMR3CPULOGGER pShared, size_t idxBuf, PRTLOGGER pDstLogger)
    949953{
    950954    uint32_t const cbToFlush = pShared->aBufs[idxBuf].AuxDesc.offBuf;
    951955    const char    *pszBefore = cbToFlush < 256 ? NULL : "*FLUSH*\n";
    952956    const char    *pszAfter  = cbToFlush < 256 ? NULL : "*END*\n";
     957
    953958#if VMMLOGGER_BUFFER_COUNT > 1
    954959    /*
    955      * To avoid totally mixing up the output, make some effort at delaying if
    956      * there are buffers still being worked on by the flusher thread.
    957      */
     960     * When we have more than one log buffer, the flusher thread may still be
     961     * working on the previous buffer when we get here.
     962     */
     963    char szBefore[64];
    958964    if (pShared->cFlushing > 0)
    959965    {
    960         STAM_REL_COUNTER_INC(&pShared->StatRaces);
    961         for (uint32_t iTry = 0; iTry < 32 && pShared->cFlushing != 0; iTry++)
    962         {
    963             RTLogBulkWrite(pDstLogger, NULL, "", 0, NULL); /* A no-op, but it takes the lock and the hope is */
    964             if (pShared->cFlushing != 0)                   /* that we end up waiting on the flusher finish up. */
    965                 RTThreadYield();
    966         }
     966        STAM_REL_PROFILE_START(&pShared->StatRaces, a);
     967        uint64_t const nsStart = RTTimeNanoTS();
     968
     969        /* A no-op, but it takes the lock and the hope is that we end up waiting
     970           on the flusher to finish up. */
     971        RTLogBulkWrite(pDstLogger, NULL, "", 0, NULL);
    967972        if (pShared->cFlushing != 0)
    968973        {
    969             pszBefore = "*MAYBE MISPLACED*\n";
    970             pszAfter  = "*END MISPLACED*\n";
    971             STAM_REL_COUNTER_INC(&pShared->StatRacesReal);
    972         }
    973     }
    974 #endif
     974            RTLogBulkWrite(pDstLogger, NULL, "", 0, NULL);
     975
     976            /* If no luck, go to ring-0 and to proper waiting. */
     977            if (pShared->cFlushing != 0)
     978            {
     979                STAM_REL_COUNTER_INC(&pShared->StatRacesToR0);
     980                SUPR3CallVMMR0Ex(VMCC_GET_VMR0_FOR_CALL(pVM), pVCpu->idCpu, VMMR0_DO_VMMR0_LOG_WAIT_FLUSHED, 0, NULL);
     981            }
     982        }
     983
     984        RTStrPrintf(szBefore, sizeof(szBefore), "*%sFLUSH* waited %'RU64 ns\n",
     985                    pShared->cFlushing == 0 ? "" : " MISORDERED",  RTTimeNanoTS() - nsStart);
     986        pszBefore = szBefore;
     987        STAM_REL_PROFILE_STOP(&pShared->StatRaces, a);
     988    }
     989#else
     990    RT_NOREF(pVM, pVCpu);
     991#endif
     992
    975993    RTLogBulkWrite(pDstLogger, pszBefore, pShared->aBufs[idxBuf].pchBufR3, cbToFlush, pszAfter);
    976994    pShared->aBufs[idxBuf].AuxDesc.fFlushedIndicator = true;
    … …  
    12501268         */
    12511269#ifdef LOG_ENABLED
    1252         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.Logger, NULL);
    1253 #endif
    1254         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
     1270        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.Logger, NULL);
     1271#endif
     1272        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
    12551273        if (rc != VINF_VMM_CALL_HOST)
    12561274        {
    … …  
    12941312         */
    12951313#ifdef LOG_ENABLED
    1296         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.Logger, NULL);
    1297 #endif
    1298         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
     1314        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.Logger, NULL);
     1315#endif
     1316        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
    12991317        if (rcStrict != VINF_VMM_CALL_HOST)
    13001318            return rcStrict;
    … …  
    24512469         */
    24522470#ifdef LOG_ENABLED
    2453         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.Logger, NULL);
    2454 #endif
    2455         VMM_FLUSH_R0_LOG(&pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
     2471        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.Logger, NULL);
     2472#endif
     2473        VMM_FLUSH_R0_LOG(pVM, pVCpu, &pVCpu->vmm.s.u.s.RelLogger, RTLogRelGetDefaultInstance());
    24562474        if (rc != VINF_VMM_CALL_HOST)
    24572475            break;

  • trunk/src/VBox/VMM/include/VMMInternal.h

    r90972 r90975  
    123123    STAMCOUNTER             StatFlushes;
    124124    STAMCOUNTER             StatCannotBlock;
    125     STAMCOUNTER             StatRaces;
    126     STAMCOUNTER             StatRacesReal;
    127125    STAMPROFILE             StatWait;
     126    STAMPROFILE             StatRaces;
     127    STAMCOUNTER             StatRacesToR0;
    128128} VMMR3CPULOGGER;
    129129/** Pointer to r0 logger data shared with ring-3. */
Note: See TracChangeset for help on using the changeset viewer.

© 2025 Oracle Support Privacy / Do Not Sell My Info Terms of Use Trademark Policy Automated Access Etiquette