はじめに
自動テストで実行されるpytestで発生した強制エラーが発生した際の調査方法について記載したいと思います。
エラー内容
$ ./run_ci_tests
(ログ抜粋)
……
tests/models/test_event_xxxx1.py ssssssss
tests/models/test_event_xxxx2.py ssssssssssssss
tests/models/test_event_xxxx3.py sssssssssss
./run_ci_tests: line xx: 24639 Killed
テストに不備はないですが、プロセス終了されている状態が発生しました。(プロセスkill発生)
テスト実行環境を確認しながら調査を実施していきます。
テスト実行環境のCPU/メモリ状態確認
テスト実行前と実行後のCPU/メモリ状態をtopコマンドで確認していきます。
テスト 実行前
Mem: 2057192k total, 1152792k used, 904400k free, 30388k buffers
Swap: 0k total, 0k used, 0k free, 169732k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4876 kg_game3 20 0 274m 148m 9.9m R 87.9 7.4 0:28.96 flask
82 root 0 -20 0 0 0 S 0.3 0.0 0:02.76 kworker/0:1H
1484 root 20 0 61572 3288 384 S 0.3 0.2 0:00.21 uwsgi
1 root 20 0 28700 3396 1616 S 0.0 0.2 0:05.15 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
テスト 実行中 (エラー発生)
Mem: 2057192k total, 1990684k used, 66508k free, 64k buffers
Swap: 0k total, 0k used, 0k free, 10740k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
5496 kg_game3 20 0 1400m 1.1g 0 D 59.9 56.4 7:01.40 python
1099 mysql 20 0 1013m 304m 0 S 3.9 15.1 0:28.09 mysqld
25 root 20 0 0 0 0 S 3.6 0.0 0:22.39 kswapd0
1187 7013 20 0 36232 1676 328 D 0.6 0.1 0:05.76 redis-server
82 root 0 -20 0 0 0 S 0.3 0.0 0:03.64 kworker/0:1H
メモリの消費が増えているのでfreeコマンドでメモリ状態をもう少し確認していきます。
テスト実行環境のメモリ状態の追加確認
テスト 実行前
total used free shared buffers cached
Mem: 2008 828 1180 0 6 33
Low: 2008 828 1180
High: 0 0 0
-/+ buffers/cache: 788 1220
Swap: 0 0 0
Total: 2008 828 1180
テスト 実行中 (エラー発生)
total used free shared buffers cached
Mem: 2008 1939 69 0 0 13
Low: 2008 1939 69
High: 0 0 0
-/+ buffers/cache: 1926 82
Swap: 0 0 0
Total: 2008 1939 69
free コマンドの情報から、メモリ割り当てが出来ていない状態までメモリ使用が行われているようです。pythonスクリプトのどの処理がメモリ増加に影響しているか tracemalloc を使用 して更に確認していきます。
tracemalloc による メモリを割り当て確認
pytest 実行箇所にメモリブロックをトレースするためのデバッグを組み込みます。
import tracemalloc
tracemalloc.start()
# ... run pytest ...
snapshot = tracemalloc.take_snapshot()
top_stats = snapshot.statistics('lineno')
for stat in top_stats[:10]:
print(stat)
テスト 実行中 (エラー発生)
[ Top 10 differences ]
<frozen importlib._bootstrap_external>:476: size=28.5 MiB (+28.5 MiB), count=283755 (+283755), average=105 B
/workspace/lib/python3.x/site-packages/werkzeug/routing.py:613: size=22.3 MiB (+22.3 MiB), count=210500 (+210500), average=111 B
/workspace/lib/python3.x/site-packages/werkzeug/routing.py:600: size=20.9 MiB (+20.9 MiB), count=132799 (+132799), average=165 B
/workspace/lib/python3.x/site-packages/werkzeug/routing.py:702: size=15.0 MiB (+15.0 MiB), count=70105 (+70105), average=224 B
/workspace/lib/python3.x/site-packages/werkzeug/routing.py:622: size=14.7 MiB (+14.7 MiB), count=69000 (+69000), average=224 B
...
- werkzeug/routing.py:613 (werkzeug)
Rule(RuleFactory) クラスのインスタンス変数 methods 設定箇所
610 if methods is None:
611 self.methods = None
612 else:
613 self.methods = set([x.upper() for x in methods])
614 if 'HEAD' not in self.methods and 'GET' in self.methods:
615 self.methods.add('HEAD')
デバッグログ内容からルーティングのルールの処理が影響していることがわかります。
調査結果
調査結果 (調査情報からの考察)
- pytest実行時、Flaskインスタンス生成後、設定しているルーティング情報が保持されたままテスト実行が進む事象が発生していた
対策
- pytest実行時の、Flaskインスタンス生成処理でルーティング情報を設定しないようにテストコードを修正することによって対処
結果
- エラー発生(プロセスkill発生)が発生せず、pytest実行の正常終了を確認
おわりに
今回は、pytestの異常終了が発生してから、状況調査を段階的に進めて原因特定をするまでの調査方法について記載してみました。
調査において、段階を踏んで原因範囲を絞り込んでいく際の参考にしていただければ幸いです。