プロファイラを使ってPythonアプリをチューニングしよう

PyConKyushu 2024 での発表資料です。
https://kyushu.pycon.jp/2024/

Transcript

1. プロファイラを使って Pythonアプリを チューニングしよう PyCon Kyushu 2024 岡野真也 PyConKyushu 2024 @tokibito
2. お前誰よ？ • 岡野真也 • @tokibito • 株式会社ObotAI 取締役CTO • 株式会社オープンコレクター 取締役 • Djangoフレームワークを長く使ってます！ • 東京から来ました PyConKyushu 2024 @tokibito
3. 今日のテーマ プロファイラを使って Pythonアプリを チューニングしよう PyConKyushu 2024 @tokibito
4. プロファイラ • cProfile • 標準モジュール • https://docs.python.org/ja/3 /library/profile.html • プロファイル(統計情報)を取 得する • 関数がどれだけ呼ばれたか • 実行時間どのぐらいかかったか PyConKyushu 2024 @tokibito
5. アプリのチューニングとは？ • コードや設定を変更し、性能を調整・向上 PyConKyushu 2024 @tokibito
6. アプリの性能とは？ • 性能を表す指標 • 処理速度 • 処理時間、単位時間あたりの処理数… • リソース使用量 • CPU、メモリ、ディスク、ネットワーク… PyConKyushu 2024 @tokibito
7. 今回注目すること • 性能を表す指標 • 処理速度 • 処理時間、単位時間あたりの処理数… • リソース使用量 • CPU、メモリ、ディスク、ネットワーク… PyConKyushu 2024 @tokibito
8. アプローチ手順 1. プロファイルを取得する（原因調査） 2. 原因を特定する 3. コードを変更する 4. プロファイルを取得する（結果の確認） PyConKyushu 2024 @tokibito
9. やってみる PyConKyushu 2024 @tokibito
10. アプリ1: read_file.py import datetime import timeit DATA_FILE = "data.jsonl" def main(): """ファイルの行数をカウントするスクリプト""" print("start:", datetime.datetime.now()) result = 0 with open(DATA_FILE) as input_file: for line in input_file: result += 1 print(f"result: {result} lines") print("end:", datetime.datetime.now()) if __name__ == "__main__": print(timeit.timeit(main, number=10)) PyConKyushu 2024 @tokibito • ファイルの行数をカウントする • data.jsonlは550MBぐらいのファイル • 1000万行 • わかりやすくするためにtimeitで10回実行 します
11. cProfileでプロファイルを取得 $ python -m cProfile -o read_file.profile read_file.py PyConKyushu 2024 @tokibito スクリプト全体のプロファイルを取る $ python -m pstats read_file.profile Welcome to the profile statistics browser. read_file.profile% stats プロファイル結果を読む
12. プロファイル結果 1414104 function calls (1414091 primitive calls) in 9.381 seconds Random listing order was used ncalls tottime percall cumtime percall filename:lineno(function) 12 0.000 0.000 0.000 0.000 {method 'get' of 'dict' objects} 4 0.000 0.000 0.000 0.000 {method 'pop' of 'dict' objects} 8 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects} 4 0.000 0.000 0.000 0.000 {method 'pop' of 'list' objects} PyConKyushu 2024 @tokibito 呼び出し数 合計時間 この関数だけ 累積時間 呼出先含む tottime /ncalls cumtime /ncalls
13. 原因を特定する read_file.profile% sort tottime read_file.profile% stats Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 10 8.186 0.819 9.380 0.938 read_file.py:7(main) 706670 0.929 0.000 0.929 0.000 {built-in method _codecs.utf_8_decode} 706670 0.257 0.000 1.186 0.000 <frozen codecs>:319(decode) 31 0.007 0.000 0.007 0.000 {built-in method builtins.print} 10 0.001 0.000 0.001 0.000 {built-in method _io.open} 20 0.000 0.000 0.000 0.000 {built-in method now} 2 0.000 0.000 0.000 0.000 {built-in method _imp.create_builtin} 12 0.000 0.000 0.000 0.000 {method '__exit__' of '_io._IOBase' objects} PyConKyushu 2024 @tokibito 各カラムでソートして、異常値を探す utf8デコードの処理が回数多くて遅そう？
14. アプリ1改善: read_file_optimized.py import datetime import timeit DATA_FILE = "data.jsonl" def main(): """ファイルの行数をカウントするスクリプト""" print("start:", datetime.datetime.now()) result = 0 with open(DATA_FILE, "rb") as input_file: while True: data = input_file.read(1024 * 1024) if not data: break result += data.count(b"¥n") print(f"result: {result} lines") print("end:", datetime.datetime.now()) if __name__ == "__main__": print(timeit.timeit(main, number=10)) PyConKyushu 2024 @tokibito • ファイルの読み込みモードを rb （バイナ リ読み込み）に変更 • ファイルは1MBずつ読む • 改行コードをcountメソッドで数える
15. プロファイルを再取得（結果の確認） $ python -m cProfile -o read_file_optimized.profile read_file_optimized.py PyConKyushu 2024 @tokibito スクリプト全体のプロファイルを取る $ python -m pstats read_file_optimized.profile Welcome to the profile statistics browser. read_file_optimized.profile% stats プロファイル結果を読む 実行時間は、10秒→5秒ぐらいに高速化
16. 再取得したプロファイルを確認 Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 5530 4.171 0.001 4.171 0.001 {method 'count' of 'bytes' objects} 5542 0.853 0.000 0.853 0.000 {method 'read' of '_io.BufferedReader' objects} 10 0.009 0.001 5.035 0.504 read_file_optimized.py:7(main) 31 0.001 0.000 0.001 0.000 {built-in method builtins.print} 10 0.000 0.000 0.000 0.000 {built-in method _io.open} 20 0.000 0.000 0.000 0.000 {built-in method now} 12 0.000 0.000 0.000 0.000 {method '__exit__' of '_io._IOBase' objects} 2 0.000 0.000 0.000 0.000 {built-in method _imp.create_builtin} PyConKyushu 2024 @tokibito 変更により遅かった処理（utf8デコード）がなくなったか確認 各カラムでソートして、異常値を探す bytesのcountが遅そう、とはいえ簡単な改善手段がなく諦め
17. アプリ1(行数カウント)の改善まとめ • 実行時間: 10秒→5秒 • やったこと • プロファイルを取得 • 原因特定 • テキストモードで読込みだとutf8デコードが遅そうだった • コード変更 • バイナリモードに変更、countメソッドでカウント • プロファイル再取得 • 該当のutf8デコードの処理がなくなったことを確認 PyConKyushu 2024 @tokibito
18. アプリ2: check_unique.py import json import datetime DATA_FILE = "data.jsonl" def main(): """ファイル内のUUIDに重複がないか検証するスクリプト""" print("start:", datetime.datetime.now()) uuids = set() with open(DATA_FILE) as input_file: records = input_file.read().splitlines() print("read file finished.") for line in records: data = json.loads(line) value = data["value"] if value in uuids: print(f"UUIDの重複が見つかりました: {line}") break uuids.add(value) print("end:", datetime.datetime.now()) if __name__ == "__main__": main() PyConKyushu 2024 @tokibito • JSONLファイル内のvalue(UUID)の重複 がないかチェックする • data.jsonlは550MBぐらいのファイル • 1000万行 {"id":2478416,"value":"612934e07b584dbdb5d8653eb81fc5c7"} {"id":5050349,"value":"ea56ac5c9fb54f8fb8236b91695bbae9"} {"id":3207974,"value":"a8bccb8160be443ea3e7c7efd466379f"}
19. cProfileでプロファイルを取得 $ python -m cProfile -o check_unique.profile check_unique.py PyConKyushu 2024 @tokibito スクリプト全体のプロファイルを取る $ python -m pstats check_unique.profile Welcome to the profile statistics browser. check_unique.profile% stats プロファイル結果を読む
20. プロファイル結果 110003471 function calls (110003351 primitive calls) in 58.260 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 6/1 0.000 0.000 58.260 58.260 {built-in method builtins.exec} 1 1.511 1.511 58.260 58.260 check_unique.py:1(<module>) 1 10.714 10.714 56.745 56.745 check_unique.py:7(main) 10000000 6.957 0.000 39.572 0.000 /usr/lib/python3.12/json/__init__.py:299(loads) 10000000 12.329 0.000 29.497 0.000 /usr/lib/python3.12/json/decoder.py:332(decode) 10000000 7.410 0.000 7.410 0.000 /usr/lib/python3.12/json/decoder.py:343(raw_decode) 20000000 5.920 0.000 5.920 0.000 {method 'match' of 're.Pattern' objects} 20000000 2.669 0.000 2.669 0.000 {method 'end' of 're.Match' objects} 10000000 2.299 0.000 2.299 0.000 {method 'add' of 'set' objects} PyConKyushu 2024 @tokibito 呼び出し数 合計時間 この関数だけ 累積時間 呼出先含む tottime /ncalls cumtime /ncalls JSONの読込みが遅そう
21. アプリ2改善: check_unique_optimized.py import orjson import datetime DATA_FILE = "data.jsonl" def main(): """ファイル内のUUIDに重複がないか検証するスクリプト""" print("start:", datetime.datetime.now()) uuids = set() with open(DATA_FILE) as input_file: records = input_file.read().splitlines() print("read file finished.") for line in records: data = orjson.loads(line) value = data["value"] if value in uuids: print(f"UUIDの重複が見つかりました: {line}") break uuids.add(value) print("end:", datetime.datetime.now()) if __name__ == "__main__": main() PyConKyushu 2024 @tokibito • JSONの読み込みをorjsonに変更 • https://pypi.org/project/orjson/
22. プロファイルを再取得（結果の確認） $ python -m cProfile -o check_unique_optimized.profile check_unique_optimized.py PyConKyushu 2024 @tokibito スクリプト全体のプロファイルを取る $ python -m pstats check_unique_optimized.profile Welcome to the profile statistics browser. check_unique_optimized.profile% stats プロファイル結果を読む 実行時間は、58秒→14秒ぐらいに高速化
23. 再取得したプロファイルを確認 20007696 function calls (20007461 primitive calls) in 14.734 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 16/1 0.000 0.000 14.734 14.734 {built-in method builtins.exec} 1 1.705 1.705 14.734 14.734 check_unique_optimized.py:1(<module>) 1 6.608 6.608 12.992 12.992 check_unique_optimized.py:7(main) 10000000 3.087 0.000 3.087 0.000 {orjson.loads} 10000007 1.744 0.000 1.744 0.000 {method 'add' of 'set' objects} 1 0.937 0.937 0.937 0.937 {method 'splitlines' of 'str' objects} 1 0.328 0.328 0.615 0.615 {method 'read' of '_io.TextIOWrapper' objects} 1 0.000 0.000 0.287 0.287 <frozen codecs>:319(decode) 1 0.287 0.287 0.287 0.287 {built-in method _codecs.utf_8_decode} PyConKyushu 2024 @tokibito JSONの読込み速度は大幅改善となった様子
24. アプリ3: call_api.py PyConKyushu 2024 @tokibito import datetime import httpx url = "http://127.0.0.1:5000/delay/1" def main(): """API呼び出しを10回実行 """ print("start:", datetime.datetime.now()) for i in range(10): response = httpx.get(url) print(response.status_code, response.json()) print("end:", datetime.datetime.now()) if __name__ == "__main__": main() • 応答に1秒かかるAPI • 10回呼び出す • このAPIは並列で呼び出してもよい • テスト用APIはhttpbin使用 • https://pypi.org/project/httpbin/ • gunicorn --threads=10 -b=127.0.0.1:5000 httpbin:app
25. プロファイル結果 174725 function calls (169945 primitive calls) in 10.907 seconds Ordered by: internal time List reduced from 1876 to 10 due to restriction <10> ncalls tottime percall cumtime percall filename:lineno(function) 12 10.153 0.846 10.153 0.846 {method 'recv' of '_socket.socket' objects} 10 0.521 0.052 0.521 0.052 {method 'load_verify_locations' of '_ssl._SSLContext' objects} 192 0.017 0.000 0.017 0.000 {built-in method marshal.loads} 873/768 0.010 0.000 0.012 0.000 {built-in method __new__ of type object at 0xa2c960} 635/611 0.008 0.000 0.030 0.000 {built-in method builtins.__build_class__} 278/1 0.007 0.000 10.907 10.907 {built-in method builtins.exec} PyConKyushu 2024 @tokibito 呼び出し数 合計時間 この関数だけ 累積時間 呼出先含む tottime /ncalls cumtime /ncalls socketのrecvが遅い=ネットワーク通信の応答が遅い
26. アプリ3改善: call_api_optimized.py import datetime import asyncio import httpx url = "http://127.0.0.1:5000/delay/1" async def main(): """API呼び出しを10回実行 """ print("start:", datetime.datetime.now()) requests = [] async with httpx.AsyncClient() as client: for i in range(10): requests.append(client.get(url)) responses = await asyncio.gather(*requests) for response in responses: print(response.status_code, response.json()) print("end:", datetime.datetime.now()) if __name__ == "__main__": asyncio.run(main() • httpxの非同期IOクライアントを使って並列でAPI を呼び出し • すべてのレスポンスが完了するまで asyncio.gatherで待つ PyConKyushu 2024 @tokibito
27. プロファイルを再取得（結果の確認） $ python -m cProfile -o call_api.profile call_api.py PyConKyushu 2024 @tokibito スクリプト全体のプロファイルを取る $ python -m pstats call_api_optimized.profile Welcome to the profile statistics browser. call_api_optimized.profile% stats プロファイル結果を読む 実行時間は、10秒→1.3秒ぐらいに高速化
28. プロファイル結果 202157 function calls (197091 primitive calls) in 1.357 seconds Ordered by: internal time List reduced from 2319 to 10 due to restriction <10> ncalls tottime percall cumtime percall filename:lineno(function) 39 0.999 0.026 0.999 0.026 {method 'poll' of 'select.epoll' objects} 1 0.049 0.049 0.049 0.049 {method 'load_verify_locations' of '_ssl._SSLContext' objects} 221 0.033 0.000 0.033 0.000 {method 'read' of '_io.BufferedReader' objects} 221 0.024 0.000 0.024 0.000 {built-in method marshal.loads} 221 0.015 0.000 0.015 0.000 {built-in method _io.open_code} PyConKyushu 2024 @tokibito 呼び出し数 合計時間 この関数だけ 累積時間 呼出先含む tottime /ncalls cumtime /ncalls ネットワーク通信で待つ部分がほとんどなくなった
29. ここまでのまとめ – アプリ1～3 • Pythonスクリプトのプロファイル取得と高速化 • cProfileモジュールでプロファイル取得 • pstatsモジュールでプロファイル閲覧・原因特定 • コードを変更したら再度プロファイル取得 PyConKyushu 2024 @tokibito
30. ウェブアプリの場合 PyConKyushu 2024 @tokibito
31. 指定範囲のコードのプロファイル取得 import cProfile with cProfile.Profile() as pr: # プロファイル対象のコードここから call_api_main() # プロファイル対象のコードここまで pr.dump_stats("webapp.profile") # 結果をファイルに保存 • ウェブアプリやフレームワー クを使ったアプリの場合 • 全体のプロファイルだと不要な 部分が多くて分析が大変 • 指定範囲のみのプロファイルを 取得する PyConKyushu 2024 @tokibito
32. アプリ4: webapp.py PyConKyushu 2024 @tokibito from flask import Flask from call_api import main as call_api_main app = Flask(__name__) @app.route("/") def index(): import cProfile with cProfile.Profile() as pr: # プロファイル対象のコードここから call_api_main() # プロファイル対象のコードここまで # 結果をファイルに保存 pr.dump_stats("webapp.profile") return "Finished" • Flaskを使ったウェブアプリ • call_api_main関数は前述のア プリ3と同じ
33. ウェブアプリのプロファイルを取得 $ flask --app webapp:app run -p 8000 PyConKyushu 2024 @tokibito Flaskのアプリを起動する（8000番ポート） $ python -m pstats webapp.profile Welcome to the profile statistics browser. webapp.profile% stats プロファイル結果を読む ブラウザで http://localhost:8000/ にアクセス ※内容はアプリ3と同じ
34. Djangoの場合 • django-debug-toolbar • https://pypi.org/project/djang o-debug-toolbar/ • アクセスしたURLのプロファイ ルをすぐに確認できる PyConKyushu 2024 @tokibito
35. ここまでのまとめ – ウェブアプリ • ウェブアプリのプロファイル取得 • cProfileモジュールを使って、指定した範囲のプロファイルを取得でき る • Djangoの場合はdjango-debug-toolbarを使うと簡単にプロファイルを 取得できる PyConKyushu 2024 @tokibito
36. サードパーティモジュール • プロファイル • Scalene • プロファイラ • SnakeViz • 可視化 • gprof2dot • 可視化 PyConKyushu 2024 @tokibito
37. 業務ではどうするか PyConKyushu 2024 @tokibito
38. システムに必要な性能を考える • 考えること • どのぐらいのデータ量を処理できる必要がある？ • どのぐらいの速度で処理できる必要がある？ • 必要な性能について取り決めたもの→性能要件 • 性能要件が決まっていないと • そもそも性能の向上って必要なの？ • どこまで性能を向上させればいいの？ PyConKyushu 2024 @tokibito
39. 性能要件を決める • 感覚的に遅くて気になる、どのぐらいなら気にならない？ • システムとして成立する性能はどれぐらい？ • 1日かかってもOK？1秒で終わらないとだめ？ • ユーザー数やアクセス数はどのぐらいまでを想定？ • 現実的な性能にする • コンピューター、OSの限界より速い処理は無理 PyConKyushu 2024 @tokibito
40. 業務では性能要件を満たすことが重要 • 性能要件を満たしていれば、それ以上のチューニングは必須で はない • 不要な最適化はコードが複雑化する可能性もあるので注意 • 現実的な性能要件ではないと分かったら、性能要件を見直す PyConKyushu 2024 @tokibito
41. チューニングのおすすめアプローチ • 効果がありそうなもの・手軽なものから試す • 大幅な設計変更が必要なアプローチ • 工数へのインパクトが大きいものは慎重に検討 • 要件の見直しも含めて検討 PyConKyushu 2024 @tokibito
42. 性能を上げる方法は色々ある • ソフトウェアのコードを変更して性能を上げる • →ここまで説明してきた方法 • ハードウェアを変更して性能を上げる • コードを変更しないで、実行環境の性能を上げる • 利点: コードの変更が不要 • 欠点: お金がかかる PyConKyushu 2024 @tokibito
43. 遅くなりやすいポイント • メモリー • メモリーが足りないとスワップ領域を使って遅くなる • CPU • 計算処理が多いと遅くなる • ディスクIO • アクセス頻度や転送量が多いと遅くなる • ネットワークIO • アクセス頻度や転送量が多いと遅くなる PyConKyushu 2024 @tokibito
44. メモリーが足りない場合は致命的 • メモリーが足りないとスワップ領域が使われて遅くなる • 実行中のアプリ以外のプロセスが遅くなったりもする • CPU使用率、ディスクIOも増加する • ＝遅い原因の特定が難しくなる • 明らかにメモリーが足りない場合 • 割当メモリー量を増やす • 省メモリーのアルゴリズム・コードに変更する • メモリー不足はなるべく最初に解決する PyConKyushu 2024 @tokibito
45. より複雑な問題への アプローチ PyConKyushu 2024 @tokibito
46. 特定条件の場合のみ遅い • 特定のユーザー、特定のデータの場合だけ遅い • アプローチ • if文などで条件指定したうえで、プロファイルを部分的に取得するコー ドを仕込む PyConKyushu 2024 @tokibito
47. 複雑なアプリの場合 • 複数のプロセス・ホスト・サブシステムにまたがって動作する アプリ • 問題が複雑化する • １つのプロセスのプロファイルを取るだけでは原因特定が難しい • システム全体から統合的にプロファイルを取得、原因特定する • 検索キーワード • 分散トレーシング • APM（Application Performance Monitoring） • OpenTelemetry、Observability PyConKyushu 2024 @tokibito
48. 遅い原因の勘どころを 身につけるには？ PyConKyushu 2024 @tokibito
49. OSの挙動を知っておく • プログラムが動作する仕組み • OSの提供する機能 • OSとアプリケーションとの役割分担 PyConKyushu 2024 @tokibito
50. Pythonやライブラリの挙動を知っておく • 目的の処理が動作するまでの内部ロジック、アルゴリズム • どういった操作が速くて、どういった操作が遅いのか • ソースコードを読む PyConKyushu 2024 @tokibito
51. 補足資料など • 本資料のサンプルコード • https://github.com/tokibito/pyconkyushu2024 PyConKyushu 2024 @tokibito