프로그램 수행시간 프로파일링시 gprof와 time커맨드 결과 차이에 대한 질문
안녕하세요. 저는 대량의 컴퓨터 계산을 이용하는 전공을 공부하는 대학원생입니다.
분자시뮬레이션 프로그램을 돌리고 있는데, 느린 부분이 있어 gprof를 이용하여 프로파일링을 하다가 이상한 점이 있어 질문합니다.
컴파일러는 intel fortran compiler를 사용하고 -O3 -fast 옵션 줘서 최적화했습니다.
사용하는 배포판은 우분투 8.04입니다.
다음은 프로파일링 결과입니다.
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
35.61 31.83 31.83 105274 0.00 0.00 neighbor_
25.38 54.52 22.69 500000 0.00 0.00 force_
9.54 63.05 8.53 1536000000 0.00 0.00 genrand_int32_
9.14 71.22 8.17 1536000000 0.00 0.00 genrand_real1_
6.58 77.10 5.88 500000 0.00 0.00 correct_
6.40 82.82 5.72 500000 0.00 0.00 predict_
4.78 87.09 4.27 500000 0.00 0.00 fene_range_
2.17 89.03 1.94 500000 0.00 0.00 v_arrange_
0.10 89.12 0.09 __write_nocancel
0.09 89.20 0.08 __intel_new_memcpy
0.03 89.23 0.03 500000 0.00 0.00 fene_particle_
0.03 89.26 0.03 cvtas_t_to_a
0.02 89.28 0.02 5000 0.00 0.00 er_
0.02 89.30 0.02 5000 0.00 0.00 rg_
0.02 89.32 0.02 for_write_seq_fmt_xmit
0.02 89.34 0.02 for_write_seq_xmit
0.01 89.35 0.01 1 0.01 89.11 MAIN__
0.01 89.36 0.01 __errno_location
0.01 89.37 0.01 _intel_fast_memset.J
0.01 89.38 0.01 cvt_ieee_t_to_text_ex
0.01 89.39 0.01 for__format_value
0.00 89.39 0.00 500000 0.00 0.00 fene_ring_
0.00 89.39 0.00 500000 0.00 0.00 output_data_
...
이 결과만 본다면 코드는 약 90초 정도에 수행되어야 합니다.
하지만 time의 결과(time ./a.out)는,
real 3m29.881s
user 3m26.730s
sys 0m0.100s
으로, 약 두 배 이상 차이가 납니다.
디스크 io 횟수를 조절해가면서 실험해봤는데, 별 차이 없습니다. 조그만 결과들 수천번 수만번 적는것과 안적는것과 거의 결과 차이가 없습니다.
그러니까 io때문은 아닌 것 같구요.
구글에 검색해봤는데 gprof는 커널에서 노는건 생각 안한다는 이야기를 하는데 (sleep의 예를 들며) 이 때는 time의 결과에 user 부분이 적게 나와야 하는 것 같습니다.
그래서 모르겠네요;;; 도대체 왜 차이가 나는 건가요? 메모리 잡는것도 두배 네배로 늘려봤는데 속도 차이가 없습니다;;
-pg 옵션 때문에 오버헤드가 생길 것 같아서 -pg빼고 time 결과만 봐도 거의 차이가 없으므로, -pg옵션의 오버헤드는 아닌 듯합니다.
요약하자면
1. gprof와 time 결과가 많이 차이가 난다. io횟수, 메모리 할당 크기, -pg옵션의 오버헤드는 실험으로 배제하였음. 이유가 무엇일까요?
2. time의 수행결과는 약 200초, gprof의 수행결과는 약 90초 정도인데, 이 때 gprof의 결과를 믿어도 괜찮을까요? 프로파일링의 퍼센티지 결과가 맞는거면,
즉, 함수별 수행시간이 *2.1이 되는거면 차이나는 110초를 무시하겠지만, 그냥 어디 엄한데서 110초가 더해지는거라면 (*2.1이 아닌 +110) 꼭 없애야 하는 상황입니다.
3. oprofile을 돌려보면 제대로 결과를 알 수 있을까요? oprofile 돌리려면 커널 옵션 다시 주고 컴파일해야합니까?
감사합니다
댓글 달기