성능 측정 - 추측하지 않고 재기

이 장에서 배우는 것

코드가 느리다는 느낌은 자주 틀린다. 이 장은 느낌 대신 숫자로 판단하는 방법을 다룬다. 먼저 Stopwatch 로 시간을 재는 요령을 익힌다. 이어서 문자열 연결과 StringBuilder, 컬렉션 종류에 따른 조회 비용을 직접 측정한다. 마지막으로 전문 도구인 BenchmarkDotNet 과 dotnet-counters 가 어떤 문제를 풀어 주는지 소개한다.

• Stopwatch 측정에서 워밍업, 반복, 최솟값 채택이 필요한 이유를 설명할 수 있다.
• 시간 대신 할당 바이트로 두 구현을 비교하는 방법을 안다.
• 반복문 안의 += 문자열 연결이 왜 느려지는지, StringBuilder 가 무엇을 바꾸는지 설명할 수 있다.
• List<T>, Dictionary<TKey, TValue>, HashSet<T> 의 조회 비용 차이를 측정으로 확인할 수 있다.
• BenchmarkDotNet 과 dotnet-counters 를 언제 꺼내 쓰는지 구분할 수 있다.

문제 상황

택배 물류 센터의 분류 서비스가 오후 피크 시간대에 느려진다는 제보가 들어왔다. 팀 회의에서 의견이 갈린다. 한 명은 운송장 목록을 문자열 하나로 이어 붙이는 코드가 원인이라고 하고, 다른 한 명은 송장 번호로 택배를 찾는 List 검색이 원인이라고 한다. 둘 다 그럴듯하지만 근거는 없다.

이런 상황에서 추측대로 코드를 고치면 세 가지 일이 생긴다. 실제 병목이 아닌 곳을 고쳐 코드만 복잡해지고, 고친 뒤에도 빨라졌는지 알 수 없다. 더 나쁜 경우에는 오히려 느려진다. 그래서 고치기 전에 재고, 고친 뒤에 다시 재는 순서를 지켜야 한다.

이 장의 예제는 두 가지 의심 지점을 작은 프로그램으로 옮겨 재 본다. 하나는 문자열 3000개 조각을 이어 붙이는 작업이고, 다른 하나는 택배 5000건 중에서 2000번 조회하는 작업이다.

Stopwatch 로 제대로 재기

Stopwatch 는 System.Diagnostics 네임스페이스의 고해상도 타이머다. Stopwatch.StartNew() 로 시작하고 Elapsed 로 경과 시간을 읽는다. 사용법은 간단하지만 결과를 믿을 만하게 만들려면 몇 가지 요령이 필요하다.

한 번 재면 안 되는 이유

첫 실행에는 측정하려는 코드 외의 비용이 섞인다. JIT 컴파일러가 메서드를 처음 기계어로 바꾸는 시간, CPU 캐시가 비어 있는 상태, 그 순간 돌던 다른 프로세스의 영향이 그렇다. 그래서 측정 절차는 다음과 같이 잡는다.

1. 워밍업으로 한 번 실행해 JIT 와 캐시 비용을 먼저 치른다.
2. 같은 작업을 여러 번 반복해 각각 시간을 잰다.
3. 평균 대신 최솟값(또는 중앙값)을 본다. 측정 잡음은 시간을 늘리기만 하고 줄이지는 않기 때문이다.

빌드 구성과 결과 사용

dotnet run 의 기본 구성은 Debug 다. Debug 빌드는 최적화가 꺼져 있어 실제 배포 성능과 차이가 크다. 시간을 비교할 때는 dotnet run -c Release 로 돌린다. 또 측정 대상 코드의 결과를 어디에도 쓰지 않으면 컴파일러가 작업을 줄여 버릴 수 있다. 예제처럼 결과를 반환해 받아 두면 이를 막을 수 있다.

시간 측정에는 Stopwatch.GetTimestamp() 와 Stopwatch.GetElapsedTime(start) 조합도 쓸 수 있다. 객체를 만들지 않으므로 측정 자체가 할당을 일으키지 않는다.

시간 말고 할당도 잰다

시간은 기계 상태에 따라 흔들리지만 할당 바이트는 훨씬 안정적이다. GC.GetAllocatedBytesForCurrentThread() 는 현재 스레드가 지금까지 힙에 할당한 누적 바이트를 돌려준다. 작업 전후의 차이를 구하면 그 작업의 할당량이 된다. 이 값은 두 구현 사이에 차이가 크면 매번 같은 방향으로 나오므로 비교와 검증에 쓰기 좋다. 할당이 성능에 주는 영향은 메모리와 GC 를 다룬 앞선 장에서 본 내용과 이어진다.

문자열 연결과 StringBuilder

string 은 불변이다. 그래서 s += "조각" 은 기존 문자열을 고치지 않고, 두 내용을 합친 새 문자열을 만들어 s 에 다시 넣는다. 길이가 L 인 문자열에 조각을 붙일 때마다 L 글자를 복사한다. 조각이 n 개면 복사량이 대략 n 의 제곱에 비례해 늘어난다.

StringBuilder 는 내부에 글자 버퍼를 두고 Append 로 뒤에 이어 쓴다. 버퍼가 차면 새 조각(chunk)을 붙여 나가므로 이미 쓴 글자를 매번 복사하지 않는다. 마지막에 ToString() 을 한 번 호출할 때만 전체 문자열이 만들어진다.

모든 연결에 StringBuilder 가 필요한 것은 아니다. 한 식 안의 a + b + c 나 보간 문자열($"{a}-{b}")은 조각 수가 코드에 고정되어 있어 한 번의 연결로 처리된다. 문제가 되는 것은 조각 수가 데이터 크기에 따라 늘어나는 반복문 안의 연결이다. 조각이 이미 컬렉션에 있다면 string.Join 도 좋은 선택이다.

컬렉션 선택 비용

송장 번호로 택배를 찾는 일에서 컬렉션 선택은 조회 비용을 정한다. 세 가지를 비교한다.

조회에 쓰는 컬렉션의 비용 차이

컬렉션	조회 방식	조회 비용	적합한 경우
List<T>	Find, Contains	원소 수에 비례	순서 유지, 적은 원소, 드문 조회
Dictionary<TKey, TValue>	TryGetValue	평균적으로 일정	키로 값을 자주 찾을 때
HashSet<T>	Contains	평균적으로 일정	존재 여부만 확인할 때

해시 기반 컬렉션은 만들 때 해시 테이블을 구성하는 비용과 메모리를 더 쓴다. 원소가 수십 개 이하이고 조회가 드물면 List 가 더 나을 수도 있다. 따라서 "해시가 항상 빠르다"가 아니라 "조회 횟수와 원소 수가 커지면 차이가 벌어진다"로 이해하고, 실제 크기로 재어 확인한다.

전문 도구 소개

Stopwatch 로 직접 만든 측정 코드는 워밍업과 반복을 스스로 챙겨야 한다. 이를 대신해 주는 도구가 있다.

측정 도구별 용도

도구	무엇을 재는가	언제 쓰는가	준비물
Stopwatch	코드 구간의 경과 시간	빠른 확인, 로그에 남기는 구간 시간	BCL 만 필요
BenchmarkDotNet	메서드 단위의 시간·할당 통계	두 구현을 엄밀히 비교할 때	NuGet 패키지, Release 빌드
dotnet-counters	실행 중 프로세스의 GC·할당률·CPU 추이	운영 중 서비스 관찰	전역 도구 설치

BenchmarkDotNet 은 측정할 메서드에 [Benchmark] 특성(attribute)을 붙이고 BenchmarkRunner.Run<T>() 로 실행한다. 워밍업, 반복 횟수 결정, 통계 처리를 알아서 하고, [MemoryDiagnoser] 를 붙이면 할당량도 보여 준다. 외부 패키지이므로 이 책의 예제에서는 쓰지 않고, 공식 사이트에서 사용법을 확인하면 된다.

dotnet-counters 는 코드를 바꾸지 않고 돌아가는 프로세스를 들여다본다. 설치와 사용의 기본 흐름은 아래와 같다.

dotnet tool install --global dotnet-counters
dotnet-counters ps
dotnet-counters monitor --process-id <PID> --counters System.Runtime

첫 줄은 설치, 둘째 줄은 대상 프로세스 번호 조회, 셋째 줄은 System.Runtime 카운터 묶음의 실시간 출력이다. 이 묶음에는 GC 힙 크기, 세대별 GC 횟수, 할당률, CPU 사용률 같은 값이 들어 있다. 피크 시간대에 할당률이 치솟는지 같은 질문에 먼저 답한 뒤, 의심 구간만 Stopwatch 나 BenchmarkDotNet 으로 파고드는 순서가 효율적이다. 자세한 옵션은 dotnet-counters 문서에 있다.

완성 코드

아래 프로그램은 두 의심 지점을 측정한다. 출력이 실행마다 같아야 하므로 기본 실행에서는 시간을 출력하지 않고 결과 값과 할당량 비교만 출력한다. --time 인자를 주면 측정한 시간도 볼 수 있다.

using System.Diagnostics;
using System.Text;

bool showTime = args.Contains("--time");

const int ParcelCount = 5000;
var parcels = new List<Parcel>(ParcelCount);
for (int i = 1; i <= ParcelCount; i++)
{
    parcels.Add(new Parcel(i, "Z" + (i % 50)));
}

var lookupIds = new int[2000];
for (int i = 0; i < lookupIds.Length; i++)
{
    lookupIds[i] = i * 3 + 1;
}

Console.WriteLine("측정 대상: 문자열 3000개 조각 이어 붙이기");
var concat = Bench.Measure(() => BuildByConcat(3000).Length, 5);
var viaBuilder = Bench.Measure(() => BuildByBuilder(3000).Length, 5);
Console.WriteLine($"문자열 길이: 연결 {concat.Result}, 빌더 {viaBuilder.Result}");
Console.WriteLine($"결과 동일: {concat.Result == viaBuilder.Result}");
Console.WriteLine($"연결 할당이 빌더의 10배 이상: {concat.Allocated >= viaBuilder.Allocated * 10}");

Console.WriteLine("측정 대상: 택배 5000건에서 2000번 조회");
var byId = parcels.ToDictionary(p => p.Id);
var idSet = new HashSet<int>(parcels.Select(p => p.Id));

var listResult = Bench.Measure(() =>
{
    long found = 0;
    foreach (int id in lookupIds)
    {
        if (parcels.Find(p => p.Id == id) is not null)
        {
            found++;
        }
    }
    return found;
}, 5);

var dictResult = Bench.Measure(() =>
{
    long found = 0;
    foreach (int id in lookupIds)
    {
        if (byId.TryGetValue(id, out _))
        {
            found++;
        }
    }
    return found;
}, 5);

var setResult = Bench.Measure(() =>
{
    long found = 0;
    foreach (int id in lookupIds)
    {
        if (idSet.Contains(id))
        {
            found++;
        }
    }
    return found;
}, 5);

Console.WriteLine($"조회 성공 수: List {listResult.Result}, Dictionary {dictResult.Result}, HashSet {setResult.Result}");
bool sameHits = listResult.Result == dictResult.Result && dictResult.Result == setResult.Result;
Console.WriteLine($"세 방식의 결과 일치: {sameHits}");

if (showTime)
{
    PrintTime("문자열 연결", concat.Best);
    PrintTime("StringBuilder", viaBuilder.Best);
    PrintTime("List.Find", listResult.Best);
    PrintTime("Dictionary", dictResult.Best);
    PrintTime("HashSet", setResult.Best);
}
else
{
    Console.WriteLine("시간 값은 실행마다 달라 출력하지 않았다. dotnet run -c Release -- --time 으로 본다.");
}

static string BuildByConcat(int count)
{
    string text = "";
    for (int n = 0; n < count; n++)
    {
        text += $"P{n};";
    }
    return text;
}

static string BuildByBuilder(int count)
{
    var sb = new StringBuilder();
    for (int n = 0; n < count; n++)
    {
        sb.Append('P').Append(n).Append(';');
    }
    return sb.ToString();
}

static void PrintTime(string name, TimeSpan elapsed)
{
    Console.WriteLine($"  {name}: {elapsed.TotalMilliseconds:F3} ms");
}

record Parcel(int Id, string Zone);

static class Bench
{
    public static (long Result, long Allocated, TimeSpan Best) Measure(Func<long> action, int rounds)
    {
        long result = action();

        long before = GC.GetAllocatedBytesForCurrentThread();
        action();
        long allocated = GC.GetAllocatedBytesForCurrentThread() - before;

        TimeSpan best = TimeSpan.MaxValue;
        for (int r = 0; r < rounds; r++)
        {
            long start = Stopwatch.GetTimestamp();
            action();
            TimeSpan elapsed = Stopwatch.GetElapsedTime(start);
            if (elapsed < best)
            {
                best = elapsed;
            }
        }

        return (result, allocated, best);
    }
}

줄별 해설

데이터 준비. 택배 5000건을 만들고 구역 이름은 Z0 부터 Z49 까지 돌려 가며 붙인다. 조회할 송장 번호는 i * 3 + 1 로 1, 4, 7, ... 5998 까지 2000개다. 5000 을 넘는 번호는 존재하지 않는 택배이므로 조회가 실패한다. 성공하는 번호는 i 가 0 부터 1666 일 때의 1667개다.

Bench.Measure. 첫 action() 호출이 워밍업이며 반환값을 result 에 받아 둔다. 두 번째 호출은 할당량을 재는 용도로, 전후의 GC.GetAllocatedBytesForCurrentThread() 차이를 구한다. 이어지는 반복문에서 rounds 번 시간을 재고 가장 작은 값을 남긴다. 튜플로 결과, 할당량, 최소 시간을 한꺼번에 돌려주므로 호출하는 쪽은 필요한 값만 꺼내 쓴다.

문자열 비교. BuildByConcat 은 반복문 안에서 += 를 쓰고, BuildByBuilder 는 같은 내용을 StringBuilder 로 만든다. 결과 길이는 두 방식이 같아야 한다. 조각 P0; 부터 P2999; 까지의 글자 수는 숫자 자릿수 합 10890 에 글자 P 와 ; 를 더한 6000 을 합쳐 16890 이다. 할당량 비교는 "10배 이상"이라는 넉넉한 기준을 썼다. 연결 쪽은 수십 MB 를 할당하고 빌더 쪽은 수백 KB 안쪽이라 이 조건은 안정적으로 참이다.

컬렉션 비교. parcels.Find(p => p.Id == id) 는 리스트를 앞에서부터 훑는다. TryGetValue 와 Contains 는 해시 값으로 바로 위치를 찾는다. 세 방식은 같은 질문에 답하므로 성공 수가 같아야 하고, 마지막 sameHits 로 이를 확인한다. 빠른 코드가 틀린 답을 내면 의미가 없으므로, 결과 일치 검사는 측정과 함께 두는 것이 좋다.

출력 분기. showTime 이 참일 때만 시간을 출력한다. args.Contains 는 LINQ 확장 메서드로, 암시적 using 덕분에 별도 선언 없이 쓴다. 끝의 Parcel 레코드와 Bench 클래스는 최상위 문장 뒤에 둔다.

실행 결과

$ dotnet run
측정 대상: 문자열 3000개 조각 이어 붙이기
문자열 길이: 연결 16890, 빌더 16890
결과 동일: True
연결 할당이 빌더의 10배 이상: True
측정 대상: 택배 5000건에서 2000번 조회
조회 성공 수: List 1667, Dictionary 1667, HashSet 1667
세 방식의 결과 일치: True
시간 값은 실행마다 달라 출력하지 않았다. dotnet run -c Release -- --time 으로 본다.

--time 을 주면 마지막 줄 대신 다섯 줄의 시간이 나온다. 숫자는 기계마다 다르지만, 조각 수나 원소 수가 클수록 List.Find 와 문자열 연결이 다른 쪽보다 크게 느려지는 경향은 같게 나타난다.

실무에서 자주 틀리는 것

한 번 재고 결론 내리기

첫 실행에는 JIT 비용이 섞인다. 아래처럼 한 번만 재면 작업 자체가 아닌 준비 비용을 재게 된다.

// 틀림: 첫 실행 한 번의 시간
var sw = Stopwatch.StartNew();
Run();
sw.Stop();
Console.WriteLine(sw.Elapsed);

// 고침: 워밍업 후 반복해서 최솟값
Run();
var best = TimeSpan.MaxValue;
for (int r = 0; r < 5; r++)
{
    long start = Stopwatch.GetTimestamp();
    Run();
    var elapsed = Stopwatch.GetElapsedTime(start);
    if (elapsed < best) best = elapsed;
}

반복문 안에서 문자열 += 쓰기

조각 수가 입력에 따라 늘어나는 곳에서는 복사량이 제곱으로 자란다.

// 틀림
string manifest = "";
foreach (var p in parcels)
{
    manifest += p.Id + ";";
}

// 고침
var sb = new StringBuilder();
foreach (var p in parcels)
{
    sb.Append(p.Id).Append(';');
}
string manifest = sb.ToString();

Debug 빌드의 시간을 믿기

최적화가 꺼진 빌드에서 잰 시간으로 구현을 비교하면 결론이 뒤집힐 수 있다. 시간 비교는 Release 구성에서 한다.

// 틀림: 기본 구성으로 시간 비교
dotnet run

// 고침: 최적화된 구성으로 비교
dotnet run -c Release -- --time

반복 조회를 List 로 처리하기

같은 목록에서 존재 여부를 수천 번 묻는데 List.Contains 를 쓰면 호출마다 전체를 훑는다.

// 틀림: 조회마다 선형 탐색
foreach (int id in requestedIds)
{
    if (knownIds.Contains(id)) Accept(id);
}

// 고침: 한 번 해시 집합으로 바꾸고 조회
var known = new HashSet<int>(knownIds);
foreach (int id in requestedIds)
{
    if (known.Contains(id)) Accept(id);
}

한눈에 보기

이 장의 핵심 정리

주제	기억할 점	확인 방법
Stopwatch 측정	워밍업 후 반복하고 최솟값을 본다	GetTimestamp, GetElapsedTime
할당 비교	시간보다 흔들림이 적다	GC.GetAllocatedBytesForCurrentThread
문자열 연결	반복문 안 += 는 제곱으로 복사한다	StringBuilder, string.Join
컬렉션 조회	조회가 잦으면 해시 기반을 쓴다	실제 크기로 측정
전문 도구	BenchmarkDotNet 은 비교, dotnet-counters 는 관찰	Release 빌드, monitor

연습 문제

1. 완성 코드의 Bench.Measure 에서 워밍업 호출을 없애면 측정값에 어떤 영향이 생길 수 있는지 설명하시오.
2. BuildByBuilder 를 string.Join 으로 다시 작성하시오. 조각은 "P0;" 부터 "P2999;" 까지이며 결과 길이가 같아야 한다.
3. 원소가 10개뿐인 목록을 하루에 몇 번만 조회하는 코드를 Dictionary 로 바꾸자는 제안에 어떻게 답하겠는가. 근거를 측정 관점에서 쓰시오.
4. 운영 중인 서비스의 메모리 사용량이 서서히 늘어난다는 제보를 받았다. BenchmarkDotNet 과 dotnet-counters 중 무엇을 먼저 쓰겠는가. 이유를 쓰시오.

정답과 해설

1. 첫 실행의 JIT 컴파일과 캐시 준비 비용이 할당 측정 호출이나 반복 측정의 첫 회에 섞인다. 최솟값을 쓰면 일부는 걸러지지만, 할당량 측정은 처음 호출에서 JIT 관련 할당이 더해져 실제보다 크게 나올 수 있다. 워밍업은 이런 일회성 비용을 측정 밖으로 보낸다.
2. 예를 들어 다음처럼 쓴다.

   static string BuildByJoin(int count)
   {
       return string.Join("", Enumerable.Range(0, count).Select(n => $"P{n};"));
   }

   길이는 16890 으로 같다. 조각마다 작은 문자열이 만들어지므로 StringBuilder 보다 할당이 많을 수 있다. 이 차이는 Bench.Measure 의 Allocated 로 확인하면 된다.
3. 원소가 적고 조회가 드물면 해시 테이블을 만드는 비용과 메모리가 이득보다 클 수 있고, 차이가 있어도 전체 시간에서 무시할 수준이다. 제안에는 "실제 크기와 호출 횟수로 재어 차이가 의미 있을 때 바꾸자"고 답한다. 코드가 복잡해지는 비용도 함께 따져야 한다.
4. dotnet-counters 를 먼저 쓴다. 서서히 늘어나는 메모리는 실행 중인 프로세스의 GC 힙 크기와 세대별 GC 횟수 추이로 봐야 드러난다. 원인이 되는 구간을 좁힌 뒤에 그 구간의 두 구현을 BenchmarkDotNet 으로 비교하는 것이 순서에 맞다.