[서버 이것저것] 로직 성능 측정해보기

개요

코드(로직)의 성능을 측정하는 것이 개발에서 중요하다는 것은 개발을 배우는 모든 사람이 알고있습니다.

다만 성능을 어떻게 측정하지? 또는 시간은 측정할 수 있는데 그 다음에는 어떻게 하지? 같은 고민이 있을 수 있습니다.

이번에는 간단하게 성능을 측정할 수 있는 프로파일러 클래스를 만들고 이를 활용하는 방안에 대해 생각해보겠습니다.

시간측정

컴퓨터의 시간측정

개요코드의 성능 측정을 위해 시작 끝 지점의 시간을 구해서 사용하거나, n초 후에 어떤 로직을 실행해야 하는 등 코드를 만들 때 시간을 측정해야 하는 경우가 있다. 이 때 시간을 어떻게 받아

basaeng.tistory.com

성능을 측정한다는 것은 어떠한 로직의 시간을 측정하고 이를 통계에 활용하는 것이라고 볼 수 있습니다.

이 때 시간을 측정하는 방법은 여러가지가 있습니다.

하나의 로직은 1ms보다 적은 시간에 실행되는 경우가 많기 때문에 시간을 측정하는 함수 중에서 프로파일러에서는 TSC를 사용하는 가장 정밀한 타이머인 QPC(Query Performance Counter)를 사용하도록 하겠습니다.

문서에 들어갈 feature

프로파일링을 마치면 나중에도 확인할 수 있도록 별도로 문서에 저장해야할 것입니다.

문서를 만들 때 column의 index로 어떤 것들이 필요할지 생각해봅시다.

이름: 측정하고자 하는 로직의 이름이 필요합니다.
호출횟수: 해당 로직이 몇번 호출되었는지 알아야합니다.
평균: 해당 로직의 평균 실행시간을 확인합니다.
최소 최대값: 해당 로직 호출 시 일어났던 최대 최소 값을 확인합니다.

이를 합쳐 프로파일링 샘플이라고 부르겠습니다.

클래스에 필요할 함수

프로파일링에 사용할 샘플에 대한 구성을 마쳤으니 이제 프로파일링을 위한 함수를 만들어봅시다.

먼저 프로파일링 클래스는 샘플 구조체에 대한 배열을 가지고 있다고 보겠습니다.

    PROFILE_SAMPLE samples[MAX_PROFILE_SIZE];

먼저 프로파일링을 위해 샘플 구조체 하나를 만드는 함수를 만들겠습니다.

FindOrCreateSample

PROFILE_SAMPLE* Profiler::FindOrCreateSample(const WCHAR * name)
{
    for (int i = 0; i < sampleIdx; i++)
    {
        if (lstrcmp(samples[i].szName, name) == 0)
        {
            return &samples[i];
        }
    }

    if (sampleIdx >= MAX_PROFILE_SIZE)
        return nullptr;

    PROFILE_SAMPLE newSample(name);
    samples[sampleIdx] = newSample;
    return &samples[sampleIdx++];
}

샘플이 존재한다면 샘플을 반환하고, 없다면 새로운 샘플을 만들어 반환합니다.

지금 생각해보니 sample을 순회하지 않고 unordered_map 자료구조를 통해 인덱싱해 최적화하는 것이 더 바람직 해보이지만 일단 넘어가겠습니다.

ProfileBegin, ProfileEnd

그 다음은 프로파일링 시작과 끝을 지정하는 것입니다.

void Profiler::ProfileBegin(const TCHAR* szName)
{
    LARGE_INTEGER now;
    QueryPerformanceCounter(&now);
    PROFILE_SAMPLE* pSample = FindOrCreateSample(szName);

    pSample->lStartTime = now;
}

void Profiler::ProfileEnd(const TCHAR* szName)
{
    LARGE_INTEGER now;
    QueryPerformanceCounter(&now);
    PROFILE_SAMPLE* pSample = FindOrCreateSample(szName);
    __int64 elapsed = now.QuadPart - pSample->lStartTime.QuadPart;
    pSample->iTotalTime += elapsed;
    pSample->iMin[0] = min(pSample->iMin[0], elapsed);
    pSample->iMax[0] = max(pSample->iMax[0], elapsed);
    pSample->iCall++;
}

시작할 때는 startTime을 지정합니다

끝날 때는 시작 시간과 비교해서 소요된 시간을 확인하고, 전체 시간과 최소 최대 호출횟수를 기록합니다.

텍스트 파일로 내보내기

void Profiler::ProfileDataOutTextFile(const TCHAR* szFileName)
{
    if (!szFileName)
        szFileName = (TCHAR*)L"profile.txt";  // 기본 파일명

    FILE* file = nullptr;
    _wfopen_s(&file, szFileName, L"wt, ccs=UTF-8");

    if (!file)
    {
        wprintf(L"파일 열기 실패: %s\n", szFileName);
        return;
    }

    LARGE_INTEGER freq;
    QueryPerformanceFrequency(&freq);

    fwprintf(file, L"           Name  |     Average  |        Min   |        Max   |      Call |\n");
    fwprintf(file, L"---------------------------------------------------------------------------\n");

    for (int i = 0; i < sampleIdx; i++)
    {
        PROFILE_SAMPLE& s = samples[i];
        double avg = (s.iTotalTime * 1000000.0) / freq.QuadPart / s.iCall;
        double minTime = (s.iMin[0] * 1000000.0) / freq.QuadPart;
        double maxTime = (s.iMax[0] * 1000000.0) / freq.QuadPart;

        fwprintf(file, L"%14s | %11.4f | %10.4f | %10.4f | %8lld\n",
            s.szName, avg, minTime, maxTime, s.iCall);
    }

    fclose(file);
}

샘플에 기록한 것을 이제 텍스트 파일로 옮겨서 기록해봅니다.

테스트해보기

많이 다뤄지는 주제인 락 동기화 객체에 대한 시간 측정으로 테스트해보았습니다.

#include <iostream>
#include <Windows.h>
#include <process.h>
#include "Profiler.h"
#include <vector>

#define MAX_THREAD_COUNT     64
#define ATTEMPT_COUNT 1000
using namespace std;

long result = 0;
long lock = 0;

CRITICAL_SECTION cs;
HANDLE mutex;

void SpinLock()
{
    while (1)
    {
        if (InterlockedExchange(&lock, 1) == 0)
        {
            break;
        }
    }
}

void SpinUnlock()
{
    lock = 0;
}

unsigned __stdcall Worker1(void* arg)
{
    for (int i = 0; i < ATTEMPT_COUNT; ++i)
    {
        ++result;
    }

    return 0;
}

unsigned __stdcall Worker2(void* arg)
{
    for (int i = 0; i < ATTEMPT_COUNT; ++i)
    {
        InterlockedIncrement(&result);
    }

    return 0;
}

unsigned __stdcall Worker3(void* arg)
{
    for (int i = 0; i < ATTEMPT_COUNT; ++i)
    {
    SpinLock();
        ++result;
    SpinUnlock();
    }

    return 0;
}

unsigned __stdcall Worker4(void* arg)
{
    for (int i = 0; i < ATTEMPT_COUNT; ++i)
    {
    EnterCriticalSection(&cs);
        ++result;
    LeaveCriticalSection(&cs);
    }

    return 0;
}

unsigned __stdcall Worker5(void* arg)
{

    for (int i = 0; i < ATTEMPT_COUNT; ++i)
    {
    WaitForSingleObject(mutex, INFINITE);
        ++result;
    ReleaseMutex(mutex);
    }

    return 0;
}


void RunBatch(string name, const wchar_t* label,
    unsigned(__stdcall* worker)(void*));

int main()
{
    RunBatch("Worker1", L"Normal", Worker1);
    RunBatch("Worker2", L"InterLockedIncrement", Worker2);
    RunBatch("Worker3", L"InterLockedExchange", Worker3);
    InitializeCriticalSection(&cs);
    RunBatch("Worker4", L"CriticalSection", Worker4);
    mutex = CreateMutex(NULL, FALSE, NULL);
    RunBatch("Worker5", L"Mutex", Worker5);



    cout << "END" << '\n';
    Profiler::GetInstance().ProfileDataOutTextFile(L"profile.txt");
}

void RunBatch(string name, const wchar_t* label,
    unsigned(__stdcall* worker)(void*))
{
    cout << name << '\n';
    for (int N = 0; N < 1000; ++N)
    {
        vector<HANDLE> handles;
        handles.reserve(MAX_THREAD_COUNT);
        PRO_BEGIN(label);
        for (int i = 0; i < MAX_THREAD_COUNT; ++i)
        {
            HANDLE h = (HANDLE)_beginthreadex(NULL, 0, worker, nullptr, 0, nullptr);
            handles.push_back(h);
        }

        WaitForMultipleObjects(MAX_THREAD_COUNT, &handles[0], TRUE, INFINITE);
        PRO_END(label);
        for (int i = 0; i < MAX_THREAD_COUNT; ++i)
            CloseHandle(handles[i]);
        //cout << result << '\n';
        result = 0;
    }

    Sleep(1000);
}

실행을 하고나면, 각 방법에 대한 성능 측정에 대한 문서가 생성됩니다.

이제 이를 활용해 성능 측정이 필요한 로직의 시작과 끝에 label을 지정해 확인해볼 수 있겠습니다.

해당 프로파일링은 디버깅 시에 사용하겠지만 측정할 때는 빈번한 호출이 되기 때문에 개선할 수 있다면 성능을 개선하면 좋습니다

IT 입문 기록