[정보] Profiling - 실시간 대화식 프로파일러

PyCon KR 2015에서 Profiling에 대해 이야기 입니다.
[Profiling]: https://github.com/what-studio/profiling
[발표 소개]: http://www.pycon.kr/2015/program/45

내용 참고 하시기 바랍니다.

 

Profiling - 실시간 대화식 프로파일러 from 흥섭 이

 

 
1. Profiling 실시간 대화식 프로파일러 이흥섭 @ 넥슨 • 왓 스튜디오 PyCon KR 2015
 2.  이흥섭 sub@nexon.co.kr • http://subl.ee/ • sublee
 3.  • 한글라이즈 http://hangulize.org/ • TrueSkill 파이썬 구현 http://trueskill.org/ • Profiling • <카트라이더 대시> • <야생의 땅: 듀랑고> http://durango.nexon.com/
 4.  Profiling what-studio/profiling
 5.  게임서버 최적화 파이썬 프로파일러
6.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/interactive.gif
 7.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/continuous.gif
 8.  게임서버
9.  Linux CPython 2.7 gevent
 10.  요청/응답
11.  시야 내 동기화
12.  생태계 AI
 13.  요청/응답 시야 내 동기화 생태계 AI I/O 바운드 CPU 바운드
14.  CPU 병목이 어딜까?
15.  프로파일러 • 성능 분석 도구 • 함수 별 실행 시간, 호출 횟수, 메모리 사용량 등 수집 • 프로그램 최적화를 보조함.
16.  1. profile/cProfile 2. Yappi
 17.  이벤트 기반 프로파일링 • 함수 호출/반환 이벤트 추적 • 실행 시간, 호출 횟수를 조사 • Exclusive ― 서브루틴 제외 • Inclusive ― 서브루틴 포함
18.  def spin(sec): t = time.time() while time.time() - t < sec: pass def spin5(): spin(5) spin5() Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/spin_example.py
 19.  InclusiveExclusive spin5() spin(5)
 20.  profile/cProfile
 21.  $ python -m profile script.py $ python -m cProfile script.py
 22.  396029 function calls in 3.000 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 3.000 3.000 script.py:1(<module>) 1 0.000 0.000 1.000 1.000 script.py:10(alice) 1 0.000 0.000 2.000 2.000 script.py:14(bob) 2 1.074 0.537 3.000 1.500 script.py:4(carol) 1 0.000 0.000 0.000 0.000 {method 'disable' of ... 396023 1.926 0.000 1.926 0.000 {time.time}
 23.  ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 3.000 3.000 script.py:1(<module>) 1 0.000 0.000 1.000 1.000 script.py:10(alice) 1 0.000 0.000 2.000 2.000 script.py:14(bob) 2 1.074 0.537 3.000 1.500 script.py:4(carol) 1 0.000 0.000 0.000 0.000 {method 'disable' of ... 396023 1.926 0.000 1.926 0.000 {time.time} Exclusive Inclusive
 24.  gevent와 잘 붙나?
25.  gevent • 코루틴 기반 네트워킹 라이브러리 • 경량 스레드: Greenlet 참고: <제약을 넘어: Gevent> ― 정민영 • PyCon KR 2014 https://goo.gl/h0OmE7
 26.  서브루틴 코루틴
27.  # gevent-example.py import gevent def slower(): for x in range(4): for y in range(10000000): pass gevent.sleep(0) def faster(): for x in range(2): for y in range(10000000): pass gevent.sleep(0) gevent.spawn(slower) gevent.spawn(faster) gevent.wait() Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/gevent_example.py
 28.  기대 결과 slower ＞ faster (약 2배)
29.  $ python -m profile gevent-example.py
 30.  Traceback (most recent call last): ... File ".../profile.py", line 211, in trace_dispatch if self.dispatch[event](self, frame,t): File ".../profile.py", line 283, in trace_dispatch_call frame, frame.f_back) AssertionError: ('Bad call', ('.../gevent/hub.py', 386, 'switch'), ...)
 31.  $ python -m cProfile gevent-example.py
 32.  함수 Exclusive Inclusive slower 0.129 0.645 faster 0.340 0.341
 33.  profile/cProfile gevent 호환 안 됨
34.  Yappi Yet Another Python Profiler
 35.  Yappi • 멀티스레딩 지원 • 스레드 별 CPU 시간 측정 • 빠름 (적은 분석 오버헤드)
36.  $ python -m yappi script.py
 37.  Clock type: CPU Ordered by: totaltime, desc name ncall tsub ttot tavg script.py:1 <module> 1 0.000018 1.815449 1.815449 script.py:4 foo 2 0.288737 1.815422 0.907711 script.py:14 bar 1 0.000004 1.001799 1.001799 script.py:10 baz 1 0.000005 0.813632 0.813632 name tid ttot scnt _MainThread 139638664439616 1.816491 1
 38.  Clock type: CPU Ordered by: totaltime, desc name ncall tsub ttot tavg script.py:1 <module> 1 0.000018 1.815449 1.815449 script.py:4 foo 2 0.288737 1.815422 0.907711 script.py:14 bar 1 0.000004 1.001799 1.001799 script.py:10 baz 1 0.000005 0.813632 0.813632 name tid ttot scnt _MainThread 139638664439616 1.816491 1 Exclusive Inclusive
 39.  # gevent-example.py import gevent def slower(): for x in range(4): for y in range(10000000): pass gevent.sleep(0) def faster(): for x in range(2): for y in range(10000000): pass gevent.sleep(0) gevent.spawn(slower) gevent.spawn(faster) gevent.wait() slower ＜ faster (약 2배) Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/gevent_example.py
 40.  함수 Exclusive Inclusive slower 0.105112 0.641017 faster 0.105722 0.430493 ???
 41.  스레드 식별자 설정 set_context_id_callback( f ) f → 스레드 Id set_context_name_callback( f ) f → 스레드 타입 이름
42.  # gyappi.py from gevent import getcurrent import yappi @yappi.set_context_id_callback def current_greenlet_id(): return id(getcurrent()) @yappi.set_context_name_callback def current_greenlet_name(): return type(getcurrent()).__name__ yappi.main() Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/gyappi.py
 43.  $ python -m gyappi gevent-example.py
 44.  Clock type: CPU Ordered by: totaltime, desc name ncall tsub ttot tavg gevent-example.py:1 <module> 1 0.000047 0.660959 0.660959 gevent-example.py:3 slower 1 0.421846 0.637329 0.637329 gevent-example.py:8 faster 1 0.214511 0.425404 0.425404 name tid ttot scnt _getframe 139755003744080 0.674929 2 Hub 139754981772656 0.670471 8 Greenlet 139754981772816 0.660287 5 Greenlet 139754981773136 0.534862 3
 45.  함수 Exclusive Inclusive slower 0.421846 0.637329 faster 0.214511 0.425404
 46.  Yappi gevent 호환 잘 됨
47.  프로그램 시작 프로그램 끝 측정 분석결과 출력
48.  측정…
49.  측정… 분석결과 출력
50.  측정 측정 측정 측정 분석결과 출력 분석결과 출력 분석결과 출력 분석결과 출력
51.  측정 측정 측정 측정 뷰어 분석결과 분석결과 분석결과 분석결과
52.  Yappi 뷰어
53.  Yappi 뷰어
54.  2 3 1 로깅 문자열 처리 난수 발생기 게임로직
55.  보편적으로 불리는 함수가 병목처럼 보임
56.  콜스택 계층구조 보존 로깅로깅 ≠
 57.  직접 만들어보자 Profiling
 58.  • Unity3D 프로파일러
59.  요구사항 콜스택 계층구조 보존 gevent 호환 대화식 뷰어 실시간 프로파일링
60.  함수 실행 추적 sys.setprofile( f ) threading.setprofile( f )
 61.  def spin(sec): f (<frame of spin>, 'call', ...) t = time.time() while time.time() - t < sec: pass f (<frame of spin>, 'return', ...) def spin5(): f (<frame of spin5>, 'call', ...) spin(5) f (<frame of spin5>, 'return', ...)
 62.  frame • f_back • f_code • f_lineno 상위 frame code • co_name • co_filename <frame>
 63.  frame • f_back • f_code • f_lineno frame frame frame top-frame stack = deque() while frame is not None: stack.appendleft(frame) frame = frame.f_back
 64.  요구사항 콜스택 계층구조 보존 gevent 호환 대화식 뷰어 실시간 프로파일링
65.  Greenlet 문맥 추적 greenlet.settrace( f )
 66.  # gevent-example.py import gevent def slower(): for x in range(4): for y in range(10000000): pass gevent.sleep(0) def faster(): for x in range(2): for y in range(10000000): pass gevent.sleep(0) gevent.spawn(slower) gevent.spawn(faster) gevent.wait() slower ＜ faster (약 2배) Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/gevent_example.py
 67.  slowerHub faster
 68.  slowerHub faster f ('switch', (Hub, slower)) f ('switch', (slower, Hub)) f ('switch', (Hub, faster)) f ('switch', (faster, Hub)) f ('switch', (Hub, slower))
 69.  slower faster
 70.  함수 Exclusive Inclusive slower 0.424 0.641 faster 0.212 0.429
 71.  요구사항 콜스택 계층구조 보존 gevent 호환 대화식 뷰어 실시간 프로파일링
72.  대화식 뷰어는 TUI로
73.  Curses
 74.  Urwid • TUI 라이브러리 • 위젯 단위 • TreeListBox • Curses의 저주에서 구원
75.  Exclusive Inclusive Profiling OWN DEEP Yappi tsub ttot profile tottime cumtime
 76.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/interactive.gif
 77.  요구사항 콜스택 계층구조 보존 gevent 호환 대화식 뷰어 실시간 프로파일링
78.  뷰어 Pickle 프로그램 프로파일링 서버 측정 측정 측정
79.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/continuous.gif
 80.  요구사항 콜스택 계층구조 보존 gevent 호환 대화식 뷰어 실시간 프로파일링
81.  느리다!
82.  특히 YAML 파싱
83.  def f(): pass def shallow(n): for x in range(n): f() def deep(n): if n != 0: deep(n - 1) Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/subcalls_example.py
 84.  def f(): pass def shallow(n): for x in range(n): f() def deep(n): if n != 0: deep(n - 1)
 85.  def f(): pass def shallow(n): for x in range(n): f() def deep(n): if n != 0: deep(n - 1)
 86.  shallow(100) deep(100) 그냥 실행 0.01 0.02 Profiling 2.27 6.07 Yappi 0.07 0.07 cProfile 0.60 0.61 profile 1.26 1.25 (단위: ㎳)
87.  http://goo.gl/Wjc7Jc
 88.  통계적 프로파일링
89.  이벤트 기반 프로파일링 • 실행 시간, 호출 횟수 측정 • 이벤트 전수 조사 e.g. profile, hotshot, Yappi, line_profiler 통계적 프로파일링 • 상대적 실행 빈도 측정 • 표본 조사 e.g. pyinstrument, plop, pprofile
 90.  통계적 프로파일링 • 샘플링 할 때 실행 중이던 콜스택을 조사 • Exclusive Count ― 콜스택 말단이던 횟수 • Inclusive Count ― 콜스택에 속했던 횟수
91.  def spin(sec): t = time.time() while time.time() - t < sec: pass def spin5(): spin(5) spin5() Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/spin_example.py
 92.  spin5() spin(5) Exclusive Count = 1 Inclusive Count = 1 Inclusive Count = 2 Inclusive Count = 3 Inclusive Count = 4 Exclusive Count = 3 Inclusive Count = 3 Exclusive Count = 2 Inclusive Count = 2 Exclusive Count = 1 Inclusive Count = 1
 93.  함수 Exclusive % Inclusive % spin5 25% (1/4) 100% (4/4) spin 75% (3/4) 75% (3/4)
 94.  요구사항 #2 이벤트 기반 프로파일링 통계적 프로파일링
95.  표본 얻기 sys._current_frames() 스레드 별 <frame> dict
 96.  주기적 조사 signal.setitimer(ITIMER_PROF, t, t) CPU 시간이 t만큼 흐를 때마다 SIGPROF 발동
97.  시그널 • time.sleep()을 끊는다. • IOError: EINTR • thread.join() 중엔 발동하지 않는다.
98.  pyinstrument가 쓰는 다른 방법 sys.setprofile(f) threading.setprofile(f) 추적 함수에서 시간을 재다가 때가 되면 조사 앞 방법 보단 느리다.
99.  shallow(100) deep(100) 그냥 실행 0.01 0.02 setitimer로 샘플링 0.01 0.02 setprofile로 샘플링 0.19 0.22 Profiling 2.27 6.07 Yappi 0.07 0.07 cProfile 0.60 0.61 profile 1.26 1.25 (단위: ㎳)
100.  요구사항 #2 이벤트 기반 프로파일링 통계적 프로파일링
101.  사용법
102.  $ pip install git+https://github.com/what-studio/profiling.git
 103.  $ python -m profiling COMMAND • profile • live-profile • remote-profile • view
 104.  $ python -m profiling profile SCRIPT Yappi, profile/cProfile 커맨드 처럼 스크립트 통째로 분석
105.  -T --timer= • basic • thread • greenlet -S --sampler= • itimer signal.setitimer • tracing sys.setprofile, threading.setprofile 통계적 프로파일링 SamplingProfiler 이벤트 기반 프로파일링 TracingProfiler
 106.  -T (이벤트 기반 프로파일링) -S (통계적 프로파일링)
107.  $ python -m profiling live-profile SCRIPT 스크립트를 돌리면서 실시간 분석 -i 갱신 주기 (기본: 1초)
108.  $ python -m profiling remote-profile SCRIPT 스크립트를 돌리다가 뷰어가 붙으면 분석 --bind 서버 엔드포인트 (기본: 127.0.0.1:8912)
 109.  $ python -m profiling view HOST:PORT 대화식 뷰어로 분석결과 보기
110.  H J K L Q ^C [ ] 종료 탐색 (포커스 이동) 접기/펼치기 정렬 기준 변경 갱신 중지/재개 조작법
111.  # facweb.py from flask import Flask app = Flask(__name__) @app.route('/<int:n>') def fac(n): r = 1 for x in range(2, n + 1): r *= x return str(r) app.run(port=8080) Py https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/facweb.py
 112.  웹 서버 HTTP 클라이언트 프로파일링 뷰어
113.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/remote.gif
 114.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/remote.gif
 115.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/remote.gif
 116.  GIF https://github.com/sublee/pyconkr2015-profiling-resources/blob/master/remote.gif
 117.  $ python -m profiling COMMAND • profile • live-profile • remote-profile • view
 118.  what-studio/profiling
 119.  마무리
120.  profile cProfile Yappi Profiling gevent 호환     콜스택     성능    / 완성도     실시간     UX    
121.  2.2k • 3회
122.  함께 해요 Issues Pull requests @falsetru @dahlia @Parkayun @kxepal @ravipudi @lqez @ivuk @sickill @htch
 123.  그밖에 다른 프로파일러들 • line_profiler • memory_profiler • pyinstrument • plop • pprofile
 124.  그밖에 • <Profiling (computer programming)> Wikipedia • http://goo.gl/qeblxo • <What are Exclusive and Inclusive?> Steve Carroll • http://goo.gl/KCysud • <What are Exclusive and Inclusive?> Steve Carroll • http://goo.gl/KCysud • <Beginners Guide to Performance Profiling> MSDN • https://goo.gl/f9Oej9 • <Profiling tools> Alain Leufroy • https://goo.gl/YxcVWF
 125.  함께 해요 #2
 126.  질의응답