VirtualBox

Changeset 96811 in vbox for trunk/src/VBox/Runtime/common


Ignore:
Timestamp:
Sep 21, 2022 1:23:31 PM (2 years ago)
Author:
vboxsync
Message:

VMM,IPRT,VBoxGuest,SUPDrv: Added a more efficient interface for guest logging using the CPUID instruction. This is mainly intended for development use and not enabled by default. Require updating host drivers.

File:
1 edited

Legend:

Unmodified
Added
Removed

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

    r96810 r96811  
    281281    /** The group. (used for prefixing.) */
    282282    unsigned                iGroup;
     283    /** Used by RTLogBulkNestedWrite.   */
     284    const char             *pszInfix;
    283285} RTLOGOUTPUTPREFIXEDARGS, *PRTLOGOUTPUTPREFIXEDARGS;
    284286
    … …  
    297299static FNRTLOGPHASEMSG rtlogPhaseMsgNormal;
    298300#endif
     301static DECLCALLBACK(size_t) rtLogOutputPrefixed(void *pv, const char *pachChars, size_t cbChars);
    299302static void rtlogLoggerExFLocked(PRTLOGGERINTERNAL pLoggerInt, unsigned fFlags, unsigned iGroup, const char *pszFormat, ...);
    300303
    … …  
    405408    { RT_STR_TUPLE("com"),          RTLOGDEST_COM },
    406409    { RT_STR_TUPLE("nodeny"),       RTLOGDEST_F_NO_DENY },
     410    { RT_STR_TUPLE("vmmrel"),       RTLOGDEST_VMM_REL },    /* before vmm */
     411    { RT_STR_TUPLE("vmm"),          RTLOGDEST_VMM },
    407412    { RT_STR_TUPLE("user"),         RTLOGDEST_USER },
    408413    /* The RTLOGDEST_FIXED_XXX flags are omitted on purpose. */
    … …  
    544549        uint16_t const iGroup = RT_HI_U16(fFlagsAndGroup);
    545550        if (   iGroup != UINT16_MAX
    546              && (   (pLoggerInt->afGroups[iGroup < pLoggerInt->cGroups ? iGroup : 0] & (fFlags | RTLOGGRPFLAGS_ENABLED))
    547                  != (fFlags | RTLOGGRPFLAGS_ENABLED)))
     551            && (   (pLoggerInt->afGroups[iGroup < pLoggerInt->cGroups ? iGroup : 0] & (fFlags | RTLOGGRPFLAGS_ENABLED))
     552                != (fFlags | RTLOGGRPFLAGS_ENABLED)))
    548553            pLoggerInt = NULL;
    549554    }
    … …  
    10851090            RTLogWriteUser(pszSecond, cchSecond);
    10861091    }
     1092
     1093# if defined(RT_ARCH_X86) || defined(RT_ARCH_AMD64)
     1094    if (pLoggerInt->fDestFlags & RTLOGDEST_VMM)
     1095    {
     1096        if (cchPreamble)
     1097            RTLogWriteVmm(pszPreamble, cchPreamble, false /*fReleaseLog*/);
     1098        if (cchFirst)
     1099            RTLogWriteVmm(pszFirst, cchFirst, false /*fReleaseLog*/);
     1100        if (cchSecond)
     1101            RTLogWriteVmm(pszSecond, cchSecond, false /*fReleaseLog*/);
     1102    }
     1103
     1104    if (pLoggerInt->fDestFlags & RTLOGDEST_VMM_REL)
     1105    {
     1106        if (cchPreamble)
     1107            RTLogWriteVmm(pszPreamble, cchPreamble, true /*fReleaseLog*/);
     1108        if (cchFirst)
     1109            RTLogWriteVmm(pszFirst, cchFirst, true /*fReleaseLog*/);
     1110        if (cchSecond)
     1111            RTLogWriteVmm(pszSecond, cchSecond, true /*fReleaseLog*/);
     1112    }
     1113# endif
    10871114
    10881115    if (pLoggerInt->fDestFlags & RTLOGDEST_DEBUGGER)
    … …  
    24362463        for (i = 0; i < RT_ELEMENTS(g_aLogDst); i++)
    24372464        {
    2438             size_t cchInstr = strlen(g_aLogDst[i].pszInstr);
    2439             if (!strncmp(pszValue, g_aLogDst[i].pszInstr, cchInstr))
     2465            if (!strncmp(pszValue, g_aLogDst[i].pszInstr, g_aLogDst[i].cchInstr))
    24402466            {
    24412467                if (!fNo)
    … …  
    24432469                else
    24442470                    pLoggerInt->fDestFlags &= ~g_aLogDst[i].fFlag;
    2445                 pszValue += cchInstr;
     2471                pszValue += g_aLogDst[i].cchInstr;
    24462472
    24472473                /* check for value. */
    … …  
    32163242
    32173243
     3244/**
     3245 * Write/copy bulk log data from a nested VM logger.
     3246 *
     3247 * This is used for
     3248 *
     3249 * @returns IRPT status code.
     3250 * @param   pLogger             The logger instance (NULL for default logger).
     3251 * @param   pch                 Pointer to the block of bulk log text to write.
     3252 * @param   cch                 Size of the block of bulk log text to write.
     3253 * @param   pszInfix            String to put after the line prefixes and the
     3254 *                              line content.
     3255 */
     3256RTDECL(int) RTLogBulkNestedWrite(PRTLOGGER pLogger, const char *pch, size_t cch, const char *pszInfix)
     3257{
     3258    if (cch > 0)
     3259    {
     3260        PRTLOGGERINTERNAL pLoggerInt = (PRTLOGGERINTERNAL)pLogger;
     3261        RTLOG_RESOLVE_DEFAULT_RET(pLoggerInt, VINF_LOG_NO_LOGGER);
     3262
     3263        /*
     3264         * Lock and validate it.
     3265         */
     3266        int rc = rtlogLock(pLoggerInt);
     3267        if (RT_SUCCESS(rc))
     3268        {
     3269            /*
     3270             * If we've got an auxilary descriptor, check if the buffer was flushed.
     3271             */
     3272            PRTLOGBUFFERDESC    pBufDesc = pLoggerInt->pBufDesc;
     3273            PRTLOGBUFFERAUXDESC pAuxDesc = pBufDesc->pAux;
     3274            if (!pAuxDesc || !pAuxDesc->fFlushedIndicator)
     3275            { /* likely, except maybe for ring-0 */ }
     3276            else
     3277            {
     3278                pAuxDesc->fFlushedIndicator = false;
     3279                pBufDesc->offBuf            = 0;
     3280            }
     3281
     3282            /*
     3283             * Write the stuff.
     3284             */
     3285            RTLOGOUTPUTPREFIXEDARGS Args;
     3286            Args.pLoggerInt = pLoggerInt;
     3287            Args.fFlags     = 0;
     3288            Args.iGroup     = ~0U;
     3289            Args.pszInfix   = pszInfix;
     3290            rtLogOutputPrefixed(&Args, pch, cch);
     3291            rtLogOutputPrefixed(&Args, pch, 0); /* termination call */
     3292
     3293            /*
     3294             * Maybe flush the buffer and update the auxiliary descriptor if there is one.
     3295             */
     3296            pBufDesc = pLoggerInt->pBufDesc;  /* (the descriptor may have changed) */
     3297            if (    !(pLoggerInt->fFlags & RTLOGFLAGS_BUFFERED)
     3298                &&  pBufDesc->offBuf)
     3299                rtlogFlush(pLoggerInt, false /*fNeedSpace*/);
     3300            else
     3301            {
     3302                pAuxDesc = pBufDesc->pAux;
     3303                if (pAuxDesc)
     3304                    pAuxDesc->offBuf = pBufDesc->offBuf;
     3305            }
     3306
     3307            rtlogUnlock(pLoggerInt);
     3308        }
     3309        return rc;
     3310    }
     3311    return VINF_SUCCESS;
     3312}
     3313RT_EXPORT_SYMBOL(RTLogBulkNestedWrite);
     3314
     3315
    32183316/*********************************************************************************************************************************
    32193317*   Flushing                                                                                                                     *
    … …  
    33263424        if (pLoggerInt->fDestFlags & RTLOGDEST_USER)
    33273425            RTLogWriteUser(pchToFlush, cchToFlush);
     3426
     3427#if defined(RT_ARCH_X86) || defined(RT_ARCH_AMD64)
     3428        if (pLoggerInt->fDestFlags & RTLOGDEST_VMM)
     3429            RTLogWriteVmm(pchToFlush, cchToFlush, false /*fReleaseLog*/);
     3430
     3431        if (pLoggerInt->fDestFlags & RTLOGDEST_VMM_REL)
     3432            RTLogWriteVmm(pchToFlush, cchToFlush, true /*fReleaseLog*/);
     3433#endif
    33283434
    33293435        if (pLoggerInt->fDestFlags & RTLOGDEST_DEBUGGER)
    … …  
    34713577            RTLogWriteUser(pThis->achScratch, pThis->offScratch);
    34723578
     3579# if defined(RT_ARCH_X86) || defined(RT_ARCH_AMD64)
     3580        if (pThis->fDestFlags & RTLOGDEST_VMM)
     3581            RTLogWriteVmm(pThis->achScratch, pThis->offScratch, false /*fReleaseLog*/);
     3582
     3583        if (pThis->fDestFlags & RTLOGDEST_VMM_REL)
     3584            RTLogWriteVmm(pThis->achScratch, pThis->offScratch, true /*fReleaseLog*/);
     3585# endif
     3586
    34733587        if (pThis->fDestFlags & RTLOGDEST_DEBUGGER)
    34743588            RTLogWriteDebugger(pThis->achScratch, pThis->offScratch);
    … …  
    37583872    if (cbChars)
    37593873    {
    3760         size_t cbRet = 0;
     3874        uint64_t const fFlags = pLoggerInt->fFlags;
     3875        size_t         cbRet  = 0;
    37613876        for (;;)
    37623877        {
    … …  
    37913906                /*
    37923907                 * Flush the buffer if there isn't enough room for the maximum prefix config.
    3793                  * Max is 256, add a couple of extra bytes.  See CCH_PREFIX check way below.
     3908                 * Max is 265, add a couple of extra bytes.  See CCH_PREFIX check way below.
    37943909                 */
    3795                 if (cb >= 256 + 16)
     3910                if (cb >= 265 + 16)
    37963911                    pLoggerInt->fPendingPrefix = false;
    37973912                else
    … …  
    38063921                 */
    38073922                psz = &pchBuf[offBuf];
    3808                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_TS)
     3923                if (fFlags & RTLOGFLAGS_PREFIX_TS)
    38093924                {
    3810                     uint64_t     u64    = RTTimeNanoTS();
    3811                     int          iBase  = 16;
    3812                     unsigned int fFlags = RTSTR_F_ZEROPAD;
    3813                     if (pLoggerInt->fFlags & RTLOGFLAGS_DECIMAL_TS)
     3925                    uint64_t     u64       = RTTimeNanoTS();
     3926                    int          iBase     = 16;
     3927                    unsigned int fStrFlags = RTSTR_F_ZEROPAD;
     3928                    if (fFlags & RTLOGFLAGS_DECIMAL_TS)
    38143929                    {
    3815                         iBase = 10;
    3816                         fFlags = 0;
     3930                        iBase     = 10;
     3931                        fStrFlags = 0;
    38173932                    }
    3818                     if (pLoggerInt->fFlags & RTLOGFLAGS_REL_TS)
     3933                    if (fFlags & RTLOGFLAGS_REL_TS)
    38193934                    {
    38203935                        static volatile uint64_t s_u64LastTs;
    … …  
    38273942                    }
    38283943                    /* 1E15 nanoseconds = 11 days */
    3829                     psz += RTStrFormatNumber(psz, u64, iBase, 16, 0, fFlags);
     3944                    psz += RTStrFormatNumber(psz, u64, iBase, 16, 0, fStrFlags);
    38303945                    *psz++ = ' ';
    38313946                }
    38323947#define CCH_PREFIX_01   0 + 17
    38333948
    3834                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_TSC)
     3949                if (fFlags & RTLOGFLAGS_PREFIX_TSC)
    38353950                {
    38363951#if defined(RT_ARCH_AMD64) || defined(RT_ARCH_X86)
    3837                     uint64_t     u64    = ASMReadTSC();
     3952                    uint64_t     u64       = ASMReadTSC();
    38383953#else
    3839                     uint64_t     u64    = RTTimeNanoTS();
     3954                    uint64_t     u64       = RTTimeNanoTS();
    38403955#endif
    3841                     int          iBase  = 16;
    3842                     unsigned int fFlags = RTSTR_F_ZEROPAD;
    3843                     if (pLoggerInt->fFlags & RTLOGFLAGS_DECIMAL_TS)
     3956                    int          iBase     = 16;
     3957                    unsigned int fStrFlags = RTSTR_F_ZEROPAD;
     3958                    if (fFlags & RTLOGFLAGS_DECIMAL_TS)
    38443959                    {
    3845                         iBase = 10;
    3846                         fFlags = 0;
     3960                        iBase    = 10;
     3961                        fStrFlags = 0;
    38473962                    }
    3848                     if (pLoggerInt->fFlags & RTLOGFLAGS_REL_TS)
     3963                    if (fFlags & RTLOGFLAGS_REL_TS)
    38493964                    {
    38503965                        static volatile uint64_t s_u64LastTsc;
    … …  
    38573972                    }
    38583973                    /* 1E15 ticks at 4GHz = 69 hours */
    3859                     psz += RTStrFormatNumber(psz, u64, iBase, 16, 0, fFlags);
     3974                    psz += RTStrFormatNumber(psz, u64, iBase, 16, 0, fStrFlags);
    38603975                    *psz++ = ' ';
    38613976                }
    38623977#define CCH_PREFIX_02   CCH_PREFIX_01 + 17
    38633978
    3864                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_MS_PROG)
     3979                if (fFlags & RTLOGFLAGS_PREFIX_MS_PROG)
    38653980                {
    38663981#ifndef IN_RING0
    … …  
    38753990#define CCH_PREFIX_03   CCH_PREFIX_02 + 21
    38763991
    3877                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_TIME)
     3992                if (fFlags & RTLOGFLAGS_PREFIX_TIME)
    38783993                {
    38793994#if defined(IN_RING3) || defined(IN_RING0)
    … …  
    38964011#define CCH_PREFIX_04   CCH_PREFIX_03 + (3+1+3+1+3+1+7+1)
    38974012
    3898                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_TIME_PROG)
     4013                if (fFlags & RTLOGFLAGS_PREFIX_TIME_PROG)
    38994014                {
    39004015
    … …  
    39204035
    39214036# if 0
    3922                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_DATETIME)
     4037                if (fFlags & RTLOGFLAGS_PREFIX_DATETIME)
    39234038                {
    39244039                    char szDate[32];
    … …  
    39354050# endif
    39364051
    3937                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_PID)
     4052                if (fFlags & RTLOGFLAGS_PREFIX_PID)
    39384053                {
    39394054                    RTPROCESS Process = RTProcSelf();
    … …  
    39434058#define CCH_PREFIX_07   CCH_PREFIX_06 + 9
    39444059
    3945                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_TID)
     4060                if (fFlags & RTLOGFLAGS_PREFIX_TID)
    39464061                {
    39474062                    RTNATIVETHREAD Thread = RTThreadNativeSelf();
    … …  
    39514066#define CCH_PREFIX_08   CCH_PREFIX_07 + 17
    39524067
    3953                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_THREAD)
     4068                if (fFlags & RTLOGFLAGS_PREFIX_THREAD)
    39544069                {
    39554070#ifdef IN_RING3
    … …  
    39644079#define CCH_PREFIX_09   CCH_PREFIX_08 + 17
    39654080
    3966                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_CPUID)
     4081                if (fFlags & RTLOGFLAGS_PREFIX_CPUID)
    39674082                {
    39684083#if defined(RT_ARCH_AMD64) || defined(RT_ARCH_X86)
    … …  
    39764091#define CCH_PREFIX_10   CCH_PREFIX_09 + 17
    39774092
    3978                 if (    (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_CUSTOM)
     4093                if (    (fFlags & RTLOGFLAGS_PREFIX_CUSTOM)
    39794094                    &&  pLoggerInt->pfnPrefix)
    39804095                {
    … …  
    39844099#define CCH_PREFIX_11   CCH_PREFIX_10 + 32
    39854100
    3986                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_LOCK_COUNTS)
     4101                if (fFlags & RTLOGFLAGS_PREFIX_LOCK_COUNTS)
    39874102                {
    39884103#ifdef IN_RING3 /** @todo implement these counters in ring-0 too? */
    … …  
    40094124#define CCH_PREFIX_12   CCH_PREFIX_11 + 8
    40104125
    4011                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_FLAG_NO)
     4126                if (fFlags & RTLOGFLAGS_PREFIX_FLAG_NO)
    40124127                {
    40134128                    psz += RTStrFormatNumber(psz, pArgs->fFlags, 16, 8, 0, RTSTR_F_ZEROPAD);
    … …  
    40164131#define CCH_PREFIX_13   CCH_PREFIX_12 + 9
    40174132
    4018                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_FLAG)
     4133                if (fFlags & RTLOGFLAGS_PREFIX_FLAG)
    40194134                {
    40204135#ifdef IN_RING3
    … …  
    40274142#define CCH_PREFIX_14   CCH_PREFIX_13 + 17
    40284143
    4029                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_GROUP_NO)
     4144                if (fFlags & RTLOGFLAGS_PREFIX_GROUP_NO)
    40304145                {
    40314146                    if (pArgs->iGroup != ~0U)
    … …  
    40424157#define CCH_PREFIX_15   CCH_PREFIX_14 + 9
    40434158
    4044                 if (pLoggerInt->fFlags & RTLOGFLAGS_PREFIX_GROUP)
     4159                if (fFlags & RTLOGFLAGS_PREFIX_GROUP)
    40454160                {
    40464161                    const unsigned fGrp = pLoggerInt->afGroups[pArgs->iGroup != ~0U ? pArgs->iGroup : 0];
    … …  
    40714186#define CCH_PREFIX_16   CCH_PREFIX_15 + 17
    40724187
    4073 #define CCH_PREFIX      ( CCH_PREFIX_16 )
    4074                 { AssertCompile(CCH_PREFIX < 256); }
     4188                if (pArgs->pszInfix)
     4189                {
     4190                    size_t cchInfix = strlen(pArgs->pszInfix);
     4191                    psz = rtLogStPNCpyPad2(psz, pArgs->pszInfix, RT_MIN(cchInfix, 8), 1);
     4192                }
     4193#define CCH_PREFIX_17   CCH_PREFIX_16 + 9
     4194
     4195
     4196#define CCH_PREFIX      ( CCH_PREFIX_17 )
     4197                { AssertCompile(CCH_PREFIX < 265); }
    40754198
    40764199                /*
    … …  
    40784201                 */
    40794202                AssertMsg(psz - &pchBuf[offBuf] <= 223,
    4080                           ("%#zx (%zd) - fFlags=%#x\n", psz - &pchBuf[offBuf], psz - &pchBuf[offBuf], pLoggerInt->fFlags));
     4203                          ("%#zx (%zd) - fFlags=%#x\n", psz - &pchBuf[offBuf], psz - &pchBuf[offBuf], fFlags));
    40814204                pBufDesc->offBuf = offBuf = (uint32_t)(psz - pchBuf);
    40824205                cb = cbBuf - offBuf - 1;
    … …  
    41014224            {
    41024225                cb = pszNewLine - pachChars;
    4103                 if (!(pLoggerInt->fFlags & RTLOGFLAGS_USECRLF))
     4226                if (!(fFlags & RTLOGFLAGS_USECRLF))
    41044227                {
    41054228                    cb += 1;
    … …  
    41914314        OutputArgs.iGroup     = iGroup;
    41924315        OutputArgs.fFlags     = fFlags;
     4316        OutputArgs.pszInfix   = NULL;
    41934317        RTLogFormatV(rtLogOutputPrefixed, &OutputArgs, pszFormat, args);
    41944318    }
Note: See TracChangeset for help on using the changeset viewer.

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