.NET Performance

  • 아티클

ETW를 사용한 .NET 응용 프로그램의 성능 진단

Subramanian Ramaswamy

코드 샘플 다운로드

직접 작성한 관리되는 응용 프로그램이 너무 느리게 실행된다고 가정해 보십시오. 응용 프로그램의 기능은 정상적이지만 성능이 문제이며, 성능 문제를 진단해서 해결하고 싶지만 응용 프로그램이 프로덕션 환경에서 실행 중이어서 프로파일러를 설치하거나 응용 프로그램을 중단할 수가 없을 수 있습니다. 또는 응용 프로그램이 널리 사용되지 않기 때문에 CPU 프로파일링을 위한 Visual Studio Profiler를 구매하기에는 설득력이 부족할 수 있습니다.

다행스럽게도 ETW(Event Tracing for Windows)를 사용하면 이러한 문제를 완화할 수 있습니다. 이 강력한 로깅 기술은 Windows 인프라의 여러 부분에서 기본 제공되며 Microsoft .NET Framework 4 CLR에서도 활용되어 관리되는 응용 프로그램의 프로파일링이 그 어느 때보다 수월해졌습니다. ETW는 시스템 수준의 데이터를 수집하고 모든 리소스(CPU, 디스크, 네트워크 및 메모리)를 프로파일링하므로 포괄적인 정보를 얻는 데 매우 유용합니다. 게다가 ETW 환경을 조정하여 오버헤드를 낮출 수 있어 프로덕션 진단에도 적합합니다.

이 기사의 목표는 ETW를 사용하여 관리되는 응용 프로그램을 프로파일링하는 기능의 강력함을 확인하는 것입니다. 여기에서 모든 내용을 다루지는 않을 것입니다. 특히 진단에 사용할 수 있는 몇 가지 OS 이벤트와 CLR ETW 이벤트에 대해서는 설명하지 않습니다. 그러나 ETW 환경을 사용하여 관리되는 응용 프로그램의 성능과 기능을 크게 향상할 수 있는 유용한 지식을 얻을 수 있을 것입니다. 관리되는 코드에 대한 ETW 기반 진단을 시작하기 위해 bcl.codeplex.com/releases/view/49601에서 다운로드 가능하며 무료로 제공되는 ETW 도구인 PerfMonitor를 사용하여 샘플 조사를 수행하겠습니다.

PerfMonitor

PerfMonitor를 사용하면 신속하고 수월하게 ETW 성능 데이터를 수집하고 유용한 보고서를 생성할 수 있습니다. Visual Studio Profiler와 같은 전문 도구를 대체하기 위한 것은 아니지만 응용 프로그램의 성능 특성에 대한 개요를 제공하고 몇 가지 간략한 분석을 수행하도록 지원합니다.

Windows Performance Toolkit을 통해 무료로 제공되는 XPerf라는 다른 ETW 진단 도구도 있습니다. 그러나 XPerf는 Windows에서 네이티브 코드 프로파일링에는 유용하지만 아직 관리되는 코드 프로파일링에 대한 지원은 완벽하지 않습니다. 반면에 PerfMonitor는 ETW를 사용하여 관리되는 코드를 프로파일링하는 데 다양하고 강력한 기능을 제공합니다. PerfMonitor는 .NET Framework 런타임 코드와 연관된 기호화 정보 수집 기능이 있어 .NET Framework 성능 조사를 위한 훌륭한 도구이지만 XPerf에서와 같은 세부적인 분석은 지원하지 않습니다. 

PerfMonitor는 필요한 기능을 모두 갖춘 도구이므로 이 도구만 준비하면 관리되는 응용 프로그램의 프로파일링과 진단을 시작할 수 있습니다. 유일한 요구 사항은 Windows Vista 또는 Windows Server 2008을 실행해야 한다는 것입니다. PerfMonitor는 명령줄 도구이며, 도구가 있는 위치에서 PerfMonitor.exe usersGuide를 실행하면 개요가 표시됩니다. 예를 들어 고객의 프로그램이 프로덕션 서버에서 운영 상태일 때 진단하려는 경우 해당 시스템으로 파일을 복사하면 프로필 수집을 시작할 준비가 완료됩니다. 필요한 경우 오프라인으로 프로필을 분석할 수 있습니다.

성능 조사 중에는 일반적으로 CPU, 디스크 I/O, 메모리, 그리고 가용성의 네 가지 요소가 확인됩니다. 대부분의 조사는 응용 프로그램 시작과 실행에 모두 영향을 주는 CPU부터 시작됩니다. 디스크 I/O 검사는 시작 시간이 오래 걸리는 경우를 진단할 때 유용하며(디스크 I/O는 재부팅 이후와 같이 메모리에 프로그램이 없을 때 프로그램을 처음 시작하는 데 걸리는 시간에 가장 중요한 요소입니다), 과도한 메모리 소비(또는 유출)는 응용 프로그램이 시간이 따라 점차 느려지는 경우를 진단할 때 유용합니다. 확장성은 응용 프로그램의 출력량이 프로세서의 수에 따라 비례적으로 높아지기를 원하는 경우에 관련이 있습니다.

PerfMonitor는 확장성을 제외하고 이러한 모든 항목의 스냅샷을 신속하게 제공하며 다른 특수한 도구를 사용하여 세부적으로 조사하기 위한 충분한 정보도 제공합니다. 예를 들어 CLR .NET GC(가비지 수집) 힙과 관련된 문제를 진단하려면 CLRProfiler가 더 나은 선택입니다. 그러나 PerfMonitor는 문제가 있는지, 그리고 다른 도구를 사용하여 세부적으로 조사할 필요가 있는지 여부를 신속하게 알려줍니다. 조금 뒤에 확인하겠지만 경우에 따라서는 PerfMonitor 자체에서 문제를 지적하고 성능 버그를 해결하는 데 필요한 모든 정보를 제공하기도 합니다. 프로그램의 메모리 사용 감사와 성능 계획의 중요성에 대해 설명한 CLR Inside Out 칼럼, “.NET 응용 프로그램의 메모리 사용 감사” (msdn.microsoft.com/magazine/dd882521)를 읽어 보십시오. 이러한 개념을 확장해서 PerfMonitor는 메모리뿐만 아니라 관리되는 프로그램의 여러 성능 측면을 감사할 수 있습니다.

샘플 조사: CsvToXml

여기에서 ETW를 사용하여 진단할 샘플 프로그램은 CSV 파일을 XML 파일로 변환합니다. 소스 코드와 솔루션 패키지(샘플 입력 CSV 파일, data.csv 포함)는 code.msdn.microsoft.com/mag201012ETW에서 받을 수 있습니다. 프로그램을 실행하려면 CsvToXml.exe data.csv output.xml 명령을 실행합니다.

다른 여러 프로그램들과 마찬가지로 CsvToXml은 급하게 개발되었는데 개발자가 큰 CSV 파일이 사용되리라고 예상하지 못한 것이 문제였습니다. 실제 환경에서 사용하기에는 너무 느려서 750K 파일을 처리하는 데 자그마치 15초가 걸렸습니다! 문제가 있다는 것은 알고 있었지만 프로파일링 도구가 없었기 때문에 문제의 원인을 추측하는 수밖에 없었습니다. 여러분이라면 소스만 보고 원인을 찾을 수 있겠습니까? 다행스럽게도 PerfMonitor로 문제를 해결할 수 있습니다.

프로그램 추적 생성 및 보기

첫 번째 단계는 관리자 명령 프롬프트 창에서 다음 명령을 실행하여 응용 프로그램에 대한 간략한 감사를 수행하는 것입니다. ETW는 데이터를 시스템 수준에서 수집하므로 관리자 권한이 필요합니다.

PerfMonitor runAnalyze CsvToXml.exe data.csv out.xml

이 명령은 ETW 로깅을 시작하고, CsvToXml.exe를 실행한 다음, CsvToXml이 완료되기를 기다리고, 로깅을 중단하며, 마지막으로 CsvToXml에 대한 분석을 보여주는 웹 페이지를 표시합니다. 이렇게 간단한 한 단계로 CsvToXml의 성능 병목 현상을 밝혀내는 데 도움이 되는 풍부한 정보를 얻을 수 있습니다.

그림 1에 이 명령의 결과가 나와 있습니다. 이 페이지에 나오는 데이터에는 프로세스 ID, 사용된 명령줄, 그리고 CPU 통계와 GC 통계, JIT(Just-In-Time) 통계를 비롯한 고수준 성능 데이터의 상세 내역이 있습니다. PerfMonitor는 또한 진단을 시작할 위치에 대한 1순위 분석과 정보 제공용 자료 또는 다른 도구에 대한 링크를 제공합니다.

Figure 1 Performance Analysis for CsvToXml

그림 1 CsvToXml에 대한 성능 분석

보고서는 형식 변환을 수행하는 데 거의 14초가 소요되었으며 CPU 사용률이 13.6초 동안 99%라는 것을 보여 줍니다. 따라서 이 시나리오는 CPU와 연관되어 있습니다.

전체 GC 시간 및 GC 일시 정지 시간은 바람직한 낮은 값을 보이고 있지만, 최대 GC 할당 속도가 과도한 수준인 105.1MB/sec을 나타내고 있어 이 부분에 추가 조사가 필요하다는 것을 알 수 있습니다.

CPU 분석

상세한 CPU 분석에서는 그림 2에 나오는 것처럼 CPU 시간을 분류해서 보여 주며 CPU 프로필 데이터를 읽는 데는 세 가지 방법이 있습니다. bottom-up(상향식) 뷰는 어떤 메서드가 CPU 시간을 가장 많이 소비하고 가장 먼저 진단해야 하는지 알려 줍니다. top-down(하향식) 뷰를 통해서는 코드의 아키텍처와 구조에 변경이 필요한지 확인하고 프로그램의 전체적인 성능을 이해할 수 있습니다. caller-callee(호출자-호출 수신자) 뷰에서는 예를 들어 어떤 메서드가 어떤 메서드를 호출하는지와 같은 메서드 간의 관계를 보여 줍니다. 

Figure 2 Bottom-Up Analysis of CsvToXml.exe

그림 2 CsvToXml.exe의 상향식 분석

다른 CPU 프로파일러와 마찬가지로 PerfMonitor 뷰에서는 포괄 시간(해당 호출 수신자를 포함하여 특정 메서드에서 소비된 시간)과 단독 시간(호출 수신자를 제외하고 특정 메서드에서 소비된 시간)을 보여 줍니다. 포괄 시간과 단독 시간이 동일한 경우 해당 특정 메서드 내에서 작업이 수행된 것입니다. PerfMonitor는 또한 특정 메서드의 시간에 따른 CPU 사용률을 세분화해서 보여 주는 CPU 사용률 그래프를 제공합니다. 보고서의 열 제목 위로 이동하면 어떤 의미가 있는지 자세히 볼 수 있습니다.

대부분의 성능 조사는 메서드를 단독 시간별로 나열하는 상향식 뷰로 시작합니다(그림 2에 나오는 뷰). 상향식 뷰를 선택해 보면 mscorlib 메서드 System.IO.File.OpenText가 CPU를 가장 많이 사용한 것을 알 수 있습니다. 해당 링크를 클릭하면 OpenText 메서드에 대한 호출자-호출 수신자 뷰가 열리며 이를 통해 프로그램에서 CsvToXml.CsvFile.get_ColumnNames 메서드가 OpenText를 호출하며 get_ColumnNames가 CPU 시간을 거의 10초나 소비한 것을 알 수 있습니다(그림 3). 또한 이 메서드는 CsvToXml.CsvFile.XmlElementForRow의 루프 내에서 호출되며, XmlElementForRow는 Main 메서드에서 호출되는 것을 알 수 있습니다.

Figure 3 Caller-Callee View for get_ColumnNames

그림 3 get_ColumnNames의 호출자-호출 수신자 뷰

따라서 이러한 메서드에 문제가 있다는 것을 짐작할 수 있습니다. 이러한 메서드의 코드를 열어 보면 그림 4에 표시된 것처럼 문제가 드러납니다. 루프 내에서 반복적으로 파일을 열고 구문 분석을 수행한 것입니다.

그림 4 ColumnNames 메서드는 XmlElementForRow 메서드에서 호출됩니다

public string[] ColumnNames
{
  get
  {
    using (var reader = File.OpenText(Filename))
      return Parse(reader.ReadLine());
  }
}

public string XmlElementForRow(string elementName, string[] row)
{
  string ret = "<" + elementName;
  for (int i = 0; i < row.Length; i++)
    ret += " " + ToValidXmlName(ColumnNames[i]) + "=\"" + EscapeXml(row[i]) + "\"";
  ret += "/>";
  return ret;
}

비슷한 시나리오는 생각보다 더 자주 발생합니다. 메서드를 처음 작성할 때는 ColumnNames의 경우처럼 메서드가 자주 호출되지 않을 것이라고 생각하고 성능을 크게 고려하지 않는 경우가 많습니다. 그러나 루프에서 메서드를 호출하여 응용 프로그램의 성능이 저하되는 경우가 있습니다.

CSV 파일의 경우 모든 행의 형식이 동일하므로 작업을 매번 수행할 필요가 없습니다. 그림 5에 나오는 것처럼 ColumnNames의 기능을 생성자로 옮기고 속성이 캐시된 열 이름을 제공하도록 할 수 있습니다. 이렇게 하면 파일을 한 번만 읽도록 할 수 있습니다.

그림 5 성능 향상을 위해 열 이름을 캐싱

public CsvFile(string csvFileName)
{
  Filename = csvFileName;

    using (var reader = File.OpenText(Filename))
      ColumnNames = Parse(reader.ReadLine());
        
}

public string Filename { get; private set; }

public string[] ColumnNames { get; private set;}

다시 빌드하고 같은 명령을 다시 실행해 보면 이제 응용 프로그램이 훨씬 빨라져서 이번에는 2.5초가 걸렸습니다.

수정된 데이터를 검토하면 여전히 CPU 시간이 가장 중요한 것을 알 수 있습니다. CPU 시간으로 드릴 다운해서 상향 분석을 보면 이제 Regex.Replace가 가장 비용이 높은 메서드이며 EscapeXml 및 ToValidXmlName에서 호출되고 있음이 확인됩니다. EscapeXml이 비용이 더 높은 메서드(단독 시간 330ms)이므로 이 메서드의 소스 코드를 확인해 보겠습니다.

private static string EscapeXml(string str)
{
  str = Regex.Replace(str, "\"", "&quote;");
  str = Regex.Replace(str, "<", "&lt;");
  str = Regex.Replace(str, ">", "&gt;");
  str = Regex.Replace(str, "&", "&amp;");
  return str;
}

EscapeXml은 XmlElementForRow의 루프 내에서도 호출되므로 잠재적인 병목일 수 있습니다. 여기에 정규식을 대신 사용하기에는 좀 과한 느낌이 있으므로 문자열 Replace 메서드를 사용하겠습니다. EscapeXml을 다음과 같이 대체합니다.

private static string EscapeXml(string str)
{
  str = str.Replace("\"", "&quote;");
  str = str.Replace("<", "&lt;");
  str = str.Replace(">", "&gt;");
  str = str.Replace("&", "&amp;");
  return str;
}

이렇게 수정하면 전체 시간을 약 2초로 줄일 수 있으며 여전이 CPU 시간이 가장 중요한 요인입니다. 이 정도면 만족스러운 결과이며, 실행 시간을 거의 1/7로 줄이는 데 성공했습니다.

독자 여러분들이 연습으로 활용할 수 있도록 ETW 이벤트를 활용해서 식별할 수 있는 몇 가지 성능 버그를 샘플 프로그램에 남겨 두었습니다.

GC 통계 살펴보기

PerfMonitor GC 통계는 메모리 프로필에 대한 간략한 개요를 제공합니다. 기억하겠지만 필자는 메모리 사용 통계를 권장하며 GC ETW 이벤트를 통해 제공되는 정보를 활용하면 .NET GC 힙과 관련된 모든 문제의 간략한 스냅샷을 얻을 수 있습니다. 간단한 요약 뷰에서는 집계 GC 힙 크기, 할당 속도 및 GC 일시 중지 시간을 볼 수 있습니다. PerfMonitor 결과 탭에서 GC Time Analysis(GC 시간 분석) 링크를 선택하면 발생한 시기, 소비한 시간 등과 같은 GC에 대한 상세 정보가 표시됩니다.

이 정보를 통해 CLRProfiler나 다른 메모리 프로파일러로 메모리 문제를 세부적으로 조사해야 하는지 여부를 결정할 수 있습니다. CLRProfiler를 사용하여 .NET GC 힙을 디버깅하는 데 대한 자세한 내용은 “.NET 가비지 수집된 힙 프로파일링”(msdn.microsoft.com/magazine/ee309515) 기사를 참조하십시오.

이 프로그램에서는 GC 통계에서 문제가 될 만한 부분은 보이지 않습니다. 할당 속도는 높으며 기본적인 원칙은 할당 속도를 10MB/s 이하로 유지하라는 것입니다. 반면에 일시 중지 시간은 매우 작습니다. CPU 시간 밑으로 할당 속도가 높게 나타나고 있는데 이것은 대부분 앞에서 확인한 것처럼 CPU 사용에 개선점이 있다는 것을 의미합니다. 그러나 수정 후에도 할당 속도가 높게 유지되고 있는데, 이것은 할당이 많이 수행되고 있다는 의미입니다. 여러분이 수정할 수 있겠습니까? GC 일시 중지 시간이 몇 밀리초라는 것은 자체 튜닝과 .NET Framework 런타임이 제공하는 GC가 효과적이라는 증거입니다. 따라서 .NET Framework GC가 메모리 관리를 자동으로 처리합니다.

JIT 통계 살펴보기

시작 시간을 단축하기 위해 살펴볼 항목 중 하나는 메서드를 JIT 컴파일하는 데 소비되는 시간입니다. 예를 들어 응용 프로그램 시작 시간의 대부분이 JIT 컴파일에 소비되는 경우 어셈블리를 미리 컴파일하고 디스크에 저장하여 JIT 컴파일을 없애는 네이티브 이미지 생성(NGen)으로 응용 프로그램 성능을 개선할 수 있습니다. 즉, 어셈블리를 JIT 컴파일하고 디스크에 저장하므로 이후 실행할 때는 JIT 컴파일을 수행할 필요가 없습니다. 그러나 NGen 방식을 선택하기 전에 일부 메서드의 JIT 컴파일을 지연하여 JIT 컴파일이 프로그램 시작 시간을 늦추지 않도록 하는 방법도 고려할 수 있습니다. 자세한 내용은 “NGen의 성능 이점” (msdn.microsoft.com/magazine/cc163610) 기사를 참조하십시오.

샘플 응용 프로그램 CsvToXml.exe의 시작 비용은 높지 않으며 실행할 때마다 모든 메서드를 JIT 컴파일해도 문제가 되지 않습니다. JIT 컴파일 통계에서는 JIT 컴파일된 메서드가 전체 17개이고(전체 메서드가 JIT 컴파일되었다는 의미), 총 JIT 컴파일 시간이 23ms임을 보여 줍니다. 이 응용 프로그램에서는 이 두 요인이 문제가 아니지만 JIT 컴파일 시간이 영향을 미치는 대규모 응용 프로그램에서는 NGen을 통해 문제를 해결할 수 있습니다. 일반적으로 응용 프로그램이 수백 개에서 수천 개의 메서드를 JIT 컴파일하면 문제가 되기 시작합니다. 이러한 경우 NGen이 JIT 컴파일 비용을 해결하는 솔루션입니다.

다른 MSDN Magazine 기사에서 시작 시간을 개선하는 방법에 대한 지침을 볼 수 있으며 ETW 이벤트로 병목을 확인하고 해결할 수 있습니다. 메서드가 인라인으로 처리되지 않은 이유에 대한 유용한 정보를 제공하는 JIT 인라인 이벤트를 포함하여 몇 가지 다른 JIT 이벤트도 사용할 수 있습니다.

.NET Framework 4의 CLR ETW 이벤트

CLR 팀에서는 DLL 로드를 추적하여 시작 중에 특정 DLL을 로드해야 하는지 여부를 결정하는 데 대한 블로그 게시물을 공개했습니다. DLL 로드를 시작 시에 수행해야 하는지 여부를 결정하는 프로세스는 ETW 이벤트를 통해 더 간단해졌습니다. .NET Framework 4에서 제공되는 ETW Module Load 이벤트를 통해 어떤 모듈이 왜 로드되는지 알 수 있습니다. 물론 모듈 언로드에 대한 이벤트도 있습니다.

이밖에도 .NET Framework 4에는 관리되는 응용 프로그램에 대한 진단을 수월하게 진행할 수 있는 다른 이벤트가 많이 있습니다. 그림 6은 이러한 이벤트를 요약하여 보여 줍니다. PerfMonitor runPrint 명령을 사용하면 실행 중 트리거된 모든 이벤트를 덤프할 수 있습니다. CLR 팀에서는 또한 ETW 프로파일링을 연결 및 분리할 수 있는 이벤트를 제공하며, 향후 릴리스에서 관리되는 응용 프로그램의 디버깅 프로세스를 더욱 간단하게 수행할 수 있는 ETW 이벤트 추가를 계획하고 있습니다.

그림 6 .NET Framework 4의 ETW 이벤트

이벤트 카테고리 이름 설명
런타임 정보 ETW 이벤트 SKU, 버전 번호, 런타임이 활성화된 방법, 시작하는 데 사용된 명령줄 매개 변수, GUID(해당되는 경우) 및 다른 관련 정보를 비롯한 런타임 관련 정보를 캡처합니다.
발생한 예외 ETW 이벤트 발생한 예외에 대한 정보를 캡처합니다.
경합 ETW 이벤트 런타임이 사용하는 모니터 잠금이나 네이티브 잠금의 경합에 대한 정보를 캡처합니다.
스레드 풀 ETW 이벤트 작업자 스레드 풀 및 I/O 스레드 풀에 대한 정보를 캡처합니다.
로더 ETW 이벤트 응용 프로그램 도메인, 어셈블리 및 모듈 로딩 및 언로딩에 대한 정보를 캡처합니다.
메서드 ETW 이벤트 기호 확인을 위한 CLR 메서드에 대한 정보를 캡처합니다.
GC ETW 이벤트 GC에 대한 정보를 캡처합니다.
JIT 추적 ETW 이벤트 JIT 인라인 및 후속 호출에 대한 정보를 캡처합니다.
상호 운용성 ETW 이벤트 MSIL(Microsoft intermediate language) 스텁 생성 및 캐싱에 대한 정보를 캡처합니다.
ARM(Application Domain Resource Monitoring) ETW 이벤트 응용 프로그램 도메인의 상태에 대한 세부적인 진단 정보를 캡처합니다.
보안 ETW 이벤트 강력한 이름 및 Authenticode 확인에 대한 정보를 캡처합니다.
스택 ETW 이벤트 이벤트가 발생한 이후 스택 추적을 생성하기 위해 다른 이벤트와 함께 사용되는 정보를 캡처합니다.

실행 디렉터리에서 PerfMonitorOutput 접미사가 있는 파일 두 개는 ETW 로그 파일입니다. kernel 접미사가 있는 파일들도 볼 수 있는데 이러한 파일에는 OS 이벤트가 포함되어 있습니다. PerfMonitor가 수집하는 데이터는 XPerf가 사용하는 데이터와 동일하므로 PerfMonitor를 사용하여 데이터 수집을 간소화하고 XPerf를 사용하여 동일한 데이터를 더 세부적으로 분석할 수 있습니다. PerfMonitor merge 명령은 ETW 파일을 XPerf에서 읽을 수 있는 형식으로 변환합니다.

요약

ETW를 사용한 성능 조사는 간단하면서도 강력합니다. 관리되는 코드를 효과적으로 디버깅할 수 있는 무료이고 오버헤드가 낮은 ETW 기반 도구가 많이 있습니다. 여기에서는 .NET Framework 런타임에서 사용할 수 있는 ETW 이벤트에 대해 간략하게 소개했습니다. 이 기사의 목표는 ETW 이벤트와 도구를 사용해서 관리되는 응용 프로그램의 디버깅을 시작하는 방법을 알아보는 것입니다. PerfMonitor를 다운로드하고 CLR의 ETW 이벤트에 대한 MSDN 설명서를 사용하면 CLR Perf 블로그와 함께 관리되는 응용 프로그램의 성능 조사를 시작하는 데 충분할 것입니다.

이 기사를 위한 안내와 지원을 제공해 준 CLR Performance 파트너 아키텍처인 Vance Morrison에게 감사 인사를 전합니다.

Subramanian Ramaswamy는 Microsoft에서 CLR Performance 프로그램 관리자로 근무하고 있으며, 조지아공과대학교에서 전자 및 컴퓨터 공학 학위를 취득했습니다.