변경 내역
-
2006.07.30 작성.
이 글은 월간 마이크로소프트웨어(일명 마소) 2006년 7월호 프로그래밍 노트 칼럼에 기고한 글입니다. 물론 구성이나 내용 상의 차이가 있을 수 있습니다.
2년 전쯤 필자는 Microsoft SQL Server 2000에 부쩍 관심을 갖고 있었다. 그래서 책을 사서 읽고 데이터베이스 전문 잡지를 구독했는데, 그때마다 저자들의 내공에 깜짝깜짝 놀라고는 했다. 오픈 소스 데이터베이스도 아닌데 내부 구현에 관해 언급하거나, 문서화 되어 있지 않은 기능을 알려주거나 했기 때문이다. 필자는 줄곧 그 점에 의문을 품고 있었다.
그러던 어느 날 SQL Server 전문가로 유명한 정원혁씨의 성능 튜닝 세미나에 참석하게 됐다. 강의 내용도 재미있었지만 필자는 강사의 시범에서 더 놀라운 발견을 할 수 있었다. SQL Server의 내부 이벤트를 잡아낼 수 있는 프로필러를 열어놓고, 관리 도구인 엔터프라이즈 매니저에서 이런저런 작업을 했던 것이다. 예전에는 아이콘을 클릭하면 데이터베이스의 테이블 목록이 나온다는 것을 당연하게 받아들였었다. 그런데 프로필러에는 아이콘 속에 감춰진 쿼리문이 드러나 있었다. 그 순간 필자는 전문가들의 노하우 중 하나를 들여다 봤다는 사실을 깨달았다.
문제의 해결책을 찾는 것은 쉽다. 구글에서 열심히 검색하면 웬만한 문제는 해결된다. 누군가 똑 같은 경험을 이미 해봤기 때문이다. 그러나 한 시간을 넘게 검색해도 문제의 실마리조차 보이지 않는 경우가 있다. 특히 느려터진 어플리케이션을 손 보는 일만큼 골치 아픈 일도 없다. 문자열의 + 연산이 성능을 저하시킬 수 있다는 사실을 안다고 해도, 그것이 현재 상황을 일으킨 주범이 아닐 수도 있다. 그것 외에도 성능을 저하시킬 수 있는 요인은 얼마든지 있다. 그래서 추측을 하기 시작한다. "IOCP로 구현하면 더 빠르다고 하더라”라는 말에 프로그램을 뜯어고친다. 몇 주간 고생해서 IOCP를 구현했다. 그러나 테스트를 해 보니 그다지 나아진 점이 없다. 몇 번의 시행착오를 더 거친 후에야 데이터베이스 테이블에 인덱스가 잘못 잡혀 있었음이 드러난다.
필자는 지난 2차례의 기사에서 문자열 조작과 관련된 성능 문제를 다뤘다. 그러나 이런 단편적인 지식만으로는 독자가 스스로 미지의 문제를 해결해 나가기 힘들 수도 있다는 생각이 들었다. 그래서 이번 시간에는 사막 한가운데에서부터 방향을 잡고 빠져나올 수 있는 방법을 제시하려 한다.
다양한 성능 분석 도구를 살펴보자.
SQL Server에 프로필러가 있듯이, .NET Framework에도 어플리케이션의 성능을 분석할 수 있는 프로필러가 있다. 필자는 다음과 같은 프로필러를 주로 사용한다. 모두 별도의 비용 없이 마음껏 사용할 수 있는 유용한 도구이다.
-
CLR Profiler
.NET Framework 1.1과 2.0을 모두 지원한다. 윈도우 서비스나 ASP.NET 웹 어플리케이션도 분석할 수 있다는 것이 가장 큰 장점이다. 이번 기사에서 집중적으로 다루게 될 도구이다.
-
DevPartner Studio .NET Profiler Community Edition
메모리 뿐만 아니라 실행시간도 한번에 분석한다. Visual Studio .NET 2002/2003과 통합된 환경이 장점이다. 다만 .NET Framework 1.1만 지원한다는 점이 아쉽다.
프로필러가 유일한 성능 분석 도구는 아니다. 역 공학이 적용된 Disassembler로 System.String의 내부 구현을 살펴본다던가, 프로필러로 성능 분석을 할 수 없는 상용 서버의 환경을 성능 카운터로 관찰할 수도 있다. 또한 .NET Framework Class Library (FCL)에 내장된 기능을 사용해서 직접 분석 도구를 작성할 수도 있다.
XML 직렬화 예제 (ConsoleApplication1.exe)
지난 시간에는 서로 다른 XML 직렬화 코드의 성능을 비교해 봤다. 당시 필자는 각각의 경우에 대해 프로파일링 결과를 제시했다. 하지만 기사의 목적이 문자열 처리와 관련된 성능 이슈를 살펴보는 것이었기 때문에 그러한 결과를 얻어낸 과정에 대해서는 언급하지 않았다. 이번에는 최악의 성능을 보여주었던 첫 번째 경우를 프로파일링해 볼 것이다.
지난 기사를 읽지 못한 독자를 위해 다시 한번 <리스트 2>에 일부 소스코드를 적었다. Customer::BuildXml() 메써드를 실행시키면 Customer 객체의 멤버 변수 값을 XML 문자열로 출력한다. 이때 문자열 생성을 위해 System.Text.StringBuilder를 사용하지 않고 단순하게 + 연산(String::Concat)을 했다. 앞으로 기사에 등장하게 될 ConsoleApplication1.exe는 Customer::BuildXml() 메써드를 매개변수로 넘겨 받은 회수만큼 반복 호출하는 콘솔 어플리케이션이다.
<리스트 2> XML 직렬화 예제
public class Customer
{
public string Name;
public Address[] Address;
public string BuildXml()
{
string xmlStr = string.Empty;
xmlStr += "<?xml version=\"1.0\" encoding=\"utf-16\"?>" + Environment.NewLine;
xmlStr += "<Customer xmlns:xsd=\"http://www.w3.org/2001/XMLSchema\" xmlns:xsi=\"http://www.w3.org/2001/XMLSchema-instance\" xmlns=\"http://example\">" + Environment.NewLine;
xmlStr += " <Name>" + Name + "</Name>" + Environment.NewLine;
foreach(Address address in Address)
{
xmlStr += address.BuildXml() + Environment.NewLine;;
}
xmlStr += "</Customer>" + Environment.NewLine;;
return xmlStr;
}
}
////////////////////////////////////////////////////////////////////////////////////
class Program
{
[STAThread]
static void Main(string[] args)
{
if(args == null || args.Length < 1)
{
Console.WriteLine("iteration needed!");
return;
}
int iterations = int.Parse(args[0]);
Customer customer1 = CreateCustomerInstance();
for(int i=0; i<iterations; i++)
{
string xmlStr = customer1.BuildXml();
}
}
}
CLR Profiler를 설치하자.
우선 CLR Profiler를 다운로드 받자. .NET Framework 1.1을 위한 프로필러는 CLR Profiler (v1.1)에서, 그리고 2.0을 지원하는 프로필러는 CLR Profiler for the .NET Framework 2.0에서 구할 수 있다. 사용 상의 큰 차이점은 없으므로 여기서는 2.0 CLR Profiler를 기준으로 진행하려 한다. 혹시나 하는 마음에 미리 말해두자면, 1.1 환경에서 컴파일한 어플리케이션을 2.0 프로필러로 프로파일링하려고 시도하면 오류가 발생한다.
물론 반대의 경우도 마찬가지다. 문제는 "이 어플리케이션은 .NET Framework 1.1 환경에서 빌드 되었습니다.”와 같이 친절한 설명을 보여주지 않는다는 점이다. 필자가 테스트를 위해 1.1 환경에서 빌드한 간단한 콘솔 어플리케이션을 2.0 CLR Profiler로 프로파일링했을 때 다음과 같은 오류 메시지가 발생했다. 어디에도 CLR (Common Language Runtime) 버전에 관한 이야기는 없다. 만약 프로필러가 작동하지 않고, 원인을 전혀 짐작할 수 없다면 CLR Profiler의 버전과 프로파일링할 어셈블리 파일의 CLR 버전이 일치하는지 여부부터 점검해봐야 한다.
<리스트 1> 오류 메시지
이 대화 상자 대신 JIT(Just-in-time) 디버깅을 호출하는 방법에 대한 자세한 내용은 이 메시지의 뒷부분을 참조하십시오. ************** 예외 텍스트 ************** System.NullReferenceException: 개체 참조가 개체의 인스턴스로 설정되지 않았습니다. 위치: CLRProfiler.MainForm.WaitForProcessToConnect(String tempDir, String text) 위치: CLRProfiler.MainForm.startApplicationButton_Click(Object sender, EventArgs e) 하략…….
CLR Profiler 설치 폴더에 가면 CLRProfiler.doc 문서가 있다. 영문 문서를 읽는데 애로 사항이 없다면 한번쯤 읽어보기 바란다. 필자가 미처 설명해 주지 못한 부분을 익힐 수 있을 것이다. 100여 페이지에 달하는 분량이 부담스러울 수 있지만, 투자한 것 이상을 돌려 받을 수 있다.
CLR Profiler를 돌려보자.
<화면 1> CLR Profiler
Binaries 폴더 안의 CLRProfiler.exe를 실행시켜 보자. 솔직히 CLR Profiler의 외형(<화면 1>)은 전혀 믿음직스럽지 못하다. VS.NET의 유려한 유저 인터페이스와 비교하면 만들다가 만 것 같을 정도다. 하지만 겉모습과는 달리 내실은 튼튼하다. <리스트 2>는 지난 기사에서 제시한 예제 중 일부이다. + 연산, 즉 String::Concat 메써드로 객체의 XML 직렬화를 구현했다. ConsoleApplication1.exe는 Customer::BuildXml을 지정된 회수만큼 반복 실행한다. 이 어플리케이션은 문자열의 생성 실행 회수를 다음과 같이 명령창에서 매개변수로 입력 받는다.
ConsoleApplication1.exe 100000
File/Set Parameters 메뉴를 열어보자. Enter Command Line 텍스트 박스에 매개변수 100000을 입력한다. Set Parameters 메뉴를 자세히 보면 매개변수 외에도 작업 디렉토리(Working Directory)도 설정할 수 있다.
]
이제 File/Profiler Application 메뉴를 열어서 프로파일링할 실행 파일, 이 경우에는 ConsoleApplication1.exe를 선택한다. 파일 탐색기에서 파일을 선택함과 동시에 실행 및 분석 작업이 시작된다. 나중에 좀더 알아보겠지만, File/Profiler Application은 콘솔 및 윈도우 폼 어플리케이션을, Profile Service는 윈도우 서비스(관리도구/서비스 메뉴에서 볼 수 있다.)를, 그리고 Profile ASP.NET은 웹 어플리케이션을 각각 프로파일링한다.
어플리케이션의 실행과 프로파일링 작업이 종료되면 <화면 2>과 같이 결과가 표시된다. 결과가 출력되기까지의 시간이 매우 길게 느껴질 수도 있다. CLR Profiler는 어플리케이션의 성능에 막대한 영향을 미치기 때문에 원래보다 수십 내지는 수백 배 이상 실행시간이 길어질 수 있다. 필자는 ASP.NET 어플리케이션이 수십만 건의 요청을 처리하는 경우를 프로파일링해 본 적이 있다. 저녁 식사를 마치고, 케이블 TV에서 인기 있는 범죄 수사물을 한편 보고 돌아왔을 때 여전히 멈추지 않고 있는 프로필러를 보고 좌절한 적이 있다.
메모.
성능분석 도구가 어플리케이션의 실행 속도를 수십 배나 늦춘다는 것은 언뜻 이해가 안 될 수 있다. 프로필러는 크게 메모리/CPU 분석용으로 나뉜다. 개발하다 보면 소스 코드 중간간에 FCL의 System.DateTime 객체나 C의 time 함수를 넣어서 구간별 실행시간을 재는 경우가 많다. CPU 프로필러는 그와 똑같은 방식으로 작동하고, 앞서 소개한 DevPartner Studio .NET Profiler가 이 분류에 속한다.
CLR Profiler는 이와는 달리 철저하게 CLR 환경의 메모리 운용을 모니터링하는 것에 집중한다. CPU 프로필러처럼 구간별 실행시간을 비교하는 대신, 어떤 객체가 가장 시스템에 부하를 많이 주는지, 그리고 그 객체가 생성되는 구간은 어디인지를 알아낸다. 시스템/어플리케이션 성능은 메모리 및 자원 관리에 영향을 많이 받는다. 그러므로 이렇게 분석된 부분을 집중적으로 개선하면, 적은 노력으로 최대의 효과를 볼 수 있다.
<화면 2> Summary
관리되는 힙(Managed Heap)과 가비지 콜렉터(Garbage Collector)에 대해 알아보자.
CLR Profiler는 CLR의 메모리 운용 상태를 모니터링하고, 호출 트리, 메모리 할당 등의 상태를 그래프로 화려하게 보여준다. 그래서 별 것도 아닌 듯이 보일 수도 있지만, 프로파일링 결과를 정확하게 분석하기 위해서는 CLR, 그 중에서도 가비지 콜렉터 (Garbage Collector)의 메모리 할당 및 수거 방식에 대해 상세히 알고 있어야 한다. 그러므로 ConsoleApplication1.exe의 프로파일링 결과를 분석하기에 앞서 가비지 콜렉터에 대해 간략히 알아보도록 하자.
<리스트 4> 가비지 콜렉터의 상태 변화
<리스트 4>는 CLR의 메모리 관리 방식을 보여준다. CLR은 어플리케이션을 위해 연속적인 메모리 공간을 미리 확보해 놓는다. 그리고 새로운 객체가 생성될 때마다, 즉 new 키워드를 사용할 때마다 뒤쪽의 비어있는 메모리 영역을 부여한다. 동적 할당을 할 때마다 객체 생성에 충분한 메모리 영역을 찾기 위해 링크드 리스트를 뒤져야 하는 C/C++ 환경과는 상당히 다르다.
가용 메모리 영역이 남아 있는 한 별다른 작업 없이 객체가 계속 생성된다. C/C++에서는 사용자가 delete 키워드로 힙 공간의 반환을 명시하지만, 관리되는 환경에서는 사용자가 특정 객체의 메모리 반환을 지시할 수 없다. 그러다가 어느 시점에 이르러 새로운 객체 생성에 필요한 메모리 영역이 부족하게 된다. (<리스트 4> – ①) 이제 가비지 콜렉터가 나설 차례다. 가비지 콜렉터는 우선 필요 없어진 객체와 아직 유효한 객체를 구분한다. ((<리스트 4> – ②) 그리고 유효한 객체만 memcpy로 메모리 영역 앞쪽으로 복사해 놓는다. (<리스트 4> – ③)
<리스트 4>는 상황을 매우 간략하게 묘사하고 있다. 실제로는 한 줄짜리 어플리케이션을 실행시키는 데도 수십 개의 객체가 생성된다. 현실에서는 상호 참조, 소켓 등의 관리되지 않는 자원 해제 등의 문제가 얽혀 있다. 그래서 가비지 수집에 소요되는 시간과 자원이 만만치 않게 된다. 그러므로 성능 향상을 위한 최선의 방법은 가비지 수집의 회수를 줄이고, 자원 해제(Finalization)의 필요성을 줄이는 것이다.
부족한 감이 있지만 일단 이야기 진행에 필요한 만큼 CLR의 메모리 운용 방식에 대해 알아봤다. 앞으로 기회가 있을 때마다 못 다한 설명을 마저 할 생각이다. 하지만 이 기사의 주제는 어디까지나 성능 분석이지 가비지 콜렉터가 아니다. 그러므로 간략하게 설명하고 넘어가거나 아예 언급조차 않는 사항이 있을 수 있다. 만약 가비지 콜렉터에 대해 자세히 알고 싶다면 참고 문헌을 꼭 읽어보기 바란다.
CLR Profiler의 결과를 분석해보자.
<리스트 3> 프로파일링 요약
Allocated bytes: 867,019,216 Relocated bytes: 7,569,048 Final Heap bytes: 244,400 Objects finalized: 0 Critical objects finalized: 0 Gen 0 collections: 3,305 Gen 1 collections: 0 Gen 2 collections: 0 Induced collections: 0 Gen 0 Heap bytes: 264,987 Gen 1 Heap bytes: 17,976 Gen 2 Heap bytes: 12 Large Object Heap bytes: 8,784 Handles created: 27 Handles destroyed: 0 Handles surviving: 27 Heap Dumps: 0 Comments: 0
<리스트 3>는 ConsoleApplication1.exe의 프로파일링 결과이다. 이 요약결과를 보면ConsoleApplication1.exe의 생명주기 동안 총 867,019,216바이트의 메모리가 할당됐다. 그이 프로그램이 실행되려면 로컬 컴퓨터의 메모리가 867 메가바이트나 있어야 한다는 뜻은 아니다. 생명주기 동안 몇 번(여기서는 3,305회)이나 가비지 콜렉터가 필요 없어진 객체를 수거해 가기 때문이다.
테스트가 진행된 필자의 컴퓨터에서는 사용 가능한 메모리가 약 400메가바이트 정도였다. 그러나 멀티 태스킹 환경이니만큼 한 어플리케이션 도메인이 모든 가용 메모리를 차지해서는 안 된다. CLR이 ConsoleApplication1.exe 어플리케이션 도메인을 위해 배당한 메모리는 Gen n Heap bytes와 Large Object Heap bytes의 합으로 생각할 수 있다. 각각의 수치는 어플리케이션 생명주기 동안의 평균값이다. 즉 264,987 + 17,976 + 12 + 8,784 = 291,759 바이트의 메모리로 867,019,216 바이트의 객체를 생성하고 파괴한 것이다. 단순한 계산으로는 최소한 867,019,216 / 291,759 = (약) 2970회의 가비지 수집이 일어났을 것임을 알 수 있다. 실제로 Gen n collections 값은 3,305회나 가비지 수집이 이뤄졌다는 것을 알려준다.
<화면 3> Objects by Address
View/Objects by Address 메뉴(<화면 3>)를 선택하면 특정 순간, 기본적으로는 프로그램 종료 시점의 관리되는 힙의 상태를 보여준다. 앞서 살펴본 <리스트 4>와 비슷하다. 왼쪽 그래프가 일반적인 객체 생성을 위해 사용되는 관리되는 힙이다. 그래프 오른쪽에 조그맣게 gen 0, gen 1이라고 표시되어 있다. 일반적인 어플리케이션은 gen 2 영역도 갖기 마련이지만 ConsoleApplication1.exe는 문자열만 생성하는 간단한 테스트 프로그램이라 gen 2 영역이 생성될 기회가 없었다.
ConsoleApplication1.exe의 프로파일링 요약 정보에서 가장 주목해야 할 부분은 Allocated bytes, Relocated bytes, 그리고 Gen 0 collections이다. 값이 0이 아닌 항목 중에서는 이 세 개가 중요한 의미를 담고 있다. Allocated bytes와 Gen n collections는 앞서 살펴봤다. Relocated bytes는 가비지 콜렉터가 memcpy로 위치를 옮긴 객체의 크기이다. 가비지 수집에서 살아남은 객체는 메모리 영역 앞쪽으로 복사됨을 보았다. 몇몇 예외적인 경우에는 살아남은 객체가 복사되지 않고, 원래 자리에 남아있기도 한다. 그러므로 Relocated bytes를 가비지 수집에서 살아 남아 다음 세대로 격상된 객체의 크기라고 보아도 무방하다.
요약 정보를 종합해 보면 ConsoleApplication1.exe는 메모리 소모적 어플리케이션이다. Customer::BuildXml() 메써드를 10000번 호출하는데 무려 867 메가바이트나 필요하다. 그래서 관리되는 힙(xxx Heap bytes)이 금방 꽉 차게 된다. 이에 따라 가비지 수집이 자주 발생하게 되고 성능이 저하되는 것이다. 시간당 트랜잭션이 100만 건인 XML 웹 서비스에서 이런 일이 발생하면, ConsoleApplication1.exe와 상용 웹 서비스 어플리케이션의 복잡도를 감안하면 서비스 자체가 불가능할 수 있다는 결론이 나온다.
다만 Relocated bytes/Allocated bytes의 값(8%)이 작다는 사실은 양호하다고 봐야 한다. 생성된 객체 중 극히 일부분만 다음 세대까지 살아남는다면, 그만큼 memcpy로 복사하는 노력이 적게 들기 때문이다. ConsoleApplication1.exe에서 생성되는 XML 문자열은 for 문 영역 안에서만 참조가 유효하기 때문에 이런 결과가 나온 것이다.
<화면 4> Time Line
<리스트 5> Time Line 그래프 읽기
수평축에 작은 글씨로 gc #1, gc #2라고 적혀 있다. 이것은 가비지 수집이 일어난 시점을 알리고 있고, 그래프의 높이가 급격히 줄어드는 시점과 정확히 일치한다. #n은 어플리케이션의 생명주기 내에서 몇 번째 발생한 가비지 수집인지를 알려준다. 같은 시간 내에서라면 #n 값이 적을수록 성능 향상에 도움이 된다는 것은 강조할 필요조차 없다.
<화면 4>에서는 모든 gc #n 글자가 붉은 색이다. 붉은 색 글자는 1세대 영역에 대한 가비지 수집 작업을 뜻한다. 2세대 영역과 3세대 영역에 대한 각각 녹색과 파란색으로 표시된다. 다음 기회에 자세히 알아보겠지만 n 세대 영역에 대한 가비지 수집은 k ( k <= n ) 세대 모두에 대해 메모리 수거를 하기 때문에, 2세대는 1세대보다 그리고 1세대는 0세대의 경우보다 느리다.
<화면 4>의 Time Line 그래프(메뉴: View/Time Line)는 앞서의 분석을 한눈에 알기 쉽게 보여준다. 최초 구간(0.0 sec ~ 0.4 sec)에서는 메모리 요구량이 매우 적다. 어플리케이션의 초기화 구간이다. 다음 구간부터는 그래프가 송곳처럼 날카로운 경사를 보인다. 0.45 sec ~ 0.5 sec 사이에 약 4차례의 가비지 수집이 이뤄졌다. 전체 실행시간 중에 가비지 수집이 차지하는 비율이 매우 높아서 어플리케이션의 본래 임무에 투자되어야 할 귀중한 자원이 낭비되고 있는 상황이다.
이상적인 어플리케이션이라면 Time Line 그래프는 <화면 5>와 같을 것이다. <화면 5>는 완만한 메모리 사용 증가율을 보인다. 전체 실행시간 중 가비지 수행이 차지하는 비중은 매우 작다. 0.1 sec에 10여 차례나 가비지 수집을 했던 <화면 4>에 비해, <화면 5>는 1.5 sec에 한 차례 정도밖에 가비지 수집을 하지 않는다. <화면 5>에서 한 차례 가비지 수집을 하는 동안, <화면 4>에서는 무려 150차례나 하는 꼴이다.
<화면 5> 이상적인 Time Line 그래프
글을 접으며
이번 기사에서는 수많은 성능 분석 도구 중에서 CLR Profiler를 선택하여 기본적인 사용법에 대해 알아봤다. 또한 가비지 콜렉터의 동작 방식도 살짝 들여다 봤다. 프로필러를 처음 접하는 개발자에겐 약간 어려운 내용이었을지도 모르고, 성능분석을 여러 차례 해본 중급 개발자에겐 너무 쉬운 이야기였을 것이다. 만약 독자가 CLR Profiler를 처음 접한다면 반드시 기사의 내용을 실습해보고, 기사나 참고 문헌을 한번씩 읽고 숙지하기를 간절히 바란다. 다음 기사에서는 성능분석 문제를 보다 깊이 파헤칠 것이기 때문이다.
남기는 말
기사 내용 중 이해가 안 되는 내용이 있다면 필자의 이메일이나 블로그로 문의해주기 바란다. 필자의 취미는 질문에 대답하는 것이다.
참고 문헌
-
Garbage Collection: Automatic Memory Management in the Microsoft .NET Framework, Jeffrey Richter
-
How To: Use CLR Profiler, J.D. Meier, Srinath Vasireddy, Ashish Babbar, and Alex Mackman
-
마이크로소프트웨어 2004년 10월호 닷넷 칼럼 – Back to the Basic: .NET Garbage Collection 돌아보기, 유경상
