はじめに

自動テストで実行される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の異常終了が発生してから、状況調査を段階的に進めて原因特定をするまでの調査方法について記載してみました。
調査において、段階を踏んで原因範囲を絞り込んでいく際の参考にしていただければ幸いです。