2.1. gprop의 개념

grop의 작동방식은 간단하다. 프로그램 수행시간동안 각 함수의 호출횟수와 함수 호출시 진입에서 종료할 때 까지의 시간을 기록해두고 이 정보에 대한 통계를 제공하는 방식이다.

저러한 일을 하기 위해서는 각 함수가 호출될 때마다 횟수를 세게하고, 시간함수를 일일이 넣어줘야 하지 않겠느냐고 생각할 수 있겠지만, 걱정할 필요 없다. 컴파일시 -pg옵션만 주면 알아서 저러한 정보들이 생성된다. 그 후 개발자는 gprop를 써서 통계정보를 얻어오기만 하면 된다.

2.2. Pathalizer를 통한 테스트

이해를 쉽게 하기 위해서 pathalizer이라는 프로그램을 통해서 테스트를 해보도록 하겠다.

일단 위 프로그램을 받아서 컴파일 하도록 하자. 컴파일 방법은 간단하니 설명하지 않도록 하겠다.

2.3. 프로그램 수행 시간

프로그램의 수행 시간을 측정하기 위해서 필자는 apache의 로그파일을 pathalizer를 통해서 분석해보도록 했다. 이 apache로그파일은 약 500000줄의 정보를 포함하고 있다.

[root@ns src]# time ./event2dot logfile
real    3m36.316s
user    0m55.590s
sys     0m1.070s
			

2.4. profiling

그럼 위의 프로그램을 분석하기 위해서 profile 정보를 남겨보도록 하겠다. 아래와 같이 -pg 옵션이 사용되도록 Makefile을 수정하도록 하자.

all: event2dot apache2events

OPTIONS=-O2 -g -pg

apache2events: config.o apache2events.o
...
...
			

# gprof ./event2dot | less
 % cumulative  self              self     total
 time seconds  seconds  calls s/call s/call name
43.32   46.03  46.03 339952989  0.00  0.00 CompareNodes(Node *,Node *)
25.06   72.66  26.63    55000   0.00  0.00 getNode(char *,NodeListNode *&)
16.80   90.51  17.85 339433374  0.00  0.00 CompareEdges(Edge *,AnnotatedEdge *)
12.70  104.01  13.50    51987   0.00  0.00 addAnnotatedEdge(AnnotatedGraph *,Edge *)
 1.98  106.11   2.10    51987   0.00  0.00 addEdge(Graph *,Node *,Node *)
 0.07  106.18   0.07        1   0.07  0.07 FindTreshold(AnnotatedEdge *,int)
 0.06  106.24   0.06        1   0.06 28.79 getGraphFromFile(char *,NodeListNode *&,Config *)
 0.02  106.26   0.02        1   0.02 77.40 summarize(GraphListNode *,Config *)
 0.00  106.26   0.00    55000   0.00  0.00 FixName(char *)
			

2.5. gprof 결과를 이용한 프로그램 최적화

그럼 이제 프로그램을 최적화를 해보도록 하자. 모든 함수를 최적화 하면 좋겠지만 역시 시간대비 효율의 문제가 있음으로 가능하면 조그마한 수정으로 큰 효과를 얻을 수 있는 함수를 선택하는게 좋을 것이다. 그렇다면 여러번 호출되는 함수중에서 수행시간이 많이 걸리는 함수를 선별해서 수정하는게 가장 좋을 것이다.

여기에서 우리는 CompareNodes라는 함수가 매우 많은 시간을 소비하고 있음을 알 수 있다. 그래서 CompareNodes함수를 분석해서 비효율적인 부분을 개선을 하기로 결정했다.

몇번의 분석을 통해서 자료구조의 유지를 위해서 사용하는 링크드리스트가 매우 비효율적으로 되어있다는 것을 발견하고 e-edges를 이진트리로 변경하기로 결정을 했다.

코드를 변경한다음 테스트를 한결과 다음과 같은 결과를 보여줬다. 1초이상의 시간을 단축시켰음을 알 수 있다.

real    2m19.314s
user    0m36.370s
sys     0m0.940s
			

2.6. 최적화 후 gprof 결과

다음은 코드 최적화 후 프로그램의 gprof 결과다.

%   cumulative self           self    total
 time   seconds seconds calls  s/call  s/call name
87.01     25.25  25.25  55000    0.00    0.00 getNode(char *,NodeListNode *&)
10.65     28.34   3.09  51987    0.00    0.00 addEdge(Graph *,Node *,Node *)
			

2.7. 다른 profile 프로그램들

GUI화면을 선호하다면 kProf와 cgprofcgprof같은 프로그램도 있으니 관심있다면 사용을 해보기 바란다.