Python profiling 예제

[출처 : http://terzeron.net/wp/?p=770]

다음의 예제는 python에 기본 내장된 프로파일러(profiler)인 hotshot을 이용하여 GNU prof와 비슷하게 프로파일링하는 것을 시연해 본 것이다.

01	#!/usr/bin/env python

02	# -*- coding: utf-8 -*-

03	# vim: set fileencoding=utf-8 :

04

05	import hotshot, hotshot.stats

06

07	def test_func2(i):

08	result = i * 10

09	return result

10

11	def test_func1(i):

12	test_func2(i)

13	result = 1 * i

14	return result

15

16	profile_filename = "prof.result"

17	prof = hotshot.Profile(profile_filename)

18	prof.start()

19

20

sum = 0

21	for i in range(10000):

22	sum = sum + i

23	test_func1(i)

24

print sum

25

26	prof.stop()

27	prof.close()

28	stats = hotshot.stats.load(profile_filename)

29	stats.strip_dirs()

30	stats.sort_stats('time', 'calls')

31	stats.print_stats()

이 스크립트의 실행 결과는 다음과 같다.

49995000
20000 function calls in 0.012 CPU seconds

Ordered by: internal time, call count

ncalls tottime percall cumtime percall filename:lineno(function)
10000 0.008 0.000 0.012 0.000 profile_example.py:11(test_func1)
10000 0.004 0.000 0.004 0.000 profile_example.py:7(test_func2)
0 0.000 0.000 profile:0(profiler)

첫번째 줄은 스크립트가 수행한 결과인 1부터 10000까지의 합을 계산한 것이다. 나머지 부분이 프로파일러가 출력한 통계치인데 다음과 같이 해석할 수 있다.

1) 총 2만 개의 함수 호출이 있었고, 0.012 초가 소요되었다.
2) 수행 시간과 호출 횟수를 기준으로 정렬되었다.
3) profile_example.py의 test_func1() 함수는 1만 번 호출되었고 총 수행 시간은 0.008초인데, 한 번 호출은 0.008/10000=0.000초이다. test_func1()이 호출한 하위 함수들까지 포함한 누적 수행 시간은 0.012초이다.
4) 같은 스크립트의 test_func2() 함수는 1만 번 호출되었고 총 수행 시간은 0.004초인데, 하위 함수들까지 포함한 누적 수행 시간은 0.004초이다.