프로파일링
프로파일링 (Profiling)
Profile 모듈은 코드 성능을 개선하려는 개발자를 위한 도구를 제공해요. 이 모듈을 쓰면 실행 중인 코드를 측정해서, 특정 줄(line)에서 시간이 얼마나 소요되는지 한눈에 파악할 수 있는 결과를 만들어 줘요. 가장 흔한 용도는 최적화 대상이 될 "병목 구간(bottleneck)"을 찾는 거예요.
Profile은 "샘플링(sampling)" 혹은 통계적 프로파일러(statistical profiler)라고 불리는 방식을 구현해요. 원리는 이래요. 어떤 task가 실행되는 동안 주기적으로 backtrace를 수집해요. 각 backtrace는 현재 실행 중인 함수와 줄 번호, 그리고 그 줄에 이르기까지 호출된 함수 체인 전체를 담게 돼요. 그래서 각 backtrace가 곧 "실행 상태의 스냅샷"인 셈이에요.
만약 실행 시간의 상당 부분이 특정 코드 줄에서 소비된다면, 그 줄은 수집된 전체 backtrace 집합에 자주 등장하겠죠. 다시 말해, 어떤 줄의 "비용"—정확히는 그 줄까지 이어지는 함수 호출 시퀀스의 비용—은 전체 backtrace 집합에 그 줄이 나타나는 빈도에 비례해요.
샘플링 프로파일러는 줄 단위로 완벽하게 커버하지는 못해요. backtrace가 일정 간격(기본적으로 유닉스 시스템에선 1ms, 윈도우에선 10ms지만 실제 스케줄링은 운영체제 부하에 따라 달라져요)으로 수집되기 때문이에요. 게다가 아래에서 더 자세히 다루겠지만, 샘플이 전체 실행 지점 중 듬성듬성한 일부에서만 모이기 때문에, 샘플링 프로파일러가 모은 데이터는 통계적 노이즈의 영향을 받아요.
하지만 이런 한계에도 불구하고 샘플링 프로파일러는 꽤 강력한 장점이 있어요.
- 시간 측정을 위해 코드를 수정할 필요가 없어요.
- Julia 핵심 코드까지, 그리고 (선택적으로) C나 Fortran 라이브러리까지 프로파일링할 수 있어요.
- "드물게" 실행되기 때문에 성능 오버헤드가 아주 작아요. 프로파일링 중에도 코드가 거의 네이티브 속도로 돌아갈 수 있거든요.
이런 이유로, 다른 대안을 고민하기 전에 먼저 내장 샘플링 프로파일러부터 써보는 걸 권장해요.
본문
기본 사용법 (Basic usage)
간단한 테스트 케이스로 시작해볼게요.
julia> function myfunc()
A = rand(200, 200, 400)
maximum(A)
end
프로파일링하려는 코드는 최소한 한 번은 먼저 실행해두는 게 좋아요. (Julia의 JIT 컴파일러 자체를 프로파일링하려는 게 아니라면요.)
julia> myfunc() # run once to force compilation
이제 이 함수를 프로파일링할 준비가 됐어요.
julia> using Profile
julia> @profile myfunc()
프로파일링 결과를 볼 수 있는 그래픽 브라우저는 여러 가지가 있어요. 시각화 도구 중 하나의 "계열(family)"은 FlameGraphs.jl에 기반하며, 계열마다 서로 다른 사용자 인터페이스를 제공해요.
- VS Code는 프로파일 시각화가 내장된 완전한 IDE예요.
- ProfileView.jl은 GTK 기반의 독립형 시각화 도구예요.
- ProfileVega.jl은 VegaLight를 사용하며 Jupyter 노트북과 잘 어울려요.
- StatProfilerHTML.jl은 HTML을 생성하고 몇 가지 추가 요약도 보여주며, Jupyter 노트북과도 잘 통합돼요.
- ProfileSVG.jl은 SVG를 렌더링해요.
- PProf.jl은 그래프·플레임그래프 등을 살펴볼 수 있는 로컬 웹사이트를 서빙해요.
- ProfileCanvas.jl은 HTML 캔버스 기반 프로파일 뷰어 UI로, Julia VS Code 확장이 사용하지만 대화형 HTML 파일을 생성하는 데도 쓸 수 있어요.
프로파일 시각화의 완전히 독립적인 접근 방식으로는 PProf.jl이 있는데, 외부 도구인 pprof를 사용해요.
여기서는 표준 라이브러리에 포함된 텍스트 기반 표시를 사용해볼게요.
julia> Profile.print()
80 ./event.jl:73; (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
80 ./REPL.jl:97; macro expansion
80 ./REPL.jl:66; eval_user_input(::Any, ::Base.REPL.REPLBackend)
80 ./boot.jl:235; eval(::Module, ::Any)
80 ./:?; anonymous
80 ./profile.jl:23; macro expansion
52 ./REPL[1]:2; myfunc()
38 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type{B...
38 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr{F...
14 ./random.jl:278; rand
14 ./random.jl:277; rand
14 ./random.jl:366; rand
14 ./random.jl:369; rand
28 ./REPL[1]:3; myfunc()
28 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinear,...
3 ./reduce.jl:426; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...
25 ./reduce.jl:428; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...
이 표시의 각 줄은 코드의 특정 위치(줄 번호)를 나타내요. 들여쓰기는 함수 호출의 중첩 순서를 뜻하는데, 더 깊이 들여쓰인 줄일수록 호출 사슬에서 더 깊은 위치에 있다는 뜻이에요. 각 줄에서 첫 번째 "필드"는 그 줄에서, 또는 그 줄이 실행한 함수들 안에서 수집된 backtrace(샘플) 수예요. 두 번째 필드는 파일 이름과 줄 번호, 세 번째 필드는 함수 이름이에요. Julia 코드가 바뀌면 특정 줄 번호도 달라질 수 있으니 유의하세요. 직접 따라 해보고 싶다면 이 예제를 직접 실행해보는 게 가장 좋아요.
이 예제에서 최상위 레벨로 호출된 함수는 event.jl 파일에 있어요. 이 함수는 Julia를 실행할 때 REPL을 구동하는 함수예요. REPL.jl의 97번 줄을 살펴보면, 거기서 eval_user_input() 함수를 호출한다는 걸 알 수 있어요. 이 함수는 REPL에 입력한 내용을 평가하는 함수죠. 우리가 대화형으로 작업하고 있으므로, @profile myfunc()를 입력했을 때 이 함수들이 호출됐던 거예요. 다음 줄은 @profile 매크로가 취한 동작을 반영해요.
첫 줄을 보면 event.jl의 73번 줄에서 backtrace 80개가 수집됐는데, 이 줄 자체가 "비싸서" 그런 건 아니에요. 세 번째 줄을 보면 이 80개의 backtrace가 사실 전부 이 줄이 호출한 eval_user_input 안에서 발생했음을 알 수 있어요. 그래서 실제로 시간이 걸리는 연산을 찾으려면 호출 체인을 더 깊이 살펴봐야 해요.
이 출력에서 첫 번째로 "중요한" 줄은 이거예요.
52 ./REPL[1]:2; myfunc()
REPL은 myfunc를 파일에 넣지 않고 REPL 안에서 정의했다는 뜻이에요. 파일을 사용했다면 파일 이름이 여기 표시됐을 거예요. [1]은 이 REPL 세션에서 myfunc가 첫 번째로 평가된 표현식이라는 뜻이에요. myfunc()의 2번 줄은 rand 호출을 담고 있고, 이 줄에서 backtrace 52개(80개 중)가 발생했어요. 그 아래를 보면 dSFMT.jl 안의 dsfmt_fill_array_close_open! 호출이 보여요.
조금 더 내려가면 이 줄이 보여요.
28 ./REPL[1]:3; myfunc()
myfunc의 3번 줄은 maximum 호출을 담고 있고, 여기서 backtrace 28개(80개 중)가 수집됐어요. 그 아래는 이런 유형의 입력 데이터에 대해 maximum 함수에서 시간이 걸리는 연산을 수행하는 base/reduce.jl의 특정 위치를 보여줘요.
전체적으로 보면, 랜덤 숫자를 생성하는 것이 최댓값을 찾는 것보다 대략 두 배 정도 비싸다는 잠정적인 결론을 내릴 수 있어요. 샘플을 더 많이 모으면 이 결과에 대한 확신을 높일 수 있어요.
julia> @profile (for i = 1:100; myfunc(); end)
julia> Profile.print()
[....]
3821 ./REPL[1]:2; myfunc()
3511 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type...
3511 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr...
310 ./random.jl:278; rand
[....]
2893 ./REPL[1]:3; myfunc()
2893 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinea...
[....]
일반적으로 어떤 줄에서 샘플을 N개 모았다면, 그 결과에는 sqrt(N) 정도의 불확실성이 있다고 예상하면 돼요. (컴퓨터가 다른 작업을 처리하느라 얼마나 바쁜지 같은 다른 노이즈 요인은 제외하고요.) 이 규칙의 주요 예외는 가비지 컬렉션인데, 자주 실행되진 않지만 한 번 실행되면 꽤 비싸요. (Julia의 가비지 컬렉터는 C로 작성됐기 때문에, 이런 이벤트는 아래에서 설명할 C=true 출력 모드나 ProfileView.jl을 사용해 감지할 수 있어요.)
지금까지는 기본인 "트리(tree)" 덤프를 봤어요. 또 다른 방식은 "플랫(flat)" 덤프로, 중첩과 무관하게 개수를 누적해서 보여줘요.
julia> Profile.print(format=:flat)
Count File Line Function
6714 ./ -1 anonymous
6714 ./REPL.jl 66 eval_user_input(::Any, ::Base.REPL.REPLBackend)
6714 ./REPL.jl 97 macro expansion
3821 ./REPL[1] 2 myfunc()
2893 ./REPL[1] 3 myfunc()
6714 ./REPL[7] 1 macro expansion
6714 ./boot.jl 235 eval(::Module, ::Any)
3511 ./dSFMT.jl 84 dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_s...
6714 ./event.jl 73 (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
6714 ./profile.jl 23 macro expansion
3511 ./random.jl 431 rand!(::MersenneTwister, ::Array{Float64,3}, ::In...
310 ./random.jl 277 rand
310 ./random.jl 278 rand
310 ./random.jl 366 rand
310 ./random.jl 369 rand
2893 ./reduce.jl 270 _mapreduce(::Base.#identity, ::Base.#scalarmax, :...
5 ./reduce.jl 420 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
253 ./reduce.jl 426 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
2592 ./reduce.jl 428 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
43 ./reduce.jl 429 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
코드에 재귀가 있으면 혼동을 줄 수 있는 점이 하나 있어요. "자식(child)" 함수의 어떤 줄이 전체 backtrace 수보다 더 많은 개수를 누적할 수 있다는 거예요. 다음 함수 정의를 봐볼게요.
dumbsum(n::Integer) = n == 1 ? 1 : 1 + dumbsum(n-1)
dumbsum3() = dumbsum(3)
만약 dumbsum3을 프로파일링하면서 dumbsum(1)을 실행하는 중에 backtrace가 수집됐다면, 그 backtrace는 이렇게 생겼을 거예요.
dumbsum3
dumbsum(3)
dumbsum(2)
dumbsum(1)
따라서 부모 함수는 개수를 하나만 얻는 데 반해, 이 자식 함수는 개수 3개를 얻어요. "트리" 표현은 이걸 훨씬 명확하게 보여줘요. 그래서 (다른 이유도 있지만) 결과를 볼 때는 트리 방식이 가장 유용한 경우가 많아요.
누적과 초기화 (Accumulation and clearing)
@profile의 결과는 버퍼에 누적돼요. @profile로 여러 코드 조각을 실행했다면, Profile.print()는 그 결과를 합쳐서 보여줘요. 이건 아주 유용할 수 있지만, 때로는 깨끗한 상태에서 다시 시작하고 싶을 때도 있겠죠. 그럴 땐 Profile.clear()를 쓰면 돼요.
프로파일 결과 표시를 제어하는 옵션 (Options for controlling the display of profile results)
Profile.print는 지금까지 설명한 것보다 더 많은 옵션을 가져요. 전체 선언부를 봐볼게요.
function print(io::IO = stdout, data = fetch(); kwargs...)
먼저 위치 인자 두 개를 살펴보고, 그다음 키워드 인자를 살펴볼게요.
io– 결과를 버퍼(예: 파일)에 저장할 수 있게 해 줘요. 기본값은stdout(콘솔)에 출력하는 거예요.data– 분석하고 싶은 데이터를 담아요. 기본값은 미리 할당된 버퍼에서 backtrace를 꺼내 오는Profile.fetch()로 얻은 값이에요. 예를 들어, 프로파일러 자체를 프로파일링하고 싶다면 이렇게 할 수 있어요.
data = copy(Profile.fetch())
Profile.clear()
@profile Profile.print(stdout, data) # Prints the previous results
Profile.print() # Prints results from Profile.print()
키워드 인자는 다음 중 어떤 조합이든 쓸 수 있어요.
format– 위에서 소개했듯, backtrace를 트리 구조를 나타내는 들여쓰기와 함께 출력할지(기본값:tree), 없이 출력할지(:flat) 결정해요.C–true로 설정하면 C와 Fortran 코드의 backtrace도 보여줘요(기본적으로는 제외돼요). 도입부 예제를Profile.print(C = true)로 실행해보세요. 병목이 Julia 코드 탓인지 C 코드 탓인지 판단할 때 아주 유용해요.C = true를 설정하면 중첩을 더 해석하기 쉬워지기도 하지만, 프로파일 덤프가 길어지는 대가가 있어요.combine– 어떤 코드 줄은 여러 연산을 담아요. 예를 들어s += A[i]는 배열 참조(A[i])와 합 연산을 모두 담고 있어요. 이 둘은 생성된 기계어 코드에서 서로 다른 줄에 해당하므로, 이 줄에서 backtrace를 수집할 때 서로 다른 주소가 두 개 이상 잡힐 수 있어요.combine = true는 이들을 한데 묶어주며, 대개 이게 원하는 동작이에요. 하지만 고유한 instruction pointer마다 별도로 출력하고 싶다면combine = false를 쓰면 돼요.maxdepth–:tree형식에서maxdepth보다 깊은 프레임을 제한해요.sortedby–:flat형식의 정렬 순서를 제어해요.:filefuncline(기본값)은 소스 줄로 정렬하고,:count는 수집된 샘플 수 순서로 정렬해요.noisefloor– 샘플의 휴리스틱 노이즈 바닥 아래에 있는 프레임을 제한해요(:tree형식에만 적용). 한번 시도해볼 만한 값은 2.0이에요(기본값은 0). 이 파라미터는n <= noisefloor * √N인 샘플을 숨겨요. 여기서n은 해당 줄의 샘플 수,N은 피호출자(callee)의 샘플 수예요.mincount–mincount보다 적게 등장하는 프레임을 제한해요.
파일/함수 이름은 때로 ...로 잘리고, 들여쓰기는 공간이 부족하면 앞쪽에 +n 형태로 잘려요. 여기서 n은 공간만 있었다면 삽입됐을 추가 공백 개수예요. 깊이 중첩된 코드의 완전한 프로파일이 필요하다면, 넓은 displaysize를 가진 IOContext로 파일에 저장하는 게 종종 좋은 방법이에요.
open("/tmp/prof.txt", "w") do s
Profile.print(IOContext(s, :displaysize => (24, 500)))
end
설정 (Configuration)
@profile은 backtrace를 누적만 하고, 분석은 Profile.print()를 호출할 때 일어나요. 오래 실행되는 계산에서는 backtrace를 저장하는 미리 할당된 버퍼가 꽉 차는 일이 얼마든지 일어날 수 있어요. 그렇게 되면 backtrace 수집은 멈추지만 계산 자체는 계속돼요. 그 결과 중요한 프로파일링 데이터를 놓칠 수 있어요(이런 일이 생기면 경고를 받게 돼요).
관련 파라미터를 얻고 설정하는 방법은 이래요.
Profile.init() # returns the current settings
Profile.init(n = 10^7, delay = 0.01)
n은 저장할 수 있는 instruction pointer의 총 개수로, 기본값은 10^6이에요. 보통 한 backtrace가 instruction pointer 20개라면 backtrace를 50000개까지 모을 수 있고, 이는 1% 미만의 통계적 불확실성을 뜻해요. 대부분의 애플리케이션에는 이 정도면 충분할 거예요.
따라서 실제로 더 자주 손댈 파라미터는 delay예요. 초 단위로 표현하며, 스냅샷 사이에 Julia가 요청된 계산을 수행할 시간을 설정해요. 아주 오래 실행되는 작업은 자주 backtrace를 수집할 필요가 없어요. 기본값은 delay = 0.001이에요. 물론 delay를 늘릴 수도 줄일 수도 있어요. 다만 backtrace를 수집하는 데 필요한 시간(저자의 노트북 기준 약 30마이크로초)과 delay가 비슷해지면 프로파일링 오버헤드가 커지기 시작해요.
벽시계 프로파일러 (Wall-time Profiler)
소개와 문제 동기 (Introduction & Problem Motivation)
앞 절에서 설명한 프로파일러는 샘플링 CPU 프로파일러예요. 높은 수준에서 보면, 이 프로파일러는 주기적으로 모든 Julia 계산 스레드를 멈추고 backtrace를 수집해서, 해당 함수의 프레임이 포함된 backtrace 샘플 수를 기준으로 각 함수에서 보낸 시간을 추정해요. 다만 한 가지를 기억해야 해요. 프로파일러가 스레드를 멈추기 직전에 시스템 스레드에서 실행 중이던 task만 backtrace를 수집한다는 거예요.
이 프로파일러는 대부분의 task가 계산(compute) 위주인 작업에 잘 맞아요. 하지만 대부분의 task가 I/O 위주인 시스템이나, 코드의 동기화 프리미티브(synchronization primitive)에서 발생하는 경합(contention)을 진단할 때는 덜 유용해요.
이 간단한 워크로드를 생각해볼게요.
using Base.Threads
using Profile
using PProf
ch = Channel(1)
const N_SPAWNED_TASKS = (1 << 10)
const WAIT_TIME_NS = 10_000_000
function spawn_a_bunch_of_tasks_waiting_on_channel()
for i in 1:N_SPAWNED_TASKS
Threads.@spawn begin
take!(ch)
end
end
end
function busywait()
t0 = time_ns()
while true
if time_ns() - t0 > WAIT_TIME_NS
break
end
end
end
function main()
spawn_a_bunch_of_tasks_waiting_on_channel()
for i in 1:N_SPAWNED_TASKS
put!(ch, i)
busywait()
end
end
Profile.@profile main()
우리의 목표는 ch 채널에 경합이 있는지—즉, 채널에 작업 항목이 생성되는 속도에 비해 대기자(waiters) 수가 과도한지—를 감지하는 거예요.
이걸 실행하면 다음과 같은 PProf 플레임그래프를 얻어요.
이 프로파일은 시스템의 동기화 프리미티브 어디에서 경합이 발생하는지 판단할 어떤 정보도 제공하지 않아요. 채널의 대기자는 블록되어 스케줄링에서 제외(descheduled)되므로, 그 대기자들에게 할당된 task를 실행하는 시스템 스레드가 없어요. 따라서 프로파일러가 그들을 샘플링하지 않아요.
벽시계 프로파일러 (Wall-time Profiler)
스레드를 샘플링하는 방식—그래서 실행 중인 task만 샘플링하는 방식—대신, 벽시계 task 프로파일러는 task의 스케줄링 상태와 무관하게 task를 샘플링해요. 예를 들어, 프로파일러가 실행되는 시점에 동기화 프리미티브에서 잠들어 있는 task도, 프로파일러가 backtrace를 잡으려 했을 때 활발히 실행 중이던 task와 같은 확률로 샘플링돼요.
이 접근 방식을 쓰면 위 예제처럼 ch 채널에 블록된 task들의 backtrace가 실제로 포함된 프로파일을 만들 수 있어요.
같은 예제를 이번엔 벽시계 프로파일러로 실행해볼게요.
using Base.Threads
using Profile
using PProf
ch = Channel(1)
const N_SPAWNED_TASKS = (1 << 10)
const WAIT_TIME_NS = 10_000_000
function spawn_a_bunch_of_tasks_waiting_on_channel()
for i in 1:N_SPAWNED_TASKS
Threads.@spawn begin
take!(ch)
end
end
end
function busywait()
t0 = time_ns()
while true
if time_ns() - t0 > WAIT_TIME_NS
break
end
end
end
function main()
spawn_a_bunch_of_tasks_waiting_on_channel()
for i in 1:N_SPAWNED_TASKS
put!(ch, i)
busywait()
end
end
Profile.@profile_walltime main()
다음과 같은 플레임그래프를 얻어요.
채널 관련 take! 함수에서 온 샘플이 아주 많다는 걸 볼 수 있어요. 이를 통해 ch에 실제로 과도한 수의 대기자가 있다는 걸 판단할 수 있어요.
계산 위주 워크로드 (A Compute-Bound Workload)
벽시계 프로파일러는 시스템의 모든 살아있는 task를, 현재 실행 중인 것뿐만 아니라 전부 샘플링하지만, 코드가 계산 위주(compute-bound)여도 성능 핫스팟을 찾는 데 여전히 유용해요. 간단한 예제를 볼게요.
using Base.Threads
using Profile
using PProf
ch = Channel(1)
const MAX_ITERS = (1 << 22)
const N_TASKS = (1 << 12)
function spawn_a_task_waiting_on_channel()
Threads.@spawn begin
take!(ch)
end
end
function sum_of_sqrt()
sum_of_sqrt = 0.0
for i in 1:MAX_ITERS
sum_of_sqrt += sqrt(i)
end
return sum_of_sqrt
end
function spawn_a_bunch_of_compute_heavy_tasks()
Threads.@sync begin
for i in 1:N_TASKS
Threads.@spawn begin
sum_of_sqrt()
end
end
end
end
function main()
spawn_a_task_waiting_on_channel()
spawn_a_bunch_of_compute_heavy_tasks()
end
Profile.@profile_walltime main()
벽시계 프로파일을 수집하고 나면 다음과 같은 플레임그래프를 얻어요.
샘플 중 상당수가 sum_of_sqrt를 포함하고 있는 걸 볼 수 있어요. 이 함수가 우리 예제에서 비싼 계산 함수죠.
프로파일에서 task 샘플링 실패 식별하기 (Identifying Task Sampling Failures in your Profile)
현재 구현에서 벽시계 프로파일러는 마지막 가비지 컬렉션 이후 살아있었던 task와, 그 이후 생성된 task를 샘플링하려 시도해요. 하지만 대부분의 task가 극도로 짧은 수명을 가진다면, 이미 완료된 task를 샘플링하게 되어 backtrace 캡처를 놓칠 수 있어요.
샘플에 failed_to_sample_task_fun이나 failed_to_stop_thread_fun이 포함된 걸 보게 된다면, 대량의 짧은 수명 task 때문에 이들의 backtrace를 수집하지 못했을 가능성이 높아요.
이 간단한 예제를 볼게요.
using Base.Threads
using Profile
using PProf
const N_SPAWNED_TASKS = (1 << 16)
const WAIT_TIME_NS = 100_000
function spawn_a_bunch_of_short_lived_tasks()
for i in 1:N_SPAWNED_TASKS
Threads.@spawn begin
# Do nothing
end
end
end
function busywait()
t0 = time_ns()
while true
if time_ns() - t0 > WAIT_TIME_NS
break
end
end
end
function main()
GC.enable(false)
spawn_a_bunch_of_short_lived_tasks()
for i in 1:N_SPAWNED_TASKS
busywait()
end
GC.enable(true)
end
Profile.@profile_walltime main()
spawn_a_bunch_of_short_lived_tasks에서 생성된 task가 극도로 짧은 수명이라는 점에 주목하세요. 이 task들이 시스템에서 다수를 차지하므로, 대부분의 샘플링된 task에 대한 backtrace 캡처를 놓칠 가능성이 높아요.
벽시계 프로파일을 수집하고 나면 다음과 같은 플레임그래프를 얻어요.
failed_to_stop_thread_fun에서 온 샘플이 많은 것은, 시스템에 상당한 수의 짧은 수명 task가 있다는 걸 확인해줘요.
메모리 할당 분석 (Memory allocation analysis)
성능을 개선하는 가장 흔한 기법 중 하나는 메모리 할당을 줄이는 거예요. Julia는 이를 측정할 수 있는 여러 도구를 제공해요.
@time
총 할당량은 @time, @allocated, @allocations으로 측정할 수 있고, 할당을 유발하는 특정 줄은 대개 이 줄들이 유발하는 가비지 컬렉션 비용을 통해 프로파일링으로 유추할 수 있어요. 하지만 때로는 코드 각 줄이 할당하는 메모리 양을 직접 측정하는 게 더 효율적일 때도 있어요.
GC 로깅 (GC Logging)
@time은 표현식을 평가하는 동안의 메모리 사용과 가비지 컬렉션에 대한 고수준 통계를 기록하지만, 가비지 컬렉션이 얼마나 자주 실행되는지, 매번 얼마나 오래 실행되는지, 매번 얼마나 많은 가비지를 수집하는지에 대한 직관을 얻으려면 각 GC 이벤트를 개별적으로 기록하는게 유용할 수 있어요. GC.enable_logging(true)으로 활성화할 수 있는데, 가비지 컬렉션이 발생할 때마다 Julia가 stderr에 기록하게 해 줘요.
할당 프로파일러 (Allocation Profiler)
Julia 1.8부터 이 기능을 쓸 수 있어요. 이 기능은 최소 Julia 1.8이 필요해요.
할당 프로파일러는 실행되는 동안 각 할당의 스택 트레이스, 타입, 크기를 기록해요. Profile.Allocs.@profile로 호출할 수 있어요.
이 할당 정보는 AllocResults 객체에 감싸인 Alloc 객체들의 배열로 반환돼요. 이들을 시각화하는 가장 좋은 방법은 현재 PProf.jl과 ProfileCanvas.jl 패키지를 쓰는 거예요. 이 패키지들이 가장 많은 할당을 일으키는 호출 스택을 시각화해 줘요.
할당 프로파일러는 오버헤드가 상당해요. 그래서 sample_rate 인자를 넘겨 일부 할당을 건너뛰게 해 속도를 높일 수 있어요. sample_rate=1.0을 넘기면 모든 걸 기록하고(느려요), sample_rate=0.1은 할당의 10%만 기록해요(빠르죠), 이런 식이에요.
Julia 1.11부터 바뀐 점이 있어요. 이전 버전의 Julia는 모든 경우에 타입을 캡처할 수 없었어요. 이전 버전에서 타입이 Profile.Allocs.UnknownType인 할당이 보인다면, 그건 프로파일러가 어떤 타입의 객체가 할당됐는지 모른다는 뜻이에요. 이는 주로 컴파일러가 생성한 코드에서 할당이 발생했을 때 일어났어요. 자세한 내용은 issue #43688을 참고하세요.
Julia 1.11부터는 모든 할당에 타입이 보고돼요.
이 도구를 사용하는 방법에 대한 더 자세한 내용은 JuliaCon 2022의 강연을 참고하세요.
할당 프로파일러 예제 (Allocation Profiler Example)
이 간단한 예제에서는 PProf로 할당 프로파일을 시각화해요. 다른 시각화 도구를 써도 돼요. 프로파일을 수집한 다음(샘플링 비율 지정), 시각화해요.
using Profile, PProf
Profile.Allocs.clear()
Profile.Allocs.@profile sample_rate=0.0001 my_function()
PProf.Allocs.pprof()
여기 더 심화된 예제가 있는데, 샘플링 비율을 어떻게 조정하는지 보여줘요. 목표로 삼을 만한 샘플 수는 대략 1천~1만 개 정도예요. 너무 많으면 프로파일 시각화 도구가 과부하에 걸리고 프로파일링도 느려져요. 너무 적으면 대표성 있는 표본이 되지 못해요.
julia> import Profile
julia> @time my_function() # Estimate allocations from a (second-run) of the function
0.110018 seconds (1.50 M allocations: 58.725 MiB, 17.17% gc time)
500000
julia> Profile.Allocs.clear()
julia> Profile.Allocs.@profile sample_rate=0.001 begin # 1.5 M * 0.001 = ~1.5K allocs.
my_function()
end
500000
julia> prof = Profile.Allocs.fetch(); # If you want, you can also manually inspect the results.
julia> length(prof.allocs) # Confirm we have expected number of allocations.
1515
julia> using PProf # Now, visualize with an external tool, like PProf or ProfileCanvas.
julia> PProf.Allocs.pprof(prof; from_c=false) # You can optionally pass in a previously fetched profile result.
Analyzing 1515 allocation samples... 100%|████████████████████████████████| Time: 0:00:00
Main binary filename not available.
Serving web UI on http://localhost:62261
"alloc-profile.pb.gz"
그런 다음 http://localhost:62261로 이동해 프로파일을 볼 수 있고, 프로파일은 디스크에 저장돼요. 더 많은 옵션은 PProf 패키지를 참고하세요.
할당 프로파일링 팁 (Allocation Profiling Tips)
위에서 말했듯, 프로파일에 대략 1천~1만 개의 샘플을 모으는 걸 목표로 하세요.
주의할 점이 하나 있어요. 우리는 모든 할당의 공간에서 균일하게 샘플링하며, 할당의 크기로 샘플에 가중치를 주지 않아요. 따라서 sample_rate=1로 설정하지 않는 한, 특정 할당 프로파일이 프로그램에서 대부분의 바이트가 할당되는 위치를 대표적으로 보여주지 못할 수 있어요.
할당은 사용자가 객체를 직접 생성해서 생길 수도 있지만, 런타임 내부에서 생기거나 타입 불안정(type instability)을 처리하려고 컴파일된 코드에 삽입될 수도 있어요. "소스 코드(source code)" 뷰를 보면 이를 분리하는 데 도움이 될 수 있고, 그런 다음 Cthulhu.jl 같은 외부 도구로 할당 원인을 식별하는 데 유용할 수 있어요.
할당 프로파일 시각화 도구 (Allocation Profile Visualization Tools)
이제 할당 프로파일을 모두 표시할 수 있는 프로파일링 시각화 도구가 여러 개 있어요. 우리가 아는 주요 도구 몇 가지를 간단히 나열할게요.
- PProf.jl
- ProfileCanvas.jl
- VSCode 내장 프로파일 시각화 도구 (
@profview_allocs) [docs needed] - REPL에서 직접 결과 보기
Profile.Allocs.fetch()로 REPL에서 결과를 확인해 각 할당의 스택트레이스와 타입을 볼 수 있어요.
줄 단위 할당 추적 (Line-by-Line Allocation Tracking)
할당을 측정하는 또 다른 방법은 --track-allocation= 커맨드라인 옵션으로 Julia를 시작하는 거예요. 여기서 none(기본값, 할당을 측정하지 않음), user(Julia 핵심 코드를 제외한 모든 곳에서 메모리 할당 측정), all(Julia 코드의 각 줄에서 메모리 할당 측정) 중에서 고를 수 있어요. 컴파일된 코드의 각 줄에 대해 할당이 측정돼요. Julia를 종료하면 누적 결과가 소스 파일과 같은 디렉토리에, 파일 이름 뒤에 .mem이 붙은 텍스트 파일로 기록돼요. 각 줄에는 할당된 총 바이트 수가 나와요. Coverage 패키지에는 몇 가지 기본적인 분석 도구가 있는데, 예를 들어 줄을 할당된 바이트 수 순으로 정렬해주는 도구가 있어요.
결과를 해석할 때 알아둬야 할 중요한 세부사항이 몇 가지 있어요. user 설정에서는, REPL에서 직접 호출되는 함수의 첫 줄이 REPL 코드 자체에서 일어나는 이벤트 때문에 할당을 보여줘요. 더 중요한 것은 JIT 컴파일도 할당 개수에 더해진다는 점이에요. Julia 컴파일러의 상당 부분이 Julia로 작성됐고, 컴파일에는 보통 메모리 할당이 필요하거든요. 권장 절차는 이래요. 분석하려는 모든 명령을 먼저 실행해 컴파일을 강제한 다음, Profile.clear_malloc_data()를 호출해 모든 할당 카운터를 초기화해요. 마지막으로 원하는 명령을 실행하고 Julia를 종료해 .mem 파일이 생성되게 하면 돼요.
참고: --track-allocation은 코드 생성을 바꿔서 할당을 기록하게 만들기 때문에, 이 옵션 없이 실행했을 때와 할당이 다를 수 있어요. 이 방법 대신 할당 프로파일러를 사용하는 걸 권장해요.
외부 프로파일링 (External Profiling)
현재 Julia는 Intel VTune, OProfile, perf를 외부 프로파일링 도구로 지원해요.
선택한 도구에 따라 Make.user에서 USE_INTEL_JITEVENTS, USE_OPROFILE_JITEVENTS, USE_PERF_JITEVENTS를 1로 설정하고 컴파일해요. 여러 플래그를 동시에 지원해요.
Julia를 실행하기 전에 환경변수 ENABLE_JITPROFILING을 1로 설정하세요.
이제 이 도구들을 활용할 방법이 아주 많아요! 예를 들어 OProfile로 간단한 녹화를 시도해볼 수 있어요.
>ENABLE_JITPROFILING=1 sudo operf -Vdebug ./julia test/fastmath.jl
>opreport -l `which ./julia`
perf로도 비슷하게 할 수 있어요.
$ ENABLE_JITPROFILING=1 perf record -o /tmp/perf.data --call-graph dwarf -k 1 ./julia /test/fastmath.jl
$ perf inject --jit --input /tmp/perf.data --output /tmp/perf-jit.data
$ perf report --call-graph -G -i /tmp/perf-jit.data
프로그램에 대해 측정할 수 있는 흥미로운 것들이 훨씬 더 많아요. 종합적인 목록은 Linux perf 예제 페이지를 읽어보세요.
참고로 perf는 실행마다 perf.data 파일을 저장하는데, 작은 프로그램이라도 꽤 커질 수 있어요. 또한 perf LLVM 모듈은 임시 디버그 객체를 ~/.debug/jit에 저장하므로, 그 폴더를 자주 청소해주세요.