gprof의 출력 결과
해석
gprof 은 여러 가지 다른 출력 스타일을 사용할 수 있다. 이들 출력
스타일중 가장 중요한 것을 아래에서 설명한다. 가장 단순한 형태의 출력 스타일(
파일 정보, 실행 횟수, 함수 및 파일의 순서)에 대한 설명은 하지 않지만, 필요한
경우 각각의 옵션에 대한 설명에서 문서화 되어 있다. 출력과
관련된 옵션 섹션 참고
Flat profile 은 프로그램 내의 각각의 함수들을 실행하는데 소비한 총 시간을 보여준다. `-z' 옵션이 설정되어 있지 않는 경우에 시간을 전혀 소비하지 않았거나, 호출이 전혀 없었던 함수들은 결과 출력에서 제외된다. 프로파일링 옵션으로 컴파일 되지 않은 모듈에 있는 함수 또는 프로그램 카운터 히스트로그램에 표시될 수 있는 시간보다 적은 시간동안 실행된 함수이 포함되어 있다면 전혀 호출이 없었던 함수들과 구분을 할 수 없다는 점에 유의하여야 한다.
아래의 예는 flat profile의 일부를 보여주고 있다.
Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 33.34 0.02 0.02 7208 0.00 0.00 open 16.67 0.03 0.01 244 0.04 0.12 offtime 16.67 0.04 0.01 8 1.25 1.25 memccpy 16.67 0.05 0.01 7 1.43 1.43 write 16.67 0.06 0.01 mcount 0.00 0.06 0.00 236 0.00 0.00 tzset 0.00 0.06 0.00 192 0.00 0.00 tolower 0.00 0.06 0.00 47 0.00 0.00 strlen 0.00 0.06 0.00 45 0.00 0.00 strchr 0.00 0.06 0.00 1 0.00 50.00 main 0.00 0.06 0.00 1 0.00 0.00 memcpy 0.00 0.06 0.00 1 0.00 10.11 print 0.00 0.06 0.00 1 0.00 0.00 profil 0.00 0.06 0.00 1 0.00 50.00 report ...
출력 결과에서 함수는 소비한 실행 시간의 내림 차순으로 먼저 정렬된 후, 호출된 횟수의 내림 차순으로 되고, 다시 함수명에 따라 정렬된다. `mcount' 함수와 `profil' 함수는 프로파일링을 위한 내부 함수로 모든 flat profile에 포함된다. `mcount' 함수와 `profil' 함수에 소요된 시간을 살펴봄으로써 프로파일링에 따른 오버헤드를 측정할 수 있다.
컬럼 이름(column headers) 이전의 라인은 각각의 샘플링 간격 표시하는 행이 있다. 이 sampling period 를 사용하여 시간을 나타내는 각각의 수치의 오차의 한계를 추정할 수 있다. 시간을 나타내는 수치가 sampling period 보다 크지 않은 경우 이 수치는 신뢰할 없는 값이다. 위의 예에서 각각의 샘플은 0.01초로 카운트되어 있다. 이는 100Hz의 sampling rate를 나타낸다. 프로그램의 총 실행 시간은 `cumulative seconds' 필드에서 알 수 있듯이 0.06초이다. 각각의 샘플이 0.01초 간격으로 수집되었으므로, 이 프로그램의 실행중에 여섯 번의 샘플링이 있었음을 알 수 있다. `self seconds' 필드의 값으로부터 여섯 번의 샘플링 중 두 개는 프로그램이 `open' 함수내에 있을 때 일어났음을 알 수 있다. 다른 네 번의 샘플링은 각각 `offtime', `memccpy', `write', 와 `mcount' 함수에서 한번씩 발생하였다. 샘플링이 여섯 번밖에 발생하지 않았으므로, 이들 값중 어느 것도 신뢰할 만한 것으로 보기는 어렵다. 즉 동일한 프로그램을 다시 실행하는 경우 `mcount' 함수의 `self seconds' 는 0.00' 또는 `0.02'이 될 수도 있다. 이러한 문제에 대한 좀더 상세한 내용은 통계적 샘플링에 따른 오류 섹션을 참고하기 바란다.
`self seconds' 필드 값이 `0.00'인 함수들은 히스토그램 샘플에서는 표시되지 않는다. 그러나 call graph 상에서 이들 함수에 대한 호출이 있었던 것으로 나타난다면 리스팅되어야 하므로, 호출 횟수를 나타내는 `calls' 필드의 내림차순으로 표시된다. 이들 함수가 실행되는데 시간이 소비되기는 했지만, 히스토그램 샘플의 양이 적기 때문에 각각의 함수에서 얼마만큼의 시간이 소비되었는 지를 판단할 수가 없다.
각 라인에 있는 필드들의 의미는 다음과 같다.
% time
cumulative seconds
self seconds
calls
self ms/call
total ms/call
name
Call graph 는 각각의 함수와 그 함수의 자식 함수(children)에서 소비된 시간의 양을 보여준다. call graph의 정보를 이용하면 함수 자체에서 많은 시간을 소비하지는 않지만, 함수 내부에 시간 소비량이 많은 함수에 대한 호출을 포함하고 있는 함수들을 찾아낼 수 있다.
다음에 예시하는 call 의 예는 앞장의 flat profile의 예제에서 사용한 프로그램에
대한 gprof 실행으로부터 얻은 call graph에서 발췌한 것이다.
granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds
index % time self children called name
<spontaneous>
[1] 100.0 0.00 0.05 start [1]
0.00 0.05 1/1 main [2]
0.00 0.00 1/2 on_exit [28]
0.00 0.00 1/1 exit [59]
-----------------------------------------------
0.00 0.05 1/1 start [1]
[2] 100.0 0.00 0.05 1 main [2]
0.00 0.05 1/1 report [3]
-----------------------------------------------
0.00 0.05 1/1 main [2]
[3] 100.0 0.00 0.05 1 report [3]
0.00 0.03 8/8 timelocal [6]
0.00 0.01 1/1 print [9]
0.00 0.01 9/9 fgets [12]
0.00 0.00 12/34 strncmp <cycle 1> [40]
0.00 0.00 8/8 lookup [20]
0.00 0.00 1/1 fopen [21]
0.00 0.00 8/8 chewtime [24]
0.00 0.00 8/16 skipspace [44]
-----------------------------------------------
[4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
0.01 0.02 244+260 offtime <cycle 2> [7]
0.00 0.00 236+1 tzset <cycle 2> [26]
-----------------------------------------------
점선으로 표시된 라인은 테이블을 엔트리(entry)별로 구분하기 위한 것이다. 각각의 함수에 하나의 엔트리가 대응하며, 각각의 엔트리에는 하나 이상의 라인들이 있다.
각각의 엔트리에서 프라이머리 라인(primary line)은 '['와 ']'로 둘러싸인 인덱스 번호로 시작한다. 프라이머리 라인의 마지막 열에는 해당 엔트리가 어떤 함수에 대한 것인지를 나타낸다. 한 개의 엔트리안에서 프라이머리 라인 앞에 있는 라인은 프라이머리 라인에서 나타내는 함수를 호출하는 함수(callers)들을 나타나며, 프라이머리 라인 뒤에 있는 라인은 프라이머리 라인에서 나타내는 함수의 서브루틴( call graph에서는 자식 함수- children -으로도 지칭한다)들을 나타낸다. 서브루틴(subroutine)은 여기서 해당 함수의 내부에서 호출되는 함수(callee)를 지칭한다.
엔트리들은 해당 함수와 해당 함수의 서브루틴에서 소비된 시간으로 정렬된다.
프로파일링을 위한 내부 함수 mcount (Flat Profile
섹션 참조)는 call graph에서 고려하지 않는다.
하나의 call graph 엔트리내에 있는 프라이머리 라인(primary line )은 현재 엔트리가 나타내는 함수가 어떤 함수인지를 설명하고 해당 함수에 대한 모든 통계정보를 제시한다.
아래의 예는 다음의 설명에서 참조하기 좋도록 필드의 이름을 나타내는 헤딩
라인, report 함수에 대한 엔트리에 있는 프라이머리 라인을 함께 나타낸것이다.
index % time self children called name ; 헤딩 라인 ...
[3] 100.0 0.00 0.05 1 report [3] ; 프라이머리 라인
프라이머리 라인에 있는 필드들이 가지는 의미는 다음과 같다.
index
% time
self
seconds 필드에 있는 값과 같아야 한다.children
self
필드값과 children필드값들을 전부 더한 값과 일치하여야
한다.called
report 함수는 main에서 1회 호출되었음을
알 수 있다.name
gnurr 싸이클 번호
1의 일부분이고 인덱스 번호가 12라면 프라이머리 라인의 name
필드는 다음과 같이 출력된다.gnurr <cycle 1> [12]
하나의 함수에 대응하는 엔트리에는 이 함수를 호출한 함수를 각각 나타내는 라인(caller-line)들이 포함되어 있다. 이들 라인의 필드는 프라이머리 라인의 필드와 일치하지만 필드의 의미는 프라이머리 라인에서의 필드의 의미와는 다르다.
아래의 예는 다음의 설명에서의 참조를 편하게 하도록 필드이름을 나타내는 헤딩
라인,
report함수를 호출한 함수들에 대한 레코드인 caller-line, 과 report함수에
대한 프라이머리 라인을 함께 나타낸 것이다.
index % time self children called name ; 헤딩라인
... 0.00 0.05 1/1 main [2] ; caller line
[3] 100.0 0.00 0.05 1 report [3] ; 프라이머리 라인
main함수에서 호출된 report
함수의 caller-line에서의 각 필드의 의미는 다음과 같다.
self
main함수에서 호출되었을 때 report
함수자신이 소비한 시간에 대한 추정치children
main함수에서 호출되었을 때 report
함수의 서브루틴에서 소비한 시간에 대한 추정치. self 필드와 children 필드의
값은 합은 main함수에서 report
함수를 호출동안에 소비된 시간에 대한 추정치가 된다.called
main 함수에서 report 함수를 호출한 횟수를 나타내고
두 번째 수치는 report 함수의 모든 caller에서 report
함수를 비재귀적으로 호출한 횟수의 총합을 나타낸다.name and index number
report 함수를 호출한 함수(caller)의 이름을 나타낸다. caller 함수의
인덱스가 함수명뒤에 추가된다. 모든 함수들이 call graph에 나타나는 것은 아니다.
즉, gprof 명령의 옵션 지정에 따라 특정 함수는 call graph에
나타나지 않을 수도 있다. caller 함수의 엔트리가 없는 경우에도 caller함수가
호출한 함수(callee)의 엔트리에 caller lines이 있을 수도 있다. caller함수가
재귀 싸이클의 일부분일 경우에는 싸이클 번호가 caller함수 이름과 인덱스 번호사이에
출력된다.
해당함수의 caller 함수를 확인할 수 없는 경우에, dummy caller line이 출력되고
dummy caller-line에서 caller함수의 이름을 나타내는 name필드는
`<spontaneous>'로 표시되고 나머지 필드는 공란으로
채워진다. caller 함수가 시그널 핸들러 함수인 경우에 dummy caller-line 가 된다.
하나의 함수에 대응하는 엔트리에는 이 함수의 내부에서 호출한 함수들(subrountin또는 callee)을 각각 나타내는 라인(subroutine-line)들이 포함되어 있다. callee-line의 필드는 프라이머리 라인의 필드와 동일하지만, 필드의 의미는 달라진다.
아래의 예는 다음의 설명에서의 참조를 편하게 하도록 필드이름을 나타내는 헤딩
라인,
main함수에 대한 프라이머리 라인, main 함수내부에서
호출한 함수들에 대한 레코드인 callee-line을 함께 나타낸 것이다.
index % time self children called name ; 헤딩 라인 ... [2] 100.0 0.00 0.05 1 main [2] ; main함수에 대한 엔트리의 프라이머리 라인
0.00 0.05 1/1 report [3] ; main 함수에서 호출한 함수에 대한 subroutine-line
report 함수를 호출하는 main
함수에 대응하는 엔트리에서의 subroutine-line에서의 각각의 필드는 다음과 같은
의미를 가진다.
self
main함수에서 호출된 report 함수 내부에서만 직접적으로
소비된 시간에 대한 추정치를 나타낸다.children
main함수에서 호출된 report 함수의 서브루틴에서 소비된
시간에 대한 추정치를 나타낸다. self 필드와 children 필드에
있는 값을 더한 값은 main함수에서 호출된 report 함수에서
소비된 시간의 총량에 대한 추정치이다.called
called필드는 '/'로 구분되는 두 개의 값을 가진다. 첫 번째 값은 main
함수에서 report 함수를 호출한 횟수를 나타내고, 두 번째 값은 report 함수에
대한 비재귀적 호출의 총 횟수를 나타낸다. 이 두 값의 비율로부터 main함수에
기인한 report함수의 self
필드와 children 필드에 있는 시간의 양을 판단할 수 있다. 자세한
내용은 children 에서 소비된 시간량의
추정 섹션을 참고하기 바란다.
name
main 함수의 서브루틴의 이름과 서브루틴의 인덱스 번호를 나타낸다.
caller 함수가 재귀 싸이클의 일부분일 경우, 싸이클 번호가 서브루틴 이름과
인덱스 번호 사이에 출력된다.
Call graph에 재귀 호출의 싸이클(cycles of recursion)이 존재하는 경우 graph가
복잡해질 수도 있다. 싸이클은 함수 a 가 함수 b 를
호출하고, 함수 b가 직/간접적으로 다시 원래의 함수 a를
호출하는 상황에서 발생할 수 있다.
두 개의 함수간에 양방향으로 call path가 있으면 이들 함수들은 동일 싸이클에 속하게
된다. 함수 a 와 함수 b 가 서로가 서로를 호출하고,
함수
b 와 함수 c 가 서로가 서로를 호출하는 경우, 함수 a,
b, c는 하나의 싸이클을 형성한다. 여기서 한 가지 유의할 점은 함수 b 가
함수 a 를 호출하고 함수 a 에서는 함수 b 를
호출하지 않는 경우에도(
gprof 는이러한 상황을 구분할 수 없기 때문에), a 와 b를
하나의 싸이클로 간주한다는 것이다.
싸이클에는 연속적인 정수값으로 번호가 부여된다. 어떤 함수가 하나의 싸이클에 속할때마다, 매번 함수의 이름이 call graph내에 나타나고 함수 이름뒤에 함수가 속하는 싸이클 번호 `<cycle number>' 추가된다.
싸이클이 문제가 되는 이유는 싸이클이 존재하는 경우 call graph내에 있는 시간
값들에 모순이 생기기 때문이다. 함수 a 의 children에서 소비된 시간에는
함수 a 의 서브루틴인 b 와 b 의 서브루틴에서
소비된 시간이 포함되어야만 하지만, b 의 서브루틴중에는 a가
있기 때문에 문제가 된다. 즉, 함수
a 가 간접 재귀 호출 형태일때, 함수
a에서의 시간중 얼마만큼을 함수 a의 children에서 소비된 시간에 반영할 것인가라는
의문이 생기게 된다.
gprof 에서는 이러한 문제를 해결하기 위하여 전체적인 싸이클에 대하여
하나의 싱글 엔트리를 만든다. 이 싱글 엔트리의 프라이머리 라인에 싸이클을 형성하고
있는 함수들에서 직접적으로 소비된 총 시간을 기술한다. 싸이클의 "서브루틴들"은
싸이클을 구성하고 있는 개별 함수들과 싸이클을 구성하고 있는 함수들에서 직접적으로
호출된 다른 모든 함수들의 집합으로 정의한다. 싸이클의 "caller 함수들"은
싸이클의 외부에 있는 함수중 싸이클내에 있는 함수를 호출하는 함수들의 집합으로
정의한다.
다음의 예는 함수 a 와 함수 b가 포함된 싸이클을 나타내는
call graph의 일부분이이다. main 함수에서 a 함수 호출을
통하여 싸이클에 진입하게 되고 함수 a 와 b는 모두 함수
c를 호출하고 있는 상황이다.
index % time self children called name
----------------------------------------
1.77 0 1/1 main [2]
[3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
1.02 0 3 b <cycle 1> [4]
0.75 0 2 a <cycle 1> [5]
----------------------------------------
3 a <cycle 1> [5]
[4] 52.85 1.02 0 0 b <cycle 1> [4]
2 a <cycle 1> [5]
0 0 3/6 c [6]
----------------------------------------
1.77 0 1/1 main [2]
2 b <cycle 1> [4]
[5] 38.86 0.75 0 1 a <cycle 1> [5]
3 b <cycle 1> [4]
0 0 3/6 c [6]
----------------------------------------
(이 프로그램에 대한 전체 call graph에서는 추가적으로 main 함수에
대한 엔트리와 c 함수에 대한 엔트리가 포함되며, main 함수는
a, 함수를 호출하고, 함수 c는 함수
a 와 함수 b를 caller로 가진다.)
index % time self children called name
<spontaneous>
[1] 100.00 0 1.93 0 start [1]
0.16 1.77 1/1 main [2]
----------------------------------------
0.16 1.77 1/1 start [1]
[2] 100.00 0.16 1.77 1 main [2]
1.77 0 1/1 a <cycle 1> [5]
----------------------------------------
1.77 0 1/1 main [2]
[3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
1.02 0 3 b <cycle 1> [4]
0.75 0 2 a <cycle 1> [5]
0 0 6/6 c [6]
----------------------------------------
3 a <cycle 1> [5]
[4] 52.85 1.02 0 0 b <cycle 1> [4]
2 a <cycle 1> [5]
0 0 3/6 c [6]
----------------------------------------
1.77 0 1/1 main [2]
2 b <cycle 1> [4]
[5] 38.86 0.75 0 1 a <cycle 1> [5]
3 b <cycle 1> [4]
0 0 3/6 c [6]
----------------------------------------
0 0 3/6 b <cycle 1> [4]
0 0 3/6 a <cycle 1> [5]
[6] 0.00 0 0 6 c [6]
----------------------------------------
싸이클의 프라이머리 라인의 self 필드는 싸이클을 형성하는 모든 함수들에서
소비된 총 시간을 나타내며 이 값은 싸이클을 구성하는 개별 함수들에서의 self 필드값
(이들 함수의 subroutine-line에 있는 엔트리에서 이 값을 알아낼 수 있다)의 합과
같게 된다.
싸이클의 프라이머리 라인과 subroutine-line에 있는 children 필드의
값은 싸이클 외부에 있는 서브루틴만을 카운트한 값이다. 함수 a 가
함수
b를 호출하였다하여도, 함수
b를 호출한 함수들에서 소비된 시간은 함수
a의 children 의 시간에는 카운트되지 않는다. 따라서,
b 를 호출한 함수들의 시간에 함수 a 로의 역방향 간접
재귀 호출(indirect
recursive calls back to a)이 포함되는 문제를 피할 수 있다.
싸이클의 엔트리에 있는 caller-line의 children 필드는caller가
싸이클내에 있는 함수를 호출했을 때, 싸이클 전체와 싸이클의 다른 서브루틴에서
에서 소비된 시간량에 대한 추정값이다
싸이클에 해당하는 프라이머리 라인에 있는 calls 필드는 두 개의
수치를 가지고 있다. 첫 번째 수치는 싸이클내에 있는 함수가 싸이클 외부에 있는
함수에 의해 호출된 횟수이며, 두 번째 수치는 싸이클 내에 있는 함수에 의해 싸이클내에
있는 함수가 호출된 횟수이다( 싸이클내에 있는 함수가 자기 자신을 호출했을 경우,
이 시간도 포함된 값이다). calls 필드에 있는 두 개의 수치값은
호출 횟수를 재귀 호출(recursive call) 횟수과 비재귀 호출 (nonrecursive call)
횟수로 분류한 것의 일반화이다.
싸이클의 엔트리에 있는 싸이클을 구성하는 함수에 대한 subroutin-line의 calls 필드는
그 함수가 싸이클내에 있는 함수에 의해 호출된 횟수를 나타낸다. 이 필드값은 전부
더한 값이 프라이머리 라인의 calls 필드의 두 번째 값이다.
싸이클내에 있는 함수에 대한 개별 엔트리에는 동일한 싸이클내에 있는 다른 함수들이
서브루틴(callees, subroutines)과 callers로써 subroutine-line과 caller-line에
나타날 수도 있다. subroutine-line과 caller-line은 싸이클내에 있는 각각의 함수가
호출된 횟수 또는 싸이클내에서 서로간에 얼마나 호출이 되었는지를 보여준다. subroutine-line과
caller-line에 있는 self 필드 및 children 필드는 재귀호출이
계속될 때 이 필드의 의미를 정의하기 곤란하기 때문에 공란으로 표시한다.
gprof의 `-l' 옵션을 사용하여 프로그램이 라인 단위의
프로파일링을 하도록 할 수 있다. 라인 단위 프로파일링 모드에서, 히스토그램 샘플들은
함수별로 적용되는 대신에 소스 코드 내의 각각의 라인별로 적용된다. 라인 단위
프로파일링을 위해서는 소스코드 라인에 대한 디버깅 심볼 정보가 필요하므로, 디버깅
심볼 정보를 생성하기 위해서 컴파일 시에 `-pg' 에 `-g' 옵션을
추가하여 컴파일하여야 한다.
라인 단위 프로파일링 모드에서 가장 유용한 출력 테이블은 flat profile이다.
현재 버전의 gprof 에서는 call graph arcs를 소스 코드 라인에서
해당 소스 코드라인을 포함하는 함수로 전달하지 못하기 때문에 call graph는 라인
단위 프로파일링모드에서 일반 모드(함수 단위 프로파일링 모드)에서만큼은 유용하지
않다.
아래의 화면 덤프는 라인 단위 프로파일링을 사용하지 않은 경우의 gprof
출력 결과의 한 예이다. ct_init 가 4개의 히스토그램 hits에 해당하고
init_block 함수에 대한 호출이
13327 회 있었음을 유의하여 보기 바란다.
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
30.77 0.13 0.04 6335 6.31 6.31 ct_init
Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
index % time self children called name
0.00 0.00 1/13496 name_too_long
0.00 0.00 40/13496 deflate
0.00 0.00 128/13496 deflate_fast
0.00 0.00 13327/13496 ct_init
[7] 0.0 0.00 0.00 13496 init_block
다음은 동일한 프로그램을 실행하고, 라인 단위 프로파일링 모드로 gprof 출력했을
때의 화면 덤프의 일부이다. ct_init에서의
4개의 히스토그램 hits가 소스코드에 있는 네 개의 라인별로 나뉘어졌음을 유의하여
보기 바란다. 라인번호 49, 351, 382, 385에서 각각 하나의 hit가 발생하였음을 볼
수 있다. Call graph에서
ct_init 함수에서 init_block 함수를 13327 번 호출한
값이 라인 396에서의 1회 호출, 라인 384에서의 3071회 호출, 라인 385에서의 730 호출,
라인 387에서의 6525회 호출로 좀더 세분화하여 분류된 것도 주의하여 보아야 할
부분이다.
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self
time seconds seconds calls name
7.69 0.10 0.01 ct_init (trees.c:349)
7.69 0.11 0.01 ct_init (trees.c:351)
7.69 0.12 0.01 ct_init (trees.c:382)
7.69 0.13 0.01 ct_init (trees.c:385)
Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
% time self children called name
0.00 0.00 1/13496 name_too_long (gzip.c:1440)
0.00 0.00 1/13496 deflate (deflate.c:763)
0.00 0.00 1/13496 ct_init (trees.c:396)
0.00 0.00 2/13496 deflate (deflate.c:727)
0.00 0.00 4/13496 deflate (deflate.c:686)
0.00 0.00 5/13496 deflate (deflate.c:675)
0.00 0.00 12/13496 deflate (deflate.c:679)
0.00 0.00 16/13496 deflate (deflate.c:730)
0.00 0.00 128/13496 deflate_fast (deflate.c:654)
0.00 0.00 3071/13496 ct_init (trees.c:384)
0.00 0.00 3730/13496 ct_init (trees.c:385)
0.00 0.00 6525/13496 ct_init (trees.c:387)
[6] 0.0 0.00 0.00 13496 init_block (trees.c:408)
gprof의 `-A' 옵션을 사용하면 annotate source 리스팅을
얻을 수 있다. annotated source 리스팅은 프로그램 소스에 각각의 함수가 호출된
횟수가 포함되어진 것이다. gprof 가 원래의 소스 코드 파일을 찾지
못하는 경우에는
`-I' 옵션으로 소스 코드 파일의 경로명을 명시적으로 지정하면 된다.
아래와 같이 컴파일 옵션을 지정하면 함수 카운팅 코드(function counting code)에 추가하여 기본 블록 카운팅 코드(block counting code)가 프로그램에 포함되어진다.
`gcc ... -g -pg -a'
컴파일 시에 위와 같은 옵션 설정은 gprof 에서 코드의 각 라인이
실행된 횟수를 결정하는 것을 가능하게 한다. gzip 소스에서 발췌한 다음 함수의
코드를 예로 살펴보자. (라인의 앞에 있는 숫자는 라인 번호이다.)
1 ulg updcrc(s, n)
2 uch *s;
3 unsigned n;
4 {
5 register ulg c;
6
7 static ulg crc = (ulg)0xffffffffL;
8
9 if (s == NULL) {
10 c = 0xffffffffL;
11 } else {
12 c = crc;
13 if (n) do {
14 c = crc_32_tab[...];
15 } while (--n);
16 }
17 crc = c;
18 return c ^ 0xffffffffL;
19 }
위의 코드에서 pdcrc 함수는 최소 5개의 기본 블록을 가지고 있다.
첫 번째 기본 블록은 함수 자체이고, 두 번째와 세 번째 기본 블록은 라인 9의
if 문은 if 의 조건 판단에 따른 분기에 따라 만들어지는
두 개 이상의 기본 블록이며, 네 번째 기본 블럭은 라인 13의
if 문에 의해 정의되는 기본 블록이며, 다섯 번째 기본 블록은 do 루프의
내용에 의해 만들어지는 기본 블럭이다. 컴파일러에서 여러 가지 특수한 경우를 처리하기
위하여 추가적인 기본 블록들을 만들어 낼 수도 있다.
기본 블록 카운팅 코드가 추가된 프로그램은
gprof -l -A 옵션을 사용하여 분석할 수 있다. 여기에 `-x' 옵션은
소스코드의
각각의 라인이 최소 1회이상 레이블되게 하므로 `-x' 옵션을 추가하여
사용하기를 권장한다. 아래의 예는 gzip 실행을 통해 얻은 updcrc
함수의 annotated source 리스팅이다.
ulg updcrc(s, n)
uch *s;
unsigned n;
2 ->{
register ulg c;
static ulg crc = (ulg)0xffffffffL;
2 -> if (s == NULL) {
1 -> c = 0xffffffffL;
1 -> } else {
1 -> c = crc;
1 -> if (n) do {
26312 -> c = crc_32_tab[...];
26312,1,26311 -> } while (--n);
}
2 -> crc = c;
2 -> return c ^ 0xffffffffL;
2 ->}
위의 예에서 보는 것과 같이 updcrc 함수는 2회 호출되었으며, 라인
9에 있는 if 문의 각각의 분기를 한번씩 통과하였음을 알 수 있다.
do
루프 본체는 총 26312 회 실행되었다. while
문과 관련된 annotation을 주의하여 보면, 각 iteration당 1번씩 26312회 실행되었다.
26312회의 실행중 1번은 ( 26312번째 실행) while
문을 exit하는데 사용되었고 나머지 26311회의 실행은 루프의 시작시점으로의 역방향
분기에서 사용된 것이다.