Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

perf로 프로파일링하기

이 문서는 perf로 rustc를 프로파일링하는 방법을 안내합니다.

초기 단계

  • rust-lang/rust를 깨끗한 상태로 체크아웃하십시오
  • bootstrap.toml에서 다음과 같이 설정하십시오:
    • rust.debuginfo-level = 1 - 줄 단위 디버그 정보를 활성화합니다
    • build.allocator는 설정하지 않은 채로 두십시오 - 그래야 valgrind로 메모리 사용량을 프로파일링할 수 있습니다
    • 나머지는 모두 기본값으로 두십시오
  • ./x build를 실행하여 전체 빌드를 수행하십시오
  • 빌드 결과물을 가리키는 rustup 툴체인을 만드십시오

perf 프로파일 수집하기

perf는 Linux에서 온갖 종류의 정보를 수집하고 분석하는 데 사용할 수 있는 훌륭한 도구입니다. 주로 프로그램이 어디에서 시간을 소비하는지 알아내는 데 사용됩니다. 하지만 캐시 미스 등 다른 종류의 이벤트에도 사용할 수 있습니다.

기본 사항

기본 perf 명령은 다음과 같습니다:

perf record -F99 --call-graph dwarf XXX

-F99는 perf가 99 Hz로 샘플링하도록 지시합니다. 이렇게 하면 오래 실행할 때 데이터가 지나치게 많이 생성되지 않습니다.

99 Hz를 자주 사용하는 이유는 다른 주기적인 활동과 주기가 맞물릴 가능성이 낮기 때문입니다.

--call-graph dwarf는 perf가 디버그 정보에서 호출 그래프 정보를 가져오도록 지시하며, 이 방식은 정확합니다. XXX는 프로파일링하려는 명령입니다. 예를 들어 다음과 같이 할 수 있습니다:

perf record -F99 --call-graph dwarf cargo +<toolchain> rustc

이렇게 하면 cargo가 실행됩니다. 여기서 <toolchain>은 처음에 만든 툴체인의 이름이어야 합니다. 다만 주의해야 할 점이 몇 가지 있습니다:

  • 의존성을 빌드하는 데 걸린 시간까지 프로파일링하고 싶지는 않을 것입니다. 따라서 cargo build; cargo clean --package $crate와 같은 방법이 도움이 될 수 있습니다
    • 다만 저는 보통 그냥 touch src/lib.rs를 실행한 뒤 다시 빌드합니다 =)
  • 증분 컴파일이 프로파일을 어지럽히는 것도 원하지 않을 것입니다. 따라서 CARGO_INCREMENTAL=0과 같은 설정이 도움이 될 수 있습니다.

cargo에서 수집한 데이터를 읽을 때 addr2line xxx/elf: could not read first record 문제가 생기지 않게 하려면 최신 버전의 addr2line을 사용해야 할 수도 있습니다:

cargo install --locked addr2line --features="bin"

perf.rust-lang.org 테스트에서 perf 프로파일 수집하기

우리는 종종 perf.rust-lang.org의 특정 테스트를 분석해야 할 때가 있습니다. 가장 쉬운 방법은 rustc-perf 벤치마킹 도구 모음을 사용하는 것이며, 이 방법은 여기에 설명되어 있습니다.

벤치마크 도구 모음 CLI를 사용하는 대신 벤치마크를 수동으로 프로파일링할 수도 있습니다. 먼저 rustc-perf 저장소를 클론해야 합니다:

$ git clone https://github.com/rust-lang/rustc-perf

그런 다음 프로파일링하려는 테스트의 소스 코드를 찾으십시오. 테스트 소스는 collector/compile-benchmarks 디렉터리와 collector/runtime-benchmarks 디렉터리에 있습니다. 그러면 특정 테스트의 디렉터리로 들어가 봅시다. 여기서는 clap-rs를 예로 사용하겠습니다:

cd collector/compile-benchmarks/clap-3.1.6

여기서는 cargo check 성능을 프로파일링하려 한다고 가정해 봅시다. 이 경우 저는 먼저 의존성을 빌드하기 위해 몇 가지 기본 명령을 실행합니다:

# Setup: first clean out any old results and build the dependencies:
cargo +<toolchain> clean
CARGO_INCREMENTAL=0 cargo +<toolchain> check

(여기서도 <toolchain>은 첫 번째 단계에서 만든 툴체인의 이름으로 바꾸어야 합니다.)

다음으로, cargo check를 실행하면서 clap-rs 크레이트만의 실행 시간을 기록하려 합니다. 저는 이를 위해 주로 cargo rustc를 사용하는데, 명시적인 플래그도 추가할 수 있기 때문입니다. 이는 나중에 해 볼 것입니다.

touch src/lib.rs
CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo rustc --profile check --lib

마지막 명령을 주목하십시오. 상당히 복잡합니다! 이 명령은 (경우에 따라) 추가 옵션과 함께 rustc를 실행하는 cargo rustc 명령을 사용합니다. --profile check와 --lib 옵션은 cargo check 실행을 수행한다는 것과 대상이 (바이너리가 아닌) 라이브러리라는 것을 지정합니다.

이제 perf 도구를 사용하여 결과를 분석할 수 있습니다. 예를 들면 다음과 같습니다.

perf report

이 명령은 대화형 TUI 프로그램을 엽니다. 간단한 경우에는 이것이 유용할 수 있습니다. 더 자세히 살펴보려면 perf-focus 도구가 유용할 수 있으며, 이 도구는 아래에서 다룹니다.

주의 사항. rustc-perf 테스트는 저마다 고유한 특성을 지니고 있습니다. 특히 일부는 라이브러리가 아니며, 이 경우에는 touch src/main.rs를 실행하고 --lib를 전달하지 않아야 합니다. 솔직히 말해 어떤 테스트가 어떤 종류인지 가장 잘 구별하는 방법은 저도 잘 모르겠습니다.

NLL 데이터 수집하기

NLL 실행을 프로파일링하려면 다음과 같이 cargo rustc 명령에 추가 옵션을 전달하기만 하면 됩니다:

touch src/lib.rs
CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo rustc --profile check --lib -- -Z borrowck=mir

perf focus로 perf 프로파일 분석하기

perf 프로파일을 수집했다면 이제 그에 대한 정보를 얻어야 합니다. 이를 위해 저는 개인적으로 perf focus를 사용합니다. 이는 단순하지만 유용한 도구로, 다음과 같은 쿼리에 답할 수 있게 해 줍니다:

  • “함수 F에서 얼마나 많은 시간이 소요되었는가” (어디에서 호출되었는지와 관계없이)
  • “함수 F가 G에서 호출되었을 때 F에서 얼마나 많은 시간이 소요되었는가”
  • “G에서 소요된 시간을 제외하고 함수 F에서 얼마나 많은 시간이 소요되었는가”
  • “F는 어떤 함수들을 호출하며, 그 함수들에서 얼마나 많은 시간을 소비하는가”

작동 방식을 이해하려면 perf에 대해 조금 알아야 합니다. 기본적으로 perf는 프로세스를 주기적으로(또는 어떤 이벤트가 발생할 때마다) 샘플링하는 방식으로 작동합니다. perf는 각 샘플마다 백트레이스를 수집합니다. perf focus를 사용하면 해당 백트레이스에 어떤 함수가 나타나는지 테스트하는 정규 표현식을 작성할 수 있으며, 그 정규 표현식을 만족하는 백트레이스를 가진 샘플이 몇 퍼센트인지 알려 줍니다. 제가 NLL 성능을 분석하는 과정을 차례로 따라가며 설명하는 것이 아마 가장 쉬울 것입니다.

perf-focus 설치하기

cargo install을 사용하여 perf-focus를 설치할 수 있습니다:

cargo install --locked perf-focus

예시: MIR borrowck에서 얼마나 많은 시간이 소요됩니까?

어떤 테스트에 대한 NLL 데이터를 수집했다고 가정해 봅시다. 이 테스트가 MIR 빌림 검사기에서 얼마나 많은 시간을 소비하는지 알고 싶습니다. MIR borrowck의 “main” 함수는 do_mir_borrowck이므로 다음 명령을 실행할 수 있습니다.

$ perf focus '{do_mir_borrowck}'
Matcher    : {do_mir_borrowck}
Matches    : 228
Not Matches: 542
Percentage : 29%

'{do_mir_borrowck}' 인자를 매처라고 합니다. 매처는 백트레이스에 적용할 테스트를 지정합니다. 이 경우 {X}는 백트레이스에 정규 표현식 X를 만족하는 함수가 하나라도 있어야 함을 나타냅니다. 이 경우 해당 정규식은 단지 우리가 원하는 함수의 이름일 뿐입니다(사실 이름의 일부이며, 전체 이름에는 모듈 경로 등 여러 가지가 더 포함됩니다). 이 모드에서 perf-focus는 do_mir_borrowck가 스택에 있었던 샘플의 비율만 출력합니다. 이 경우에는 29%입니다.

c++filt에 관한 참고 사항. perf에서 데이터를 가져오기 위해 perf focus는 현재 perf script를 실행합니다(아마 더 나은 방법이 있을 것입니다…). 저는 가끔 perf script가 C++ 맹글링된 이름을 출력하는 경우를 보았습니다. 이는 번거로운 일입니다. 직접 perf script | head를 실행해 보면 알 수 있습니다. rustc::middle 대신 5rustc6middle 같은 이름이 보인다면 같은 문제를 겪고 있는 것입니다. 다음과 같이 하면 이 문제를 해결할 수 있습니다:

perf script | c++filt | perf focus --from-stdin ...

이렇게 하면 perf script의 출력이 파이프를 통해 c++filt를 거치게 되며, 대부분의 이름이 더 읽기 쉬운 형식으로 변환될 것입니다. perf focus의 --from-stdin 플래그는 perf focus를 실행하는 대신 stdin에서 데이터를 가져오도록 지시합니다. 이를 더 편리하게 만들어야 합니다(최소한 perf focus에 c++filt 옵션을 추가하거나, 아예 항상 사용하도록 할 수도 있습니다. 그렇게 해도 거의 해가 없습니다).

예시: MIR borrowck는 트레이트를 해결하는 데 얼마나 많은 시간을 소비합니까?

MIR borrowck가 트레이트 검사기에서 얼마나 많은 시간을 소비하는지 알고 싶을 수도 있습니다. 더 복잡한 정규식을 사용하여 이를 질의할 수 있습니다.

$ perf focus '{do_mir_borrowck}..{^rustc::traits}'
Matcher    : {do_mir_borrowck},..{^rustc::traits}
Matches    : 12
Not Matches: 1311
Percentage : 0%

여기서는 .. 연산자를 사용하여 “스택에 do_mir_borrowck가 있고, 그보다 나중에 이름이 rustc::traits로 시작하는 함수가 있는 경우가 얼마나 자주 있는가?”(기본적으로 해당 모듈의 코드)를 물었습니다. 결과적으로 답은 “거의 없음“입니다. 이 조건에 맞는 샘플은 12개뿐입니다(샘플이 하나도 보이지 않는다면, 대개 쿼리가 잘못되었다는 뜻입니다).

궁금하다면 --print-match 옵션을 사용하여 정확히 어떤 샘플인지 확인할 수 있습니다. 이 옵션은 각 샘플의 전체 백트레이스를 출력합니다. 줄 앞의 |는 정규 표현식과 일치한 부분을 나타냅니다.

예시: MIR borrowck는 어디에서 시간을 소비합니까?

좀 더 “탐색적인” 쿼리를 수행하고 싶을 때가 많습니다. 예를 들어, MIR borrowck가 전체 시간의 29%를 차지한다는 것은 알지만, 그 시간은 어디에서 소비되는 것입니까? 이럴 때는 대개 --tree-callees 옵션이 가장 좋은 도구입니다. 보통은 --tree-min-percent나 --tree-max-depth도 함께 지정하는 것이 좋습니다. 결과는 다음과 같습니다.

$ perf focus '{do_mir_borrowck}' --tree-callees --tree-min-percent 3
Matcher    : {do_mir_borrowck}
Matches    : 577
Not Matches: 746
Percentage : 43%

Tree
| matched `{do_mir_borrowck}` (43% total, 0% self)
: | rustc_borrowck::nll::compute_regions (20% total, 0% self)
: : | rustc_borrowck::nll::type_check::type_check_internal (13% total, 0% self)
: : : | core::ops::function::FnOnce::call_once (5% total, 0% self)
: : : : | rustc_borrowck::nll::type_check::liveness::generate (5% total, 3% self)
: : : | <rustc_borrowck::nll::type_check::TypeVerifier<'a, 'b, 'tcx> as rustc::mir::visit::Visitor<'tcx>>::visit_mir (3% total, 0% self)
: | rustc::mir::visit::Visitor::visit_mir (8% total, 6% self)
: | <rustc_borrowck::MirBorrowckCtxt<'cx, 'tcx> as rustc_mir_dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_statement_entry (5% total, 0% self)
: | rustc_mir_dataflow::do_dataflow (3% total, 0% self)

--tree-callees를 사용하면 다음과 같은 일이 일어납니다.

  • 정규 표현식과 일치하는 각 샘플을 찾습니다.
  • 정규식 매치 이후에 나타나는 코드를 살펴보고 호출 트리를 빌드하려고 합니다

--tree-min-percent 3 옵션은 “전체 시간의 3%보다 많은 시간을 차지하는 것만 보여 달라“는 뜻입니다. 이 옵션이 없으면 트리가 매우 지저분해지는 경우가 많고, malloc 내부 같은 잡다한 항목까지 포함됩니다. --tree-max-depth도 유용할 수 있는데, 이 옵션은 단지 출력할 단계의 수를 제한합니다.

각 줄에는 해당 함수에서 소비된 전체 시간의 비율(“total”)과 그 함수가 호출한 다른 함수가 아닌 그 함수 자체에서만 소비된 시간의 비율(self)을 표시합니다. 보통은 “total“이 더 흥미로운 수치이지만, 항상 그런 것은 아닙니다.

상대 백분율

기본적으로 perf-focus의 모든 백분율은 전체 프로그램 실행을 기준으로 합니다. 이는 전체적인 관점을 유지하는 데 도움이 됩니다. 핫스팟을 찾기 위해 깊이 파고들다 보면, 전체 프로그램 실행 측면에서 이 “핫스팟“이 실제로는 중요하지 않다는 사실을 놓치기 쉽습니다. 또한 서로 다른 쿼리 간의 백분율을 쉽게 비교할 수 있게 해 줍니다.

그렇긴 하지만 때로는 상대 백분율을 얻는 것이 유용하므로, perf focus는 --relative 옵션을 제공합니다. 이 경우 백분율은 (전체 샘플이 아니라) 일치하는 샘플만을 기준으로 표시됩니다. 예를 들어 다음과 같이 borrowck 자체를 기준으로 한 백분율을 얻을 수 있습니다.

$ perf focus '{do_mir_borrowck}' --tree-callees --relative --tree-max-depth 1 --tree-min-percent 5
Matcher    : {do_mir_borrowck}
Matches    : 577
Not Matches: 746
Percentage : 100%

Tree
| matched `{do_mir_borrowck}` (100% total, 0% self)
: | rustc_borrowck::nll::compute_regions (47% total, 0% self) [...]
: | rustc::mir::visit::Visitor::visit_mir (19% total, 15% self) [...]
: | <rustc_borrowck::MirBorrowckCtxt<'cx, 'tcx> as rustc_mir_dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_statement_entry (13% total, 0% self) [...]
: | rustc_mir_dataflow::do_dataflow (8% total, 1% self) [...]

여기서 compute_regions가 “47% total“로 나타난 것을 볼 수 있는데, 이는 do_mir_borrowck에서 소비된 시간의 47%가 해당 함수에서 소비된다는 뜻입니다. 앞에서는 20%로 나타났는데, 이는 do_mir_borrowck 자체가 전체 시간의 43%에 불과하기 때문입니다(그리고 .47 * .43 = .20입니다).