[Python] 내 코드의 성적표를 받아보자! 프로파일링 하는 방법! ( feat. line_profiler)

최근에 업무를 하면서 제가 작성했던 코드의 성능을 높이는 작업이 필요하여 어떻게 할까 고민하던 차에

회사 동기가 알려주어 프로파일링이라는 것을 알게되었고 프로파일링을 통하여 제 코드의 성능 저하 원인을 파악하게 되었고 

해당 원인을 해결함으로써 거의 10배에 가까운 성능 향상이 일어나는 것을 경험하게 되었습니다.

 

한편으로는 기존에 제가 작성하던 코드가 얼마나 비효율적이었는지를 깨닫는 시간이기도 했습니다.

 

뭔가 엄청 망한 성적표를 받는 기분이었습니다. 😅

 

프로파일링을 통해서

내 코드 속에서

어떤 부분이 가장 많이 호출되는지

어떤 부분이 동작하는데 가장 많은 소요시간이 걸리는지

알수있었습니다.

 

이 글에서는 python의 profile과 line_profiler를 활용하여 프로파일링 하는 방법에 대하여 적어보려 합니다.

 

터미널에서 명령어를 활용하여 결과를 보는 방법도 있지만 이 글에서는 코드로 작성하여 확인하는 방법을 공유합니다.

 

프로파일에는 이전에 풀었던 백준의 회사에 있는 사람 문제 코드로 해보았습니다.

1. profile을 활용하여 프로파일링 하는 방법

먼저 profile을 활용하는 방법입니다.

import profile
import pstats
from pstats import SortKey

필요한 라이브러리를 import 합니다.

profile은 순수 파이썬 모듈이므로 별도로 설치는 필요 없습니다.

def company_people(access_record):
    record_dict = {}
    
    for access in access_record:
        name, status = access.split()
        
        if status == "enter":
            record_dict[name] = status
        else:
            del record_dict[name]
        
    return sorted(list(record_dict.keys()), reverse=True)

def solution(access_record):
    people = company_people(access_record)
    
    for person in people:
        print(person)

그 다음 프로파일링할 코드를 작성하거나 import 합니다.

def test():
    access_record = ["Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", "Somjang enter", "Somjang leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", "Somjang enter", "Somjang leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", "Somjang enter"]
    
    solution(access_record=access_record)

마지막으로 test() 함수에 동작할 코드를 넣어준 뒤

if __name__ == '__main__':
    # run code and save statistics file
    profile.run('test()', "profile.stats")

    # call statistics file
    stats = pstats.Stats("profile.stats")

    print("statistics sorted by the cumulative time spend in the function")
    stats.strip_dirs().sort_stats(SortKey.CUMULATIVE).print_stats(10)
    print('='*50)

    print("statistics sorted by the time spend in the single function")
    stats.strip_dirs().sort_stats(SortKey.TIME).print_stats(10)
    print('='*50)

    print("statistics sorted by primitive calls")
    stats.strip_dirs().sort_stats(SortKey.PCALLS).print_stats(10)
    print('='*50)

메인에서 프로파일링을 수행합니다.

 

각 줄을 한줄씩 보면 다음과 같습니다.

profile.run('test()', "profile.stats")

프로파일링할 코드를 실행하고 그 실행으로 부터 프로파일링 통계를 수집합니다.

stats = pstats.Stats("profile.stats")

Profile 인스턴스에서 통계 객체의 인스턴스를 만듭니다.

 

누적시간 순으로 정렬한 결과 중 상위 10개

stats.strip_dirs().sort_stats(SortKey.CUMULATIVE).print_stats(10)

 

statistics sorted by the cumulative time spend in the function
Thu Jul  8 22:10:04 2021    profile.stats

         123 function calls in 0.001 seconds

   Ordered by: cumulative time
   List reduced from 12 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 profile:0(test())
        1    0.000    0.000    0.001    0.001 :0(exec)
        1    0.000    0.000    0.001    0.001 <string>:1(<module>)
        1    0.000    0.000    0.001    0.001 profiling_test.py:25(test)
        1    0.000    0.000    0.001    0.001 profiling_test.py:18(solution)
        1    0.000    0.000    0.001    0.001 profiling_test.py:5(company_people)
      113    0.000    0.000    0.000    0.000 :0(split)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        1    0.000    0.000    0.000    0.000 :0(print)
        1    0.000    0.000    0.000    0.000 :0(sorted)

코드가 실행되는 동안 걸린 총 소요시간에서 

각 과정들이 실행되는데 소요되는 누적 소요시간 순으로 정렬 한 것입니다.

profiling 관련 코드 말고 가장 누적 소요시간이 가장 긴 것은

이름과 출입여부를 나누는 부분에서 사용한 split인 것을 볼 수 있습니다.

 

profile한 시간, 함수를 호출한 총 횟수, 실행하는데 걸린 소요시간 순으로 보여집니다.

 

내부 시간 순 상위 10개

stats.strip_dirs().sort_stats(SortKey.TIME).print_stats(10)

statistics sorted by the time spend in the single function
Thu Jul  8 22:10:04 2021    profile.stats

         123 function calls in 0.001 seconds

   Ordered by: internal time
   List reduced from 12 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 profiling_test.py:5(company_people)
      113    0.000    0.000    0.000    0.000 :0(split)
        1    0.000    0.000    0.001    0.001 :0(exec)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        1    0.000    0.000    0.001    0.001 profile:0(test())
        1    0.000    0.000    0.000    0.000 :0(print)
        1    0.000    0.000    0.001    0.001 profiling_test.py:25(test)
        1    0.000    0.000    0.001    0.001 profiling_test.py:18(solution)
        1    0.000    0.000    0.001    0.001 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 :0(sorted)

 

Primitive time 순 상위 10개

stats.strip_dirs().sort_stats(SortKey.PCALLS).print_stats(10)

statistics sorted by primitive calls
Thu Jul  8 22:10:04 2021    profile.stats

         123 function calls in 0.001 seconds

   Ordered by: primitive call count
   List reduced from 12 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      113    0.000    0.000    0.000    0.000 :0(split)
        1    0.000    0.000    0.001    0.001 profile:0(test())
        1    0.000    0.000    0.001    0.001 :0(exec)
        1    0.000    0.000    0.001    0.001 <string>:1(<module>)
        1    0.000    0.000    0.001    0.001 profiling_test.py:25(test)
        1    0.000    0.000    0.001    0.001 profiling_test.py:18(solution)
        1    0.000    0.000    0.001    0.001 profiling_test.py:5(company_people)
        1    0.000    0.000    0.000    0.000 :0(keys)
        1    0.000    0.000    0.000    0.000 :0(sorted)
        1    0.000    0.000    0.000    0.000 :0(print)

 

저는 위의 방법으로 불필요하게 많이 호출하는 것들을 알 수 있었고

불필요하게 많이 호출하는 부분들을 최대한 줄여나감으로 상당부분 성능 개선을 할 수 있었습니다.

2. line_profiler를 활용하여 프로파일링 하는 방법

위의 방법보다 더 자세하게 코드 속 어디에서 시간이 많이 소요되는지 알고 싶을때!

line_profiler를 사용하면 더 쉽게 알 수 있습니다.

 

line_profiler는 파이썬 기본 모듈이 아니므로 사용하기 위해서는 설치를 해주어야합니다.

$ pip install line_profiler

설치를 한 뒤에 사용하기 위하여 line_profiler를 import 해줍니다.

from line_profiler import LineProfiler

프로파일링에 사용할 코드는 이전과 동일하게 작성합니다.

if __name__ == '__main__':
    line_profiler = LineProfiler()
    line_profiler.add_function(company_people)

    lp_wrapper = line_profiler(test)

    lp_wrapper()

    line_profiler.print_stats()

라인프로파일링 코드는 위와 같이 작성합니다.

 

기본적으로

line_profiler = LineProfiler()

라인프로파일러를 생성한 뒤

lp_wrapper = line_profiler(test)

main함수 ( 여기서는 test ) 를 전달하는 line_profiler 인스턴스를 호출하여 wrapper를 만들고

lp_wrapper()

이를 실행한 뒤

line_profiler.print_stats()

라인 프로파일링 결과를 출력하도록 합니다.

 

만약 main함수 이외에 다른 함수가 보고 싶다면

해당 함수를 import 또는 작성하여 

line_profiler = LineProfiler()
line_profiler.add_function(company_people)

위와 같이 생성한 line_profiler에 add_function을 활용하여 해당 함수를 추가해주면 됩니다.

 

결과는 다음과 같이 나옵니다.

Timer unit: 1e-06 s

Total time: 0.000253 s
File: line_profiling.py
Function: company_people at line 3

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     3                                           def company_people(access_record):
     4         1          1.0      1.0      0.4      record_dict = {}
     5                                               
     6       114         51.0      0.4     20.2      for access in access_record:
     7       113         86.0      0.8     34.0          name, status = access.split()
     8                                                   
     9       113         49.0      0.4     19.4          if status == "enter":
    10        57         33.0      0.6     13.0              record_dict[name] = status
    11                                                   else:
    12        56         29.0      0.5     11.5              del record_dict[name]
    13                                                   
    14         1          4.0      4.0      1.6      return sorted(list(record_dict.keys()), reverse=True)

Total time: 0.000468 s
File: line_profiling.py
Function: test at line 23

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    23                                           def test():
    24         1         10.0     10.0      2.1      access_record = ["Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    25         1          1.0      1.0      0.2      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    26         1          1.0      1.0      0.2      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", "Somjang enter", "Somjang leave", 
    27         1          0.0      0.0      0.0      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    28         1          0.0      0.0      0.0      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    29         1          0.0      0.0      0.0      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", "Somjang enter", "Somjang leave", 
    30         1          1.0      1.0      0.2      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    31         1          1.0      1.0      0.2      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", 
    32         1          3.0      3.0      0.6      "Baha enter", "Askar enter", "Baha leave", "Artem enter", "Somjang enter", "Rachel enter", "Joy enter", "Askar leave", "Artem leave", "Somjang leave", "Joy leave", "Rachel leave", "Somjang enter"]
    33                                               
    34         1        451.0    451.0     96.4      solution(access_record=access_record)

각 함수 별 소요시간, 각 함수의 라인별 호출 횟수, 소요시간, 한번 요청될때 소요되는 시간,

전체에서 차지하는 비율이 나옵니다.

 

각 Column 설명

구분	Line	Hits	Time	Per Hit	Time	Line Contents
내용	결과 라인번호	총 호출 횟수	총 소요시간	1번 호출 시 걸린 소요시간	전체 소요시간 중 해당 라인의 비율	각 라인 코드

이를 통하여 저는 어느 부분의 코드가 많이 호출되고 줄일 수 있는 부분이 있는지 확인하면서 코드를 수정했습니다.

 

앞으로도 이번 프로젝트를 진행하며 경험한 내용을 바탕으로 더 나은 코드를 작성하기 위해 노력하고자 합니다~!

 

읽어주셔서 감사합니다.