예제와 함께하는 gprof를 이용한 기본적인 CPU 프로파일링

gprof를 사용하면 특정 실행파일의 함수별 호출횟수, 대략적인 CPU 사용시간을 확인할 수 있다.

즉, 함수별 호출횟수를 기반으로 성능 최적화 포인트 (혹은 성능저하 포인트)를 잡아낼 수 있는 툴이다.

참고로 CPU 사용률의 경우, 10ms 단위의 샘플링이기 때문에 아주 상세한 정보라고 보기는 힘들다.

그리고 기본으로 제공하는 text 리포트의 경우 callstack 정보를 상세하게 확인하기 어려운 단점이 존재한다.

[기본적인 사용법]

기본적인 프로파일링 시퀀스는 다음과 같다.

1. 컴파일 with -pg
2. 실행
3. 프로파일링 리포트 확인

-pg 옵션이 활성화된 실행파일은 아래 세 가지 작업이 추가가 된다.

1.  gmon.out 파일생성 (GMON_OUT_PREFIX 환경변수로 위치 조정가능)
2.  10ms 마다 PC (프로그래밍 카운터) 확인해서 기록
3.  매 함수 호출마다 caller를 확인하고 호출횟수를 카운팅

프로파일링 리포트는 크게 두 파트로 나누어지는데 간략하게 설명하면 아래와 같다.

1. 함수별 소요시간
2. 함수별 호출관계

상세한 결과는 아래 예제와 함께 확인해보자.

[예제]

#include "iostream"

using namespace std;

#define MAX 10000

void work()
{
	for (int i = 0; i < MAX; ++i) {
		for (int j = 0; j < MAX; ++j) {

		}
	}
}

void a()
{
	work();
}


void b()
{
	for (int i = 0; i < MAX; ++i) {
		for (int j = 0; j < MAX; ++j) {

		}
	}
	work();
}

void c()
{
	work();
	work();
}

void d()
{
	work();
	work();
	work();
}

int main()
{
	a();
	b();
	c();
	d();
	return 0;
}

컴파일 및 실행, 리포트는 아래 명령을 참고하자

   $ g++ -g -pg -o test  test.cpp

   $ ./test

   $ gprof ./test

첫 번째 결과는 다음과 같다.

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 88.51      1.29     1.29        7   184.60   184.60  work()
 12.45      1.47     0.18        1   181.71   366.31  b()
  0.00      1.47     0.00        1     0.00   184.60  a()
  0.00      1.47     0.00        1     0.00   369.20  c()
  0.00      1.47     0.00        1     0.00   553.80  d()

각 필드를 설명하자면 아래와 같다.

•  %time : 전체 수행시간을 퍼센트로 나타낸 값
• cumulative seconds : 실제 수행시간의 누적값 (self seconds 값들의 누적)
• self seconds : 해당 함수의 실제 수행시간 (정렬의 key로 사용된다)
• calls : 해당 함수가 호출된 횟수
• self ms/call : 해당 함수가 다른 함수를 호출하지 않고 소비한 시간 ms
• total ms/call : 해당 함수가 호출된 시점부터 리턴될 때 까지 걸린 ms

이를 통해서 아래와 같은 점들을 알 수 있다.

• d() 함수는 호출시 가장 오래 걸리는 함수이지만 대부분의 시간은 호출되는 다른 하부 함수들에서 소비된다
• work()와 b() 함수는 callee들을 제외한 순수 로직상으로 비슷한 시간이 소비된다.
• work() 함수는 가장 많이 호출된다.

두 번째, 결과를 확인해보자.

		     Call graph (explanation follows)


granularity: each sample hit covers 2 byte(s) for 0.68% of 1.47 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]    100.0    0.00    1.47                 main [1]
                0.00    0.55       1/1           d() [3]
                0.00    0.37       1/1           c() [4]
                0.18    0.18       1/1           b() [5]
                0.00    0.18       1/1           a() [6]
-----------------------------------------------
                0.18    0.00       1/7           a() [6]
                0.18    0.00       1/7           b() [5]
                0.37    0.00       2/7           c() [4]
                0.55    0.00       3/7           d() [3]
[2]     87.7    1.29    0.00       7         work() [2]
-----------------------------------------------
                0.00    0.55       1/1           main [1]
[3]     37.6    0.00    0.55       1         d() [3]
                0.55    0.00       3/7           work() [2]
-----------------------------------------------
                0.00    0.37       1/1           main [1]
[4]     25.0    0.00    0.37       1         c() [4]
                0.37    0.00       2/7           work() [2]
-----------------------------------------------
                0.18    0.18       1/1           main [1]
[5]     24.9    0.18    0.18       1         b() [5]
                0.18    0.00       1/7           work() [2]
-----------------------------------------------
                0.00    0.18       1/1           main [1]
[6]     12.5    0.00    0.18       1         a() [6]
                0.18    0.00       1/7           work() [2]
-----------------------------------------------

각 필드 설명은 아래와 같다.

• time : self + child의 합이 전체 시간에서 몇 퍼센트를 차지하는지 나타낸다
• called : 호출된 횟수이다. 재귀호출의 경우 +로 표시된다.

self와 children의 경우는 위치에 따라서 그 의미가 약간씩 다르다. 우선 첫 번째 부분.

index % time    self  children    called     name
                                                 <spontaneous>
[1]    100.0    0.00    1.47                 main [1]
                0.00    0.55       1/1           d() [3]
                0.00    0.37       1/1           c() [4]
                0.18    0.18       1/1           b() [5]
                0.00    0.18       1/1           a() [6]

index가 표시된 함수를 기준으로 살펴봐야 한다. 여기는 main 함수가 기준이다.

살펴보니 main 함수가 d(), c(), b(), a()를 호출했음을 의미한다. (실제 호출순서와는 다르게 정렬된 결과다)

main 함수의 children - 즉, d(), c(), b(), a() - 이 총 1.47s을 소비했고 main 함수 자체는 시간소비를 하지 않았음을 알 수 있다.

b() 함수를 제외하고는 나머지 함수들은 모두 children 함수들에서 시간을 소비했음을 알 수 있다.

d() 함수의 상세 내용을 확인하고 싶으면 [3]이 표시된 항목을 해석해야 한다.

index % time    self  children    called     name
                                                 <spontaneous>
                0.00    0.55       1/1           main [1]
[3]     37.6    0.00    0.55       1         d() [3]
                0.55    0.00       3/7           work() [2]

d() 함수는 우선 main [1] 으로부터 호출되었으며 work() [2]를 3번 호출하고 있음을 알 수 있다.

d() 함수 자체는 별도의 수행시간을 소비하지 않지만 children인 work() 함수에서 0.55s가 소비된다.

work() 함수의 수행시간은 최종적으로 main()의 children 시간에 적용된 것을 확인할 수 있다.

여기서 또 파악할 수 있는 것은 work() 함수는 총 7번 호출 중에 d()함수에 의해서 3번 호출된다는 점이다.

즉, work() 함수는 3번 호출되어서 총 0.55s를 사용했다. (0.18s X 3)

관련된 [2] 항목을 살펴보자.

index % time    self  children    called     name
                                                 <spontaneous>
                0.18    0.00       1/7           a() [6]
                0.18    0.00       1/7           b() [5]
                0.37    0.00       2/7           c() [4]
                0.55    0.00       3/7           d() [3]
[2]     87.7    1.29    0.00       7         work() [2]

work() 함수는 children에서 소비되는 시간은 별도로 없으며 7번 호출되어서 총 1.29s를 소비한다.

총 7번의 호출이 어느 함수를 통해서 이뤄졌는지 또한 알 수 있다.

추가적으로 살펴볼 수 있는 부분은 self인데 a() 함수의 self 값인 0.18s는 실제로 a() 함수가 사용한 시간이 아니고 work() 함수에 의해서 직접적으로 사용된 시간을 의미한다.

앞 부분의 self에 대한 해석과 약간 다르다.

다음 포스팅에서는 좀 더 고급사용법을 다룰 예정이다