2009. 2. 23. 10:52
Computer/C++, C

gprof(프로파일링)

* 프로그램을 검증하는 사용. 프로그램에 대한 함수들의 사용빈도, 사용시간등을 측정할 수 있는 툴

* 예제

- # vi gprof_test.c

- # gcc -o gprof_test gprof_test.c -pg

- # ./gporf_test
바이너리를 실행하면 gmon.out 파일이 생성됨.

- # gprof gprof_test gmon.out > gprof_profile.txt
gprof [실행 binary] [실행으로 생덩된 gmon.out]

- # cat gprof_profile.txt
Flat profile:
 
Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 71.43      0.05     0.05        1    50.00    50.00  func
 28.57      0.07     0.02        1    20.00    20.00  func2
 
 
                        Call graph
 
 
granularity: each sample hit covers 4 byte(s) for 14.29% of 0.07 seconds
 
index % time    self  children    called     name
                                                 <spontaneous>
[1]    100.0    0.00    0.07                 main [1]
                0.05    0.00       1/1           func [2]
                0.02    0.00       1/1           func2 [3]
-----------------------------------------------
                0.05    0.00       1/1           main [1]
[2]     71.4    0.05    0.00       1         func [2]
-----------------------------------------------
                0.02    0.00       1/1           main [1]
[3]     28.6    0.02    0.00       1         func2 [3]
-----------------------------------------------
 
 
Index by function name
 
   [2] func                    [3] func2

* 주의사항 

- 프로그램이 정상 종료해야 gmon.out파일이 생성됨.


--------------------------------------------------------------------------------------

프로그래머 도구상자:

gprof를 사용한 프로파일링

By Vinayak Hegde 
한글번역 전정호 
이 글은 한글번역판입니다. 원문은 여기에서 볼 수 있습니다.

연재 소개

리눅스(와 다른 유닉스)에는 같이 사용하여 놀라운 기능을 하는 작고 멋진 도구들이 많다. 이런 소프트웨어를 사용하거나 직접 만들면 재미있다. 나는 이번 연재에서 프로그래머에게 유용한 도구들을 살펴볼 것이다. 이 도구들을 사용하면 더 좋은 코드를 작성할 수 있고 작업이 더 편해질 것이다.

프로파일링(profiling)?? 왜 필요하지 ??

소프트웨어를 설계하고 코딩을 하다보면 프로그램을 최적화할 때가 있다. 일반적인 프로파일링과 최적화에 대해 다루기 전에 최적화에 대한 두 인용문을 소개하고 싶다.

  • 대부분의 계산 실수는 어리석음과 다른 어떤 이유보다도 효율성이란 이름으로 (효율성을 달성하건 안하건간에) 행해진다. 
    -- William A. Wulf
  • 우리는 사소한 효율성을 잊어야 한다: 어설픈 최적화는 모든 화의 근원이다. 
    -- Donald E. Knuth

대부분의 프로그램은 80:20 법칙을 따른다. 전체 코드의 20%가 전체 시간의 80%를 차지한다. 위의 인용문이 뜻하는 바는 컴퓨터의 시간보다 프로그래머의 시간이 더 귀중하다는 뜻이다. 그래서 프로그래머가 해당 컴퓨터 아키텍쳐의 세세한 부분보다는 논리에 집중하여 프로그래밍 시간을 줄여주는 자바나 C#같은 언어가 인기를 얻었다. 프로그램의 실행시간은 길어지지만, 프로그래머의 시간은 절약된다. 그러나 프로그램을 더 빨리 실행하기위한 최적화가 필요하지 않다는 말은 아니다. 많은 컴파일러는 알아서 최적화를 한다. 예를 들어, GCC 컴파일러는 (대문자 주의) -O 옵션으로 최적화 수준을 지정한다. 프로파일링(profiling)은 프로그램의 성능을 높이기위해 최적화할 코드및 함수의 위치를 발견하도록 도와준다. 프로그램에서 10번만 호출하는 함수보다 1000번 호출하는 함수를 최적화하는게 당연하다고 생각하지 않는가. 프로그램을 프로파일링하면 코드의 어떤 부분을 자주 사용하고 어떤 함수가 CPU 시간을 많이 잡아먹는지 알 수 있다. 이 두 정보는 최적화할 대상을 정하는데 유용하다. 실제 프로그램을 실행하면서 정보를 모으기때문에 감춰진 버그를 찾는데도 유용하다. 실행중에 예기치않게 어떤 함수를 1000번 호출한다면 설계상 문제이거나 버그일 수 있다. 또, 크고 복잡한 프로젝트에서 코드를 살펴볼때도 유용하다.

프로파일링 정보에는 두가지 종류가 있다 :-

  • Flat Profile 
    함수별로 사용하는 CPU 시간과 호출 횟수를 보여준다. 수집한 전체 프로파일링 정보의 간단한 요약이다. 성능을 높이기위해 어떤 함수를 다시 작성하거나 수정할지 알려준다.
  • Call Graph 
    모든 함수에 대해 자신을 포함하여 다른 함수가 호출한 횟수를 보여준다. 그래서 어떤 함수 호출을 없애거나 다른 효율적인 함수로 대체할지 제안한다. 이 정보는 함수들간의 관계를 드러내고, 감춰진 버그를 알려주기도 한다. 호출그래프를 본 후에 특정 코드 경로를 최적화하고 싶을 것이다.

어떻게 프로파일링 정보를 수집하나 ??

소스코드를 -pg 옵션을 사용하여 (줄단위 프로파일링을 한다면 -g 옵션도 같이) 컴파일해야 한다. Makefile의 내용이 적다면 컴파일 명령어마다 직접 이 옵션을 추가할 수 있다. 그러나 컴파일 명령어가 많다면 makefile에서 CFLAGS/CXXFLAGS 파라미터를 정의하거나 수정하여, 옵션을 makefile의 모든 컴파일 명령어에 추가한다. gnu make 도구를 사용하여 gprof 사용법을 설명하겟다.

gzip으로 압축한 tar 파일을 푼다
$ tar zxf make-3.80.tar.gz
$ cd make-3.80

configure 스크립트를 실행하여 makefile을 만든다
$ ./configure
[configure 출력 생략]

만들어진 makefile의 CFLAGS 파라미터에서 최적화 옵션을 빼고 -pg 옵션을 추가한다. 컴파일러가 최적화하면 프로파일링에 문제가 있는 경우가 있기때문에 GCC 최적화 옵션을 뺐다. 특히 줄단위(line-by-line) 프로파일링을 한다면, 소스코드를 최적할때 없어지는 줄이 있을 수 있다.

소스코드를 컴파일한다
$ make
[컴파일 출력 생략]

아파치, lynx, cvs 같은 소프트웨어를 컴파일할때 이 make를 사용할 수 있다. 그럼 이 make를 사용하여 아파치를 컴파일해본다. 아파치 소스 압축을 풀고, configure한 후, make를 실행하면 프로파일링 정보를 저장한 gmon.out 이라는 파일이 생긴다. 프로파일링 정보를 기록하기때문에 평소보다 make가 느리다. 중요한 점은 일상적인 입력을 가지고 평소와 같이 동작하면서 프로파일링 정보를 모은다는 점이다. 실세 상황에서 자료를 모은다.

프로파일링 결과 분석

이제 "gmon.out"이라는 바이너리파일을 얻었다. 불행히도 프로파일링 자료파일명을 지정하는 방법은 현재 없다. gprof가 "gmon.out" 파일을 해석하여 사람이 볼 수 있는 결과를 만든다. 문법은 다음과 같다:

gprof 옵션 [실행파일 [프로파일링 자료파일 ... ] ] [ > 사람이 볼 수 있는 출력파일]

$ gprof make gmon.out > profile-make-with-Apache.txt

전체 파일은 여기 있다

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.33      0.01     0.01      207     0.05     0.05  file_hash_2
 33.33      0.02     0.01       38     0.26     0.26  new_pattern_rule
 33.33      0.03     0.01        6     1.67     2.81  pattern_search
  0.00      0.03     0.00     2881     0.00     0.00  hash_find_slot
  0.00      0.03     0.00     2529     0.00     0.00  xmalloc
  0.00      0.03     0.00     1327     0.00     0.00  hash_find_item
  0.00      0.03     0.00     1015     0.00     0.00  directory_hash_cmp
  0.00      0.03     0.00      963     0.00     0.00  find_char_unquote
  0.00      0.03     0.00      881     0.00     0.00  file_hash_1
  0.00      0.03     0.00      870     0.00     0.00  variable_buffer_output

위에서 알아낼 수 있는 결론은 :

  1. 3 함수가 (file_hash_2, new_pattern_rule, pattern_search) 거의 대부분의 시간을 잡아먹는다.
  2. pattern_search 함수는 6번만 호출하지만, 호출당 평균 2.81 밀리초가 걸린다.

그러나 정보가 충분하지 않다. 그래서 이 make를 사용하여 lynx, cvs, make, patch를 컴파일해 보았다. 만들어진 gmon.out 파일의 이름을 변경하고, 마지막에 다음과 같이 프로파일링 정보를 가공한다.

$ gprof make gmon-*.out > overall-profile.txt

파일은 여기 있다 
flat profile 부분은 다음과 같다.

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 18.18      0.06     0.06    23480     0.00     0.00  find_char_unquote
 12.12      0.10     0.04      120     0.33     0.73  pattern_search
  9.09      0.13     0.03     5120     0.01     0.01  collapse_continuations
  9.09      0.16     0.03      148     0.20     0.88  update_file_1
  9.09      0.19     0.03       37     0.81     4.76  eval
  6.06      0.21     0.02    12484     0.00     0.00  file_hash_1
  6.06      0.23     0.02     6596     0.00     0.00  get_next_mword
  3.03      0.24     0.01    29981     0.00     0.00  hash_find_slot
  3.03      0.25     0.01    14769     0.00     0.00  next_token
  3.03      0.26     0.01     5800     0.00     0.00  variable_expand_string

아파치를 컴파일할 때와 조금 차이가 있음을 알 수 있다.

  1. find_char_unquote 함수를 23480번 호출하고, 모두 합쳐서 프로그램 실행시간의 1/6 이상을 차지한다.
  2. eval 함수는 37번만 호출하지만, 프로그램 실행시간의 1/11 정보를 차지한다. 아마도 이 함수가 많은 작업을 하며, 여러 함수로 나누어보는 것이 좋을 수 있다. 또, eval 호출에 평균 4.76 밀리초가 걸리는데 다른 함수와 비교하여 매우 크다
  3. pattern_search와 update_file_1 함수를 합치면 거의 실행시간의 1/4을 차지하지만, 전부 268번만 호출한다. 아마도 이 함수들을 작은 함수로 나눌 수 있을 것이다.

이제 아파치 컴파일 프로파일링 자료에서 call graph 부분을 보자.

index % time    self  children    called     	name
-----------------------------------------------
                                   6             eval_makefile  [49]
[25]     3.7    0.00    0.00       6         eval  [25]
                0.00    0.00     219/219         try_variable_definition [28]
                0.00    0.00      48/48          record_files [40]
                0.00    0.00     122/314         variable_expand_string  [59]
                0.00    0.00       5/314         allocated_variable_expand_for_file  [85]
                0.00    0.00     490/490         readline [76]
                0.00    0.00     403/403         collapse_continuations [79]
                0.00    0.00     355/355         remove_comments [80]
                0.00    0.00     321/963         find_char_unquote [66]
                0.00    0.00     170/170         get_next_mword [88]
                0.00    0.00     101/111         parse_file_seq [93]
                0.00    0.00     101/111         multi_glob [92]
                0.00    0.00      48/767         next_token [70]
                0.00    0.00      19/870         variable_buffer_output [68]
                0.00    0.00      13/2529        xmalloc [64]
                0.00    0.00       2/25          xrealloc [99]
                                   5             eval_makefile  [49]
-----------------------------------------------

위의 정보는 다음과 같이 읽는다 : 

  1. 첫번째 열은 gprof 출력의 마지막에 있는 함수 목록 번호다.
  2. 두번째 열은 eval 함수와 eval 함수가 호출한 함수들의 전체 실행시간이다.
  3. 세번째 열과 네번째 열은 각각 순수하게 해당 함수에서 보낸 시간과 호출한 다른 함수들에서 보낸 시간이다
  4. 다섯번째 열의 첫번째 숫자는 eval에서 해당 함수를 호출한 횟수이고, 두번째 숫자는 프로그램에서 해당 함수를 호출한 (자신이 자신을 호출한 경우를 제외한) 전체 횟수이다.
  5. 함수가 자신을 호출하는 재귀호출이 있거나 상호 재귀호출이 있다면 (위의 eval_makefile과 eval과 같이) 함수명 뒤에 cycle 이 붙는다.
  6. 어떤 함수는 항상 eval에서만 호출한다. 함수를 합쳐서 함수를 호출하는 부담을 줄이면 성능이 좋아지는 경우가 있다.

다른 gprof 기능

gprof를 사용하면 상세한 소스 목록과 줄단위 프로파일링 정보도 얻을 수 있다. 일단 어느 부분을 최적화할지 결정하였다면 이 정보가 유용하다. 이 기능을 사용하여 소스코드를 한줄씩 살펴보며 비효율적인 부분을 찾을 수 있다. 줄단위 프로파일링과 flat profile을 사용하면 코드가 어떤 경로로 가장 자주 실행되는지 알 수 있다. 상세한 소스 목록을 사용하여 함수 호출에서 (반복문과 분기문의) 기본 블럭에까지 살펴보면 어떤 반복문이 가장 많이 실행되는지 어떤 분기를 가장 많이 하는지 알 수 있다. 최적의 성능을 얻기위해 코드를 세밀히 조절할 때 유용하다. 여기서 다루지 않은 기능도 있다. 자세한 내용은 gprof info 문서를 참고하라. kprof라는 gprof의 KDE 그래픽 인터페이스도 있다. 참조자료에 URL을 적어두었다.

결론

gprof와 같은 프로파일링 도구는 프로그램을 최적화할때 매우 도움이 된다. 프로파일링은 프로그램의 병목지점을 발견하고 수작업을 최적화하는 첫번째 단계다.

참고자료

  • gprof의 GNU Info 문서
  • gprof의 KDE 그래픽 인터페이스 KProf
  • Function Check - gprof의 몇가지 결점을 해결한 다른 프로파일링 도구 


출처 :
KLDP http://kldp.org/node/32606
한글 번역 http://blog.empas.com/stoneshim/1393358

저작자표시
Posted by 두장

티스토리툴바