VirtualBox

Ignore:
Timestamp:
Feb 19, 2008 12:33:26 PM (17 years ago)
Author:
vboxsync
Message:

Making the logging more useful.

Location:
trunk/src/VBox/HostDrivers/Support
Files:
2 edited

Legend:

Unmodified
Added
Removed

  • trunk/src/VBox/HostDrivers/Support/SUPDRVShared.c

    r6790 r7014  
    3939#include <iprt/process.h>
    4040#include <iprt/log.h>
     41
     42/*
     43 * Logging assignments:
     44 *      Log     - useful stuff, like failures.
     45 *      LogFlow - program flow, except the really noisy bits.
     46 *      Log2    - Cleanup and IDTE
     47 *      Log3    - Loader flow noise.
     48 *      Log4    - Call VMMR0 flow noise.
     49 *      Log5    - Native yet-to-be-defined noise.
     50 *      Log6    - Native ioctl flow noise.
     51 *
     52 * Logging requires BUILD_TYPE=debug and possibly changes to the logger
     53 * instanciation in log-vbox.c(pp).
     54 */
    4155
    4256
    … …  
    461475                RTSpinlockRelease(pDevExt->Spinlock, &SpinlockTmp);
    462476
     477                Log(("supdrvCleanupSession: destroying %p/%d (%p/%p) cpid=%RTproc pid=%RTproc dtor=%p\n",
     478                     pObj, pObj->enmType, pObj->pvUser1, pObj->pvUser2, pObj->CreatorProcess, RTProcSelf(), pObj->pfnDestructor));
    463479                if (pObj->pfnDestructor)
    464480                    pObj->pfnDestructor(pObj, pObj->pvUser1, pObj->pvUser2);
    … …  
    951967            /* validate */
    952968            PSUPCALLVMMR0 pReq = (PSUPCALLVMMR0)pReqHdr;
     969            Log4(("SUP_IOCTL_CALL_VMMR0: op=%u in=%u arg=%RX64 p/t=%RTproc/%RTthrd\n",
     970                  pReq->u.In.uOperation, pReq->Hdr.cbIn, pReq->u.In.u64Arg, RTProcSelf(), RTThreadNativeSelf()));
     971
    953972            if (pReq->Hdr.cbIn == SUP_IOCTL_CALL_VMMR0_SIZE(0))
    954973            {
    … …  
    975994                    pReq->Hdr.rc = VERR_WRONG_ORDER;
    976995            }
     996
     997            if (    RT_FAILURE(pReq->Hdr.rc)
     998                &&  pReq->Hdr.rc != VERR_INTERRUPTED
     999                &&  pReq->Hdr.rc != VERR_TIMEOUT)
     1000                Log(("SUP_IOCTL_CALL_VMMR0: rc=%Rrc op=%u out=%u arg=%RX64 p/t=%RTproc/%RTthrd\n",
     1001                     pReq->Hdr.rc, pReq->u.In.uOperation, pReq->Hdr.cbOut, pReq->u.In.u64Arg, RTProcSelf(), RTThreadNativeSelf()));
     1002            else
     1003                Log4(("SUP_IOCTL_CALL_VMMR0: rc=%Rrc op=%u out=%u arg=%RX64 p/t=%RTproc/%RTthrd\n",
     1004                      pReq->Hdr.rc, pReq->u.In.uOperation, pReq->Hdr.cbOut, pReq->u.In.u64Arg, RTProcSelf(), RTThreadNativeSelf()));
    9771005            return 0;
    9781006        }
    … …  
    13201348                     * Object is to be destroyed, unlink it.
    13211349                     */
     1350                    pObj->u32Magic = SUPDRVOBJ_MAGIC + 1;
    13221351                    fDestroy = true;
    13231352                    if (pDevExt->pObjs == pObj)
    … …  
    13471376    if (fDestroy)
    13481377    {
    1349         pObj->u32Magic++;
     1378        Log(("SUPR0ObjRelease: destroying %p/%d (%p/%p) cpid=%RTproc pid=%RTproc dtor=%p\n",
     1379             pObj, pObj->enmType, pObj->pvUser1, pObj->pvUser2, pObj->CreatorProcess, RTProcSelf(), pObj->pfnDestructor));
    13501380        if (pObj->pfnDestructor)
    13511381            pObj->pfnDestructor(pObj, pObj->pvUser1, pObj->pvUser2);
    … …  
    32443274                pImage->cUsage--;
    32453275        }
     3276        else
     3277            Log(("supdrvIOCtl_LdrFree: Dangling objects in %p/%s!\n", pImage->pvImage, pImage->szName));
    32463278    }
    32473279    else

  • trunk/src/VBox/HostDrivers/Support/linux/SUPDrv-linux.c

    r6845 r7014  
    4040#include <iprt/err.h>
    4141#include <iprt/mem.h>
     42#include <iprt/log.h>
    4243
    4344#include <linux/sched.h>
    … …  
    687688                           ".\n",
    688689                           g_DevExt.pGip->u32Mode == SUPGIPMODE_SYNC_TSC ? "'synchronous'" : "'asynchronous'");
    689                     dprintf(("VBoxDrv::ModuleInit returning %#x\n", rc));
     690                    LogFlow(("VBoxDrv::ModuleInit returning %#x\n", rc));
    690691                    printk(KERN_DEBUG DEVICE_NAME ": Successfully loaded version "
    691692                           VBOX_VERSION_STRING " (interface " xstr(SUPDRVIOC_VERSION) ").\n");
    … …  
    739740    }
    740741#else  /* !CONFIG_VBOXDRV_AS_MISC */
    741 #ifdef CONFIG_DEVFS_FS
     742# ifdef CONFIG_DEVFS_FS
    742743    /*
    743744     * Unregister a device entry
    744745     */
    745746    VBOX_UNREGISTER_DEVFS(g_hDevFsVBoxDrv);
    746 #endif // devfs
     747# endif /* devfs */
    747748    rc = VBOX_UNREGISTER_DEVICE(g_iModuleMajor, DEVICE_NAME);
    748749    if (rc < 0)
    749750    {
    750         dprintf(("unregister_chrdev failed with rc=%#x (major:%d)\n", rc, g_iModuleMajor));
     751        dprintf(("VBOX_UNREGISTER_DEVICE failed with rc=%#x (major:%d)\n", rc, g_iModuleMajor));
    751752    }
    752753#endif /* !CONFIG_VBOXDRV_AS_MISC */
    … …  
    771772    int                 rc;
    772773    PSUPDRVSESSION      pSession;
    773     dprintf(("VBoxDrvLinuxCreate: pFilp=%p\n", pFilp));
     774    Log(("VBoxDrvLinuxCreate: pFilp=%p pid=%d/%d %s\n", pFilp, RTProcSelf(), current->pid, current->comm));
    774775
    775776    /*
    … …  
    785786    }
    786787
    787     dprintf(("VBoxDrvLinuxCreate: g_DevExt=%p pSession=%p rc=%d\n", &g_DevExt, pSession, rc));
    788788    pFilp->private_data = pSession;
    789789
     790    Log(("VBoxDrvLinuxCreate: g_DevExt=%p pSession=%p rc=%d/%d (pid=%d/%d %s)\n",
     791         &g_DevExt, pSession, rc, VBoxDrvLinuxErr2LinuxErr(rc),
     792         RTProcSelf(), current->pid, current->comm));
    790793    return VBoxDrvLinuxErr2LinuxErr(rc);
    791794}
    … …  
    800803static int VBoxDrvLinuxClose(struct inode *pInode, struct file *pFilp)
    801804{
    802     dprintf(("VBoxDrvLinuxClose: pFilp=%p private_data=%p\n", pFilp, pFilp->private_data));
     805    Log(("VBoxDrvLinuxClose: pFilp=%p pSession=%p pid=%d/%d %s\n",
     806         pFilp, pFilp->private_data, RTProcSelf(), current->pid, current->comm));
    803807    supdrvCloseSession(&g_DevExt, (PSUPDRVSESSION)pFilp->private_data);
    804808    pFilp->private_data = NULL;
    … …  
    861865    uint32_t            cbBuf;
    862866
    863     dprintf2(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p\n", pFilp, uCmd, (void *)ulArg));
     867    Log6(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p pid=%d/%d\n", pFilp, uCmd, (void *)ulArg, RTProcSelf(), current->pid));
    864868
    865869    /*
    … …  
    868872    if (RT_UNLIKELY(copy_from_user(&Hdr, (void *)ulArg, sizeof(Hdr))))
    869873    {
    870         dprintf(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx,) failed; uCmd=%#x.\n", ulArg, uCmd));
     874        Log(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx,) failed; uCmd=%#x.\n", ulArg, uCmd));
    871875        return -EFAULT;
    872876    }
    873877    if (RT_UNLIKELY((Hdr.fFlags & SUPREQHDR_FLAGS_MAGIC_MASK) != SUPREQHDR_FLAGS_MAGIC))
    874878    {
    875         dprintf(("VBoxDrvLinuxIOCtl: bad header magic %#x; uCmd=%#x\n", Hdr.fFlags & SUPREQHDR_FLAGS_MAGIC_MASK, uCmd));
     879        Log(("VBoxDrvLinuxIOCtl: bad header magic %#x; uCmd=%#x\n", Hdr.fFlags & SUPREQHDR_FLAGS_MAGIC_MASK, uCmd));
    876880        return -EINVAL;
    877881    }
    … …  
    883887    if (RT_UNLIKELY(cbBuf > _1M*16))
    884888    {
    885         dprintf(("VBoxDrvLinuxIOCtl: too big cbBuf=%#x; uCmd=%#x\n", cbBuf, uCmd));
     889        Log(("VBoxDrvLinuxIOCtl: too big cbBuf=%#x; uCmd=%#x\n", cbBuf, uCmd));
    886890        return -E2BIG;
    887891    }
    888892    if (RT_UNLIKELY(cbBuf != _IOC_SIZE(uCmd) && _IOC_SIZE(uCmd)))
    889893    {
    890         dprintf(("VBoxDrvLinuxIOCtl: bad ioctl cbBuf=%#x _IOC_SIZE=%#x; uCmd=%#x.\n", cbBuf, _IOC_SIZE(uCmd), uCmd));
     894        Log(("VBoxDrvLinuxIOCtl: bad ioctl cbBuf=%#x _IOC_SIZE=%#x; uCmd=%#x.\n", cbBuf, _IOC_SIZE(uCmd), uCmd));
    891895        return -EINVAL;
    892896    }
    … …  
    899903    if (RT_UNLIKELY(copy_from_user(pHdr, (void *)ulArg, Hdr.cbIn)))
    900904    {
    901         dprintf(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx, %#x) failed; uCmd=%#x.\n", ulArg, Hdr.cbIn, uCmd));
     905        Log(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx, %#x) failed; uCmd=%#x.\n", ulArg, Hdr.cbIn, uCmd));
    902906        RTMemFree(pHdr);
    903907        return -EFAULT;
    … …  
    929933    else
    930934    {
    931         dprintf(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p failed, rc=%d\n", pFilp, uCmd, (void *)ulArg, rc));
     935        Log(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p failed, rc=%d\n", pFilp, uCmd, (void *)ulArg, rc));
    932936        rc = -EINVAL;
    933937    }
    934938    RTMemFree(pHdr);
    935939
    936     dprintf2(("VBoxDrvLinuxIOCtl: returns %d\n", rc));
     940    Log6(("VBoxDrvLinuxIOCtl: returns %d (pid=%d/%d)\n", rc, RTProcSelf(), current->pid));
    937941    return rc;
    938942}
    … …  
    984988    unsigned i;
    985989#endif
    986     dprintf(("VBoxDrvLinuxInitGip:\n"));
     990    LogFlow(("VBoxDrvLinuxInitGip:\n"));
    987991
    988992    /*
    … …  
    992996    if (!pPage)
    993997    {
    994         dprintf(("VBoxDrvLinuxInitGip: failed to allocate the GIP page\n"));
     998        Log(("VBoxDrvLinuxInitGip: failed to allocate the GIP page\n"));
    995999        return -ENOMEM;
    9961000    }
    … …  
    10091013    pDevExt->ulLastJiffies  = jiffies;
    10101014    pDevExt->u64LastMonotime = (uint64_t)pDevExt->ulLastJiffies * TICK_NSEC;
    1011     dprintf(("VBoxDrvInitGIP: TICK_NSEC=%ld HZ=%d jiffies=%ld now=%lld\n",
    1012              TICK_NSEC, HZ, pDevExt->ulLastJiffies, pDevExt->u64LastMonotime));
     1015    Log(("VBoxDrvInitGIP: TICK_NSEC=%ld HZ=%d jiffies=%ld now=%lld\n",
     1016         TICK_NSEC, HZ, pDevExt->ulLastJiffies, pDevExt->u64LastMonotime));
    10131017    supdrvGipInit(pDevExt, pGip, HCPhys, pDevExt->u64LastMonotime,
    10141018                  HZ <= 1000 ? HZ : 1000);
    … …  
    10451049    unsigned i;
    10461050#endif
    1047     dprintf(("VBoxDrvLinuxTermGip:\n"));
     1051    LogFlow(("VBoxDrvLinuxTermGip:\n"));
    10481052
    10491053    /*
    … …  
    12321236    pgprot_t        pgFlags;
    12331237    pgprot_val(pgFlags) = _PAGE_PRESENT | _PAGE_USER;
    1234     dprintf2(("supdrvOSGipMap: ppGip=%p\n", ppGip));
     1238    LogFlow(("supdrvOSGipMap: ppGip=%p\n", ppGip));
    12351239
    12361240    /*
    … …  
    12551259        {
    12561260            rc = SUPDRV_ERR_NO_MEMORY;
    1257             dprintf(("supdrvOSGipMap: no vma found for ulAddr=%#lx!\n", ulAddr));
     1261            Log(("supdrvOSGipMap: no vma found for ulAddr=%#lx!\n", ulAddr));
    12581262        }
    12591263#endif
    … …  
    12611265        {
    12621266            rc = SUPDRV_ERR_NO_MEMORY;
    1263             dprintf(("supdrvOSGipMap: remap_page_range failed rc2=%d\n", rc2));
     1267            Log(("supdrvOSGipMap: remap_page_range failed rc2=%d\n", rc2));
    12641268        }
    12651269    }
    12661270    else
    12671271    {
    1268         dprintf(("supdrvOSGipMap: do_mmap failed ulAddr=%#lx\n", ulAddr));
     1272        Log(("supdrvOSGipMap: do_mmap failed ulAddr=%#lx\n", ulAddr));
    12691273        rc = SUPDRV_ERR_NO_MEMORY;
    12701274    }
    … …  
    12771281    {
    12781282        *ppGip = (PSUPGLOBALINFOPAGE)ulAddr;
    1279         dprintf2(("supdrvOSGipMap: ppGip=%p\n", *ppGip));
     1283        LogFlow(("supdrvOSGipMap: ppGip=%p\n", *ppGip));
    12801284        return 0;
    12811285    }
    … …  
    12911295    }
    12921296
    1293     dprintf2(("supdrvOSGipMap: returns %d\n", rc));
     1297    LogFlow(("supdrvOSGipMap: returns %d\n", rc));
    12941298    return rc;
    12951299}
    … …  
    13041308int VBOXCALL supdrvOSGipUnmap(PSUPDRVDEVEXT pDevExt, PSUPGLOBALINFOPAGE pGip)
    13051309{
    1306     dprintf2(("supdrvOSGipUnmap: pGip=%p\n", pGip));
     1310    LogFlow(("supdrvOSGipUnmap: pGip=%p\n", pGip));
    13071311    if (current->mm)
    13081312    {
    … …  
    13111315        up_write(&current->mm->mmap_sem);
    13121316    }
    1313     dprintf2(("supdrvOSGipUnmap: returns 0\n"));
     1317    LogFlow(("supdrvOSGipUnmap: returns 0\n"));
    13141318    return 0;
    13151319}
    … …  
    13231327void  VBOXCALL  supdrvOSGipResume(PSUPDRVDEVEXT pDevExt)
    13241328{
    1325     dprintf2(("supdrvOSGipResume:\n"));
     1329    LogFlow(("supdrvOSGipResume:\n"));
    13261330    ASMAtomicXchgU8(&pDevExt->fGIPSuspended, false);
    13271331#ifdef CONFIG_SMP
    … …  
    13771381    unsigned i;
    13781382#endif
    1379     dprintf2(("supdrvOSGipSuspend:\n"));
     1383    LogFlow(("supdrvOSGipSuspend:\n"));
    13801384    ASMAtomicXchgU8(&pDevExt->fGIPSuspended, true);
    13811385
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