Pythonのloggingはとても便利です．
logging --- Python 用ロギング機能 — Python 3.9.1 ドキュメント
logging.debug(msg, *args, **kwargs)関数には便利なキーワード引数が存在します．
stack_info
logging.info("test", stack_info=True)
これだけで，スタック情報がロギングメッセージに追加されます．例えば，興味がある関数が複数回呼び出される原因を同定したい時に便利です．
DjangoのModel.save()が複数回呼び出されてデータベースのアクセスが無駄に多い原因を調べる時は，以下のようになります．
class AppleModel(models.Model): def save(self, *args, **kwargs): logger.info("save()", stack_info=True) super().save(self, *args, **kwargs)
これを実行すると，以下のようになりました．
2021-02-09 15:02:16,709 INFO: save()
Stack (most recent call last):
...
File "/app/utils/views.py", line 56, in perform_create
serializer.save(owner=owner)
File "/opt/venv/lib/python3.8/site-packages/rest_framework/serializers.py", line 205, in save
self.instance = self.create(validated_data)
File "/app/apple/views.py", line 34, in create
return AppleModel.objects.create(
File "/opt/venv/lib/python3.8/site-packages/django/db/models/manager.py", line 85, in manager_method
return getattr(self.get_queryset(), name)(*args, **kwargs)
File "/opt/venv/lib/python3.8/site-packages/django/db/models/query.py", line 447, in create
obj.save(force_insert=True, using=self.db)
File "/app/apple/models.py", line 69, in save
logger.info("save()", stack_info=True)
File "/app/utils/views.py", line 143, in perform_update
serializer.save()
File "/opt/venv/lib/python3.8/site-packages/rest_framework/serializers.py", line 200, in save
self.instance = self.update(self.instance, validated_data)
File "/app/apple/views.py", line 69, in update
instance.save()
File "/app/apple/models.py", line 69, in save
logger.info("save()", stack_info=True)
これをみれば，AppleModel.objects.create()関数がsave()を呼び出し，自分が作成したviewsでもsave()を呼び出しているため，2回実行されていることが分かります．
Djangoのドキュメントにも，同じことが記載されています．
QuerySet API reference | Django documentation | Django
stacklevel
1より大きい数値を指定すると，その数だけスタックがスキップされます．
この機能を使うには，loggingのフォーマットを'{asctime} {levelname} {filename}-{lineno}: {message}'と設定して，ファイル名と行番号を表示するようにします．
logger.info("save()", stacklevel=1)
とデフォルトの状態で実行すると，以下のようにlogger.info()が存在するファイル名と行番号が表示されます．
2021-02-09 15:18:33,334 INFO models.py-69: save()
stacklevelを変更すると，logger.info()を呼び出した関数のファイル名と行番号に変わりました．
logger.info("save()", stacklevel=2)
2021-02-09 15:17:48,146 INFO views.py-69: save()
呼び出し元が重要なデバッグでは，このようにstacklevelを指定することで，ソースコードを目で追いかける必要がなくなります．
これ以外にも，exc_infoやextraという引数が存在し，ドキュメントに詳しく記載されています．
logging --- Python 用ロギング機能 — Python 3.9.1 ドキュメント
デバッグを効率よく行うためにも，これらの機能を積極的に活用していきたいと思います．
