Odd discrepancy in CPU vs Wall time measurements with malloc

Question

Answer: user and kernel cpu time is measured separately, be careful!

EDIT: pTimes is now reset to zero between each benchmark, but the results got weirder!

With the end goal of fiddling with my own custom memory management schemes, I made a simple benchmark for the existing malloc() in Visual Community 2019, Windows 10. Out of interest, I benchmarked the CPU times as well as wall times, and I tested malloc by allocating a large block of memory in many chunks, and then individually freeing each chunk without using them. See here:

void malloc_distr256(int nMemsize) {
    long long pFreeList[256];

    for (int i = 0; i < 256; ++i) pFreeList[i] = malloc(nMemsize >> 8);
    for (int i = 0; i < 256; ++i) free((void*)pFreeList[i]);
}

void malloc_distr64(int nMemsize) {
    long long pFreeList[64];

    for (int i = 0; i < 64; ++i) pFreeList[i] = malloc(nMemsize >> 6);
    for (int i = 0; i < 64; ++i) free((void*)pFreeList[i]);
}

void malloc_distr0(int nMemsize) {
    void* pMem = malloc(nMemsize);

    free(pMem);
}

These functions I benchmarked using the following code - "BenchTimes" is just a struct holding double CPU/wall times:

inline double cputime() {
    FILETIME lpCreationTime;
    FILETIME lpExitTime;
    FILETIME lpKernelTime;
    FILETIME lpUserTime;

    if (GetProcessTimes(GetCurrentProcess(), &lpCreationTime, &lpExitTime, &lpKernelTime, &lpUserTime)) {
        double dUnits = (double)(lpUserTime.dwLowDateTime | (long long)lpUserTime.dwHighDateTime << 32);
        return dUnits * 0.1;
    }
    else return 0xFFF0000000000000;
}

inline double walltime() {
    LARGE_INTEGER lnFreq, lnTime;

    if (QueryPerformanceFrequency(&lnFreq)) if (QueryPerformanceCounter(&lnTime))
        return 1000000.0 * (double)lnTime.QuadPart / (double)lnFreq.QuadPart;
//multiply by 1,000,000 to convert seconds to microseconds
//because the cpu time measurer I had in microseconds as well
    return 0.0;
}

void bench(void (pfnFunc)(int), int nMemsize, int nIters, int nReps, BenchTimes* pTimes) {
    pTimes->dCpuTime = 0.0;
    pTimes->dWallTime = 0.0;

    for (volatile int r = 0; r < nReps; ++r) {
        double dCpuStart = cputime();
        double dWallStart = walltime();

        for (volatile int i = 0; i < nIters; ++i) pfnFunc(nMemsize);

        double dCpuEnd = cputime();
        double dWallEnd = walltime();

        double dCpuDiff = dCpuEnd - dCpuStart;
        double dWallDiff = dWallEnd - dWallStart;

        pTimes->dCpuTime += dCpuDiff;
        pTimes->dWallTime += dWallDiff;
    }
}

These are the timings as measured on my pc (i5-9400f), timed in seconds.

I am very curious about the large discrepancies in performance and in Wall time to CPU time comparisons!

The code to run this is here:

    BenchTimes sTimes;

    bench(malloc_distr256, 1 << 20, 100, 1000, &sTimes);

    fprintf(stdout, "Malloc alloc/free bench allocated %lf megabytes, distributed over 256 chunks\n", (double)(1 << 20) / 1000000);
    fprintf(stdout, "Malloc alloc/free bench returned:\nWalltime - total: %lf\nCPU Time - total: %lf\n", sTimes.dWallTime / 1000000, sTimes.dCpuTime / 1000000);
    
    bench(malloc_distr64, 1 << 20, 100, 1000, &sTimes);

    fprintf(stdout, "\nMalloc alloc/free bench allocated %lf megabytes, distributed over 64 chunks\n", (double)(1 << 20) / 1000000);
    fprintf(stdout, "\nMalloc alloc/free bench returned:\nWalltime - total: %lf\nCPU Time - total: %lf\n", sTimes.dWallTime / 1000000, sTimes.dCpuTime / 1000000);

    bench(malloc_distr0, 1 << 20, 100, 1000, &sTimes);

    fprintf(stdout, "\nMalloc alloc/free bench allocated %lf megabytes, distributed over no chunks\n", (double)(1 << 20) / 1000000);
    fprintf(stdout, "\nMalloc alloc/free bench returned:\nWalltime - total: %lf\nCPU Time - total: %lf\n", sTimes.dWallTime / 1000000, sTimes.dCpuTime / 1000000);

    system("pause");

Answer 1

malloc is implemented via HeapAlloc which is implemented in system function named RtlAllocateHeap.

The function manages heap. It allocates system memory pages via VirtualAlloc[Ex] or its equivalent, and provides smaller allocations within these pages.

With larger allocations, the VirtualAlloc[Ex] equivalent is called on every allocation, with smaller allocations it is called occasionally.

VirtualAlloc[Ex] is implemented using NtAllocateVirtualMemory which is kernel call. Most of the time spent in it is not counted in lpUserTime.

On the other hand, QueryPerformanceCounter is a honest total time.