.NET profiling API로 함수 실행시간 구하기

개요

APM(Application Performance Management)에 관해서 공부하는 중 함수의 실행 시간 및 계층 구조 뷰 출력 부분을 직접 구현하기 위한 스터디 한 자료를 정리합니다.

원하는 닷넷 어플리케이션 내부의 이벤트를 감시하거나 내부 정보를 가져오기 위해서는 ICorProfilerCallback과 ICorProfilerInfo를 이용해서 Profiler를 만들고 등록해줘야 합니다.

닷넷 프래임워크에게 지금 등록해준 Profiler에게 이벤트를 전달해달라고 요청하는 과정으로 이해하시면 됩니다.

닷넷 프레임워크에서 이벤트가 발생하면 ICorProfilerCallback 구현코드가 call back 형식으로 실행됩니다. 우리는 원하는 이벤트를 감시하기 위해서 ICorProfilerCallback의 메소드 중 하나를 선택해서 코드를 구현하기만 하면 되는 것이죠.

ICorProfilerInfo의 경우에는 닷넷 내부 정보를 알고 싶을 때 사용하게 되는데요. 예를 들면 방금 실행된 함수의 이름을 알고 싶다면 ICorProfilerInfo.GetTokenAndMetaDataFromFunction() 메소드를 사용해서 함수의 정보를 가져올 수 있습니다.

ICorProfilerCallback과 ICorProfilerInfo의 세부 정보는 아래 링크를 참고하시기 바랍니다.

• ICorProfilerCallback Interface
• ICorProfilerInfo Interface

Profiler 작성하기

Profiler는 아래와 같이 크게 4개의 파트로 나누어집니다.

• ALT main
  • COM 프로젝트의 기본적인 구성 요소
  • 대부분 자동 생성되는 코드 (일부 수정 필요)
• ProfilerCallback
  • 닷넷 프레임워크(CLR)에서 보내지는 이벤트를 수신 처리
  • ICorProfilerInfo 참조 가져오기
• MethodList
  • 함수 실행(enter), 종료(leave), tail call 이벤트 처리
  • 함수의 구체적인 정보 캐싱
• PerformanceCounter
  • 함수의 실행시간 계산

*.idl (interface definition language)

자동으로 생성된 idl 파일을 아래와 같이 수정합니다. 8번 라인 밑으로 추가하시면 됩니다.

uuid의 경우에는 새로 작성하셔도 되지만 코드에서 같은 부분을 찾아서 수정해야 합니다.

외부에 DotNetProfilerLib 인터페이스를 노출하겠다는 의미이며, 이후 닷넷 프레임워크에서 해당 인터페이스를 가져가서 사용하게 됩니다.

import "oaidl.idl";
import "ocidl.idl";

[
	uuid(5bbe4e9a-cb29-4446-a431-33c2c8604778),
	version(1.0),
]
interface IProfiler : IUnknown {
};
[
	uuid(DA37BE57-9EA8-4622-BDF5-E724CD3A60C1),
	version(1.0),
	helpstring("DotNetProfiler 1.0 Type Library")
]
library DotNetProfilerLib
{
	importlib("stdole2.tlb");
	[
		uuid(9E2B38F2-7355-4C61-A54F-434B7AC266C0),
		helpstring("Profiler Class")
	]
	coclass Profiler
	{
		[default] interface IUnknown;
	};
};

dllmain.h

DECLARE_LIBID의 인자를 LIBID_DotNetProfilerLib를 수정해줍니다. LIBID_DotNetProfilerLib에 해당하는 객체의 인터페이스를 외부로 노출하기 위한 작업입니다.

수정 후 오류가 나는데요. 프로젝트를 빌드하면 "Generated Files" 폴더에 있는 파일이 다시 생성되면서 해결됩니다.

class CdotnetprofilerModule : public ATL::CAtlDllModuleT< CdotnetprofilerModule >
{
public :
	DECLARE_LIBID(LIBID_DotNetProfilerLib)
	DECLARE_REGISTRY_APPID_RESOURCEID(IDR_DOTNETPROFILER, "{...}")
};

extern class CdotnetprofilerModule _AtlModule;

ProfilerCallback.h

ICorProfilerCallback, ICorProfilerCallback2 인터페이스를 구현할 클래스를 선언합니다.

...
class ATL_NO_VTABLE ProfilerCallback :
    public CComObjectRootEx<CComSingleThreadModel>,
    public CComCoClass<ProfilerCallback, &CLSID_Profiler>,
    public ICorProfilerCallback2
{
public:
    ProfilerCallback();

    DECLARE_REGISTRY_RESOURCEID(IDR_PROFILER)
    BEGIN_COM_MAP(ProfilerCallback)
        COM_INTERFACE_ENTRY(ICorProfilerCallback)
        COM_INTERFACE_ENTRY(ICorProfilerCallback2)
    END_COM_MAP()
    DECLARE_PROTECT_FINAL_CONSTRUCT()

    HRESULT FinalConstruct();
    void FinalRelease();

    // ICorProfilerCallback interface implementation
    virtual HRESULT __stdcall Initialize(IUnknown* pICorProfilerInfoUnk);

    // 이벤트 종류가 많아서 이하 생략합니다.
    ...

    // ICorProfilerCallback2 interface implementation
    virtual HRESULT __stdcall ThreadNameChanged(ThreadID threadId, ...);

    // 이벤트 종류가 많아서 이하 생략합니다.
    ...
};

OBJECT_ENTRY_AUTO(__uuidof(Profiler), ProfilerCallback)

ProfilerCallback.c

ProfilerCallback::Initialize

이 포스트에서 필요한 이벤트는 Initialize 뿐입니다. Profiler가 로딩되었을 때 발생하며 초기화 코드를 작성합니다.

...
CComQIPtr<ICorProfilerInfo> pICorProfilerInfo;
CComQIPtr<ICorProfilerInfo2> pICorProfilerInfo2;

HRESULT __stdcall ProfilerCallback::Initialize(IUnknown* pICorProfilerInfoUnk)
{
    // ICorProfilerInfo 가져오기
    HRESULT hr = pICorProfilerInfoUnk->QueryInterface(
        IID_ICorProfilerInfo, (LPVOID*) &pICorProfilerInfo);
    if (FAILED(hr)) {
        cout << "Error - QueryInterface(IID_ICorProfilerInfo)" << endl;
        return S_FALSE;
    }

    // ICorProfilerInfo2 가져오기
    hr = pICorProfilerInfoUnk->QueryInterface(
        IID_ICorProfilerInfo2, (LPVOID*) &pICorProfilerInfo2);
    if (FAILED(hr)) {
        cout << "Error - QueryInterface(IID_ICorProfilerInfo2)" << endl;
        return S_FALSE;
    }

    // 수신할 이벤트 종류 선택
    DWORD eventMask = (DWORD) (COR_PRF_MONITOR_ENTERLEAVE);
    hr = pICorProfilerInfo->SetEventMask(eventMask);
    if (FAILED(hr)) {
        cout << "Error - SetEventMask" << endl;
        return S_FALSE;
    }

    // 함수 실행 및 종료 이벤트 call back 함수 지정
    hr = pICorProfilerInfo2->SetEnterLeaveFunctionHooks2(
        (FunctionEnter2*) &FunctionEnterNaked,
        (FunctionLeave2*) &FunctionLeaveNaked,
        (FunctionTailcall2*) &FunctionTailcallNaked
    );
    if (FAILED(hr)) {
        cout << "Error - SetEnterLeaveFunctionHooks2" << endl;
        return S_FALSE;
    }

    MethodList::getIncetance().Initialize(pICorProfilerInfo);

    return S_OK;
}

naked specific

SetEnterLeaveFunctionHooks2()로 지정되는 함구들은 naked로 선언되어야 합니다.

naked로 선언된 함수는 스택 프레임 코드(prolog, epilog)가 없는 상태로 컴파일 됩니다. 함수가 실행될 때 자신만의 공간을 생성해서 사용하다가 종료될 때 반납하게 되는데요. 이부분이 생략되는 것입니다.

스택프레임 코드를 직접 작성해야 하며 이부분을 커스터마이징 하고자 할 때 사용합니다.

아래 코드를 보시면 실제 이벤트를 처리해야할 FunctionEnterGlobal 함수를 호출하는 것이 주 목적입니다.

다만 FunctionEnterGlobal 함수 실행 이전에 pushad로 범용 레지스터의 값들을 저장했다가 실행이 종료되면 popad를 이용해서 복원하는 것이 추가된 것입니다.

추측하건데 Profiler를 통해서 레지스터리 값이 변경되어서 닷넷 프레임워크의 이전 동작에 영향을 주는 것을 방지하기 위한 것으로 보입니다.

void _declspec(naked) FunctionEnterNaked(FunctionID functionID, ...)
{
    __asm
    {
        push    ebp
        mov     ebp, esp
        pushad

        mov     eax, [ebp + 0x14]      // argumentInfo
        push    eax
        mov     ecx, [ebp + 0x10]      // func
        push    ecx
        mov     edx, [ebp + 0x0C]      // clientData
        push    edx
        mov     eax, [ebp + 0x08]      // functionID
        push    eax
        call    FunctionEnterGlobal

        popad
        pop     ebp
        ret     16
    }
}

leave와 tail call도 같은 형식이기 때문에 설명을 생략합니다.

최종 이벤트 처리

string padding(int count) {
    string result = "";
    for (int i = 0; i < count; i++) result = result + "    ";
    return result;
}

static int callDepth = 0;

void __stdcall FunctionEnterGlobal(FunctionID functionID, ...)
{
    MethodInfo* methidInfo = MethodList::getIncetance().enter(functionID);
    cout << "FunctionEnter: " << padding(callDepth++) << methidInfo->getName()
         << endl;
}

void __stdcall FunctionLeaveGlobal(FunctionID functionID, ...)
{
    MethodInfo* methidInfo = MethodList::getIncetance().leave(functionID);
    cout << "FunctionLeave: " << padding(--callDepth) << methidInfo->getName()
         << " - " << methidInfo->latency << endl;
}

void __stdcall FunctionTailcallGlobal(FunctionID functionID, ...)
{
    MethodInfo* methidInfo = MethodList::getIncetance().tailCall(functionID);
    cout << "FunctionTailcall: " << padding(--callDepth) << methidInfo->getName()
         << " - " << methidInfo->latency << endl;
}

MethodList.hpp

...
using namespace std;

// 함수 정보를 저장
class MethodInfo {
public:
	MethodInfo(FunctionID id, string name) {
		_id = id;
		_name = name;
	}
    ...
};

// 함수 정보 객체 캐싱 및 실행 시간 측정
class MethodList {
public:
    static MethodList& getIncetance() {
        static MethodList instance;
        return instance;
    }

	/**
	* MethodList 객체를 초기화 합니다.
	* @param corProfilerInfo 프로파일러 인터페이스의 참조 주소
	*/
    void Initialize(ICorProfilerInfo* corProfilerInfo) {
        _pICorProfilerInfo = corProfilerInfo;
    }

	/**
	* 함수가 실행 상태로 진입하고 있다.
	* @param id 실행상태 중인 함수의 ID
	* @return 메소드 정보가 담긴 객체
	*/
	MethodInfo* enter(FunctionID id) {
		PerformanceCounter::getIncetance().enter();
		return getMethodInfo(id);
	}

	/**
	* 함수가 종료 중에 다른 함수를 실행하고 있다.
	* @param id 실행상태 중인 함수의 ID
	* @return 메소드 정보가 담긴 객체
	*/
	MethodInfo* leave(FunctionID id) {
		MethodInfo* methodInfo = getMethodInfo(id);
		methodInfo->latency = PerformanceCounter::getIncetance().leave();
		return methodInfo;
	}

	/**
	* 함수가 실행 상태로 진입하고 있다.
	* @param id 실행상태 중인 함수의 ID
	* @return 메소드 정보가 담긴 객체
	*/
	MethodInfo* tailCall(FunctionID id) {
		MethodInfo* methodInfo = getMethodInfo(id);
		methodInfo->latency = PerformanceCounter::getIncetance().leave();
		return methodInfo;
	}

	/**
	* FunctionID를 이용해서 메소드 정보 객체를 가져온다.
	* @param id 찾고자 하는 함수의 ID
	* @return 메소드 정보가 담긴 객체 (없으면 nullptr)
	*/
	MethodInfo* getMethodInfo(FunctionID id) {
		auto item = _methods.find(id);
		if (item != _methods.end()) {
			return item->second;
		}

		MethodInfo* methodInfo = new MethodInfo(id, _getMethodName(id));
		_methods.insert(pair<FunctionID, MethodInfo*>(id, methodInfo));
		return methodInfo;
	}

private:
    ...
};

PerformanceCounter.hpp

#pragma once

#include <windows.h>
#include <stack>

using namespace std;

class PerformanceCounter {
public:
    static PerformanceCounter& getIncetance() {
        static PerformanceCounter instance;
        return instance;
    }

    /**
    * 함수의 시작 시점을 스택에 저장한다.
    */
    void enter() {
        LARGE_INTEGER counter;
        QueryPerformanceCounter(&counter);
        _stack.push(counter);
    }

    /**
    * 함수의 종료시점과 스택의 최상위 시간과 비교해서 함수의 실행 시간을 리턴한다.
    * @return 함수 실행에 걸린 시간
    */
    double leave() {
        LARGE_INTEGER counter;
        QueryPerformanceCounter(&counter);

        LARGE_INTEGER exCounter = _stack.top();
        _stack.pop();

        // TODO: 예제의 실행시간이 너무 짧아서,
        // 임시로 시간대신 카운터 수를 그대로 사용하였다.
//        return (counter.QuadPart - exCounter.QuadPart) / _frequency.QuadPart;
        return (counter.QuadPart - exCounter.QuadPart);
    }

private:
    ...
};

테스트 어플리케이션 작성하기

테스트 프로그램은 특별한 제한 없이 작성하시면 됩니다.

Program.cs

using System;

namespace TestApp
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("enter to test #1 - sum");
            Console.ReadLine();
            Console.WriteLine(sum(1, 2));

            Console.WriteLine("enter to test #2 - recursive");
            Console.ReadLine();
            MethodTest methodTest = new MethodTest();
            Console.WriteLine(methodTest.recursive(3));

            Console.WriteLine("enter to close this program");
            Console.ReadLine();
        }

        static int sum(int a, int b)
        {
            return a + b;
        }
    }
}

MethodTest.cs

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;

namespace TestApp
{
    internal class MethodTest
    {
        public int recursive(int count)
        {
            if (count == 0) return 0;
            return recursive(count - 1) + count;
        }
    }
}

Profiler 등록하고 테스트하기

Profiler 등록

RegSrv32을 이용해서 COM 오브젝트를 레지스트리에 등록해서 사용할 수도 있지만 아래와 같이 환경변수를 사용해서 처리하겠습니다.

C:...> SET COR_ENABLE_PROFILING=1 C:...> SET COR_PROFILER={9E2B38F2-7355-4C61-A54F-434B7AC266C0} C:...> SET COR_PROFILER_PATH=Debug/DevToNetProfiler.dll C:...> START TestApp/bin/Debug/TestApp.exe

전체 함수 추적

테스트 어플리케이션만 필터링한 결과

::: tip FunctionLeave 이벤트 맨 뒤에 표시된 숫자는 함수의 실행 시간입니다. ms 단위로 표시하기에는 너무 작은 숫자이기 때문에 PerformanceCounter 리턴값을 그대로 사용했습니다. :::

실패한 것들

• 최신 버전의 닷넷 어플리케이션 프로파일링 실패
  • 엉뚱한 가설을 세우고 테스트하는 동안 많은 시간을 보낸 이후 .NET Core로 작성된 어플리케이션들에서 프로파일러가 로딩이 안되는 현상 발견
  • XPlat CoreCLR Profiler with ELT Simulation 참고
• Tail call 이벤트 캐치 실패
  • 닷넷 플랫폼이 Tail call을 지원하는 것은 확인
  • 언어 레밸의 문제라고 하는데 해결방법을 아직 확인하지 못함

새로 배운 것들

• _declspec(naked)
• Tail call
• NuGet

참고자료

• 포스트에서 설명하고 있는 전체 코드: https://github.com/ryujt/dotnet-profiler

Profiling API

• Create a .NET profiler with the Profiling API
• Creating a Custom .NET Profiler
  • 빌드 된 실행 데모는 Windows 8 이상에서 동작 안 하는 듯
  • Visual Studio 2022에서 소스가 빌드되지 않음
• Building a Mixed-Mode Sampling Profiler
• XPlat CoreCLR Profiler with ELT Simulation
• David Broman's CLR Profiling API Blog
• coreclr/Documentation/botr/profiling.md
• Building a .NET Cross Platform Profiler
• ASP.NET MVC 프로그램 계측을 위한 CLR 프로파일러 백도어 작성
• Reading parameters value with the .NET Profiling APIs
• Mini Profiler for ASP.ET Core Projects

Open Source Repository

• https://github.com/scouter-project/scouter
• https://github.com/elastic/apm-agent-dotnet
• https://github.com/MiniProfiler
• https://github.com/apache/skywalking
• https://github.com/DataDog/dd-trace-dotnet
• https://github.com/boobooly/Beyond.APM
• https://github.com/dotnet/dotnet-monitor

기타 참고자료

• 알아두면 쓸모 있는 닷넷(.NET) 이야기
• Build a RESTful API in ASP.NET 6.0 in 9 Steps!
• ASP.NET Core Crash Course - C# App in One Hour