Odd performance issue with nested for loops

Question

Below is the full source code you can just copy paste into Visual Studio for easy repro.

#include <Windows.h>

#include <algorithm>
#include <vector>
#include <iostream>
#include <sstream>

LARGE_INTEGER gFreq;

struct CProfileData;

// Yes, we map the pointer itself not the string, for performance reasons
std::vector<CProfileData*> gProfileData;

// simulate a draw buffer access to avoid CBlock::Draw being optimized away
float gDrawBuffer = 0;

struct CTimer
{
    CTimer()
    {
        Reset();
    }

    size_t GetElapsedMicro()
    {
        LARGE_INTEGER now;
        ::QueryPerformanceCounter(&now);
        return (1000000 * (now.QuadPart - m_timer.QuadPart)) / gFreq.QuadPart;
    }

    inline void Reset()
    {
        ::QueryPerformanceCounter(&m_timer);
    }

    LARGE_INTEGER m_timer;
};

struct CProfileData
{
    CProfileData() : m_hitCount(0), m_totalTime(0), m_minTime(-1),
        m_maxTime(0), m_name(NULL)
    {
        gProfileData.push_back(this);
    }

    size_t m_totalTime;
    size_t m_minTime;
    size_t m_maxTime;
    size_t m_hitCount;
    const char * m_name;
};

class CSimpleProfiler
{
public:
    CSimpleProfiler(const char * aLocationName, CProfileData * aData)
        : m_location(aLocationName), m_data(aData)
    {
        ::QueryPerformanceCounter(&m_clock);
    }

    ~CSimpleProfiler()
    {
        CProfileData & data = *m_data;
        data.m_name = m_location;
        ++data.m_hitCount;


        LARGE_INTEGER now;
        ::QueryPerformanceCounter(&now);

        size_t elapsed = (1000000 * (now.QuadPart - m_clock.QuadPart)) / gFreq.QuadPart;
        data.m_totalTime += elapsed;

        elapsed < data.m_minTime ? data.m_minTime = elapsed : true;
        elapsed > data.m_maxTime ? data.m_maxTime = elapsed : true;
    }

    static void PrintAll()
    {
        std::stringstream str;
        str.width(20);
        str << "Location";
        str.width(15);
        str << "Total time";
        str.width(15);
        str << "Average time";
        str.width(15);
        str << "Hit count";
        str.width(15);
        str << "Min";
        str.width(15);
        str << "Max" << std::endl;

        ::OutputDebugStringA(str.str().c_str());

        for (auto i = gProfileData.begin(); i != gProfileData.end(); ++i)
        {
            CProfileData & data = **i;
            std::stringstream str;
            str.width(20);
            str << data.m_name;
            str.width(15);
            str << data.m_totalTime;
            str.width(15);
            str << data.m_totalTime / (float)data.m_hitCount;
            str.width(15);
            str << data.m_hitCount;
            str.width(15);
            str << data.m_minTime;
            str.width(15);
            str << data.m_maxTime << std::endl;

            ::OutputDebugStringA(str.str().c_str());
        }
    }

    static void Clear()
    {
        for (auto i = gProfileData.begin(); i != gProfileData.end(); ++i)
        {
            (*i)->m_totalTime = 0;
            (*i)->m_minTime = 0;
            (*i)->m_maxTime = 0;
            (*i)->m_hitCount = 0;
        }
    }

private:
    LARGE_INTEGER m_clock;
    const char * m_location;
    CProfileData * m_data;
};


#define PROFILING_ENABLED

#ifdef PROFILING_ENABLED
#define SIMPLE_PROFILE \
    static CProfileData pdata ## __LINE__; \
    CSimpleProfiler p ## __LINE__(__FUNCTION__, & pdata ## __LINE__)

#define SIMPLE_PROFILE_WITH_NAME(Name) \
    static CProfileData pdata ## __LINE__; \
    CSimpleProfiler p ## __LINE__(Name, & pdata ## __LINE__)
#else
#define SIMPLE_PROFILE __noop
#define SIMPLE_PROFILE_WITH_NAME(Name) __noop
#endif


void InvalidateL1Cache()
{
    const int size = 256 * 1024; 
    static char *c = (char *)malloc(size);
    for (int i = 0; i < 0x0fff; i++)
        for (int j = 0; j < size; j++)
            c[j] = i*j;
}

int _tmain(int argc, _TCHAR* argv[])
{
    ::QueryPerformanceFrequency(&gFreq);

    LARGE_INTEGER pc;
    ::QueryPerformanceCounter(&pc);

    struct CBlock
    {
        float x;
        float y;

        void Draw(float aBlend)
        {   
            for (size_t i = 0; i < 100; ++i )
                gDrawBuffer += aBlend;
        }
    };


    typedef std::vector<std::vector<CBlock>> Layer;
    typedef std::vector<Layer> Layers;
    Layers mBlocks;

    // populate with dummy data;
    mBlocks.push_back(Layer());
    Layer & layer = mBlocks.back();
    layer.resize(109);

    srand(0); // for reprodicibility (determinism)
    for (auto i = layer.begin(); i != layer.end(); ++i)
    {
        i->resize(25 + rand() % 10 - 5);
    }

    // end populating dummy data

    while (1)
    {
        CSimpleProfiler::Clear();

        float aBlend = 1.f / (rand() % 100);
        {
            for (auto i = mBlocks.begin(); i != mBlocks.end(); ++i)
            {
                for (auto j = i->begin(); j != i->end(); ++j)
                {

                    CTimer t;

                    {
                        SIMPLE_PROFILE_WITH_NAME("Main_Draw_3");
                        for (auto blockIt = j->begin(); blockIt != j->end();)
                        {
                            CBlock * b = nullptr;
                            {
                                b = &*blockIt;
                            }
                        {
                            b->Draw(aBlend);
                        }
                        {
                            ++blockIt;
                        }
                        }
                    }

                    if (t.GetElapsedMicro() > 1000)
                    {
                        ::OutputDebugStringA("SLOWDOWN!\n");
                        CSimpleProfiler::PrintAll();
                    }
                }
            }
        }
    }

    return 0;
}

I get the following profiling from time to time, expressed in microseconds:

SLOWDOWN!
            Location     Total time   Average time      Hit count            Min            Max
         Main_Draw_3           2047        36.5536             56              0           1040

This spikes from time to time. Normally, it takes 100 microseconds for Main_Draw_3 block to finish, but it spikes to 1000 (the Max column) from time to time. What causes this?

I'm aware cache misses could play a role, but is it really that in this case?... What is happening here and how can I mitigate this?

More info:

• compiler VS 2013, compiled with Maximize Speed (/O2)

Answer 1

I think there might be two issues:

• Are you compiling with optimizations on? What are the flags?
• Maybe you could increase the sample size (by doing for instance ten (or hundred, or thousand etc) runs of this code in one profiling run). The reason is that if the sample size is small, the standard deviation is very high