最近の砂場でのpythonのサンプルコードの実行方法について

日記的なrepositoryを作っていて、何か調べたいことがあったときにそこにサンプルコードを書いて調べたりしている。そのサンプルコードの書き方でdebugとinfoの実行形態を分ける方法が便利だったのでメモ。

趣旨

この方法の趣旨は以下のような感じ。

  • 通常は、INFOレベルでログが出れば良い
  • 時折、詳しく調べたいときにDEBUGレベルのログを出したい

そしてこれらを オプションの指定など無し で切り替えたい。

方法

今の所はMakefileを使っている。サンプルコードのファイル名を概ね"\d{2}\S+.py"みたいな名前にしている(e.g. "00sample.py", "11app.py")。

そしてMakefileは以下の様な形にすると良さそうなことに気づいた(各タスクは手書きしている。その方が管理しやすい気がしている。時折、特定のタスクだけ実行するコマンドも変えたいときがあるので)。

PYTHON ?= LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default

00:
  ${PYTHON} 00*.py
01:
  ${PYTHON} 01*.py
02:
  ${PYTHON} 02*.py
03:
  ${PYTHON} 03*.py

実行するときは以下の様に。

# 通常の実行
$ python 00*.py

# 詳細な出力が欲しい場合の実行
$ make 00

実行例

そして具体的には以下の様なコードを書く。

00hello.py

import os
import logging
logger = logging.getLogger(__name__)


def main():
    logger.debug("debug message1")
    logger.info("hello")
    logger.debug("debug message2")


# 丁寧にmain()を定義したり__name__のifを付けない場合もある
if __name__ == "__main__":
    logging.basicConfig(level=getattr(logging, os.environ.get("LOGLEVEL", "INFO")))
    main()

このときの実行結果は以下の様な形。makeから実行したときだけdebug出力になる。

00hello.py

# 通常の実行
$ python 00*.py
INFO:__main__:hello

# 詳細な出力が欲しい場合の実行
$ make 00
LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default 00*.py
DEBUG:__main__:debug message1
INFO:__main__:hello
DEBUG:__main__:debug message2

最近気づいたのは、オプションの入力(--foo的なもの)を調整することすら面倒に感じることがあり、それらが不要な形にしておくとストレスが減るということだった。考えてみると、コンソール上でオプションを調節するためのカーソル移動がけっこうストレスだったりしたのかもしれない。

ただちょっとコード自体書くのが面倒な感じもするのでloggedpyを作ってみたのと同じ感じで短くできないかなと思ったりはしている(osとloggingのimportなくしたい)。

オプションの意味

python -W default

詳細な実行のときにはpython -W defaultの指定もあると便利(詳しくはドキュメントを)。色々なwarningをもう少し細かく教えてくれる。シェルのaliasに指定しても良い位かもしれない。

$ python 01*.py
9
01warning.py:8: DeprecationWarning: The 'warn' method is deprecated, use 'warning' instead
  logger.warn("xxxx")
WARNING:__main__:xxxx

$ make 01
LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default 01*.py
9
01warning.py:8: DeprecationWarning: The 'warn' method is deprecated, use 'warning' instead
  logger.warn("xxxx")
WARNING:__main__:xxxx
sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='01warning.py' mode='r' encoding='UTF-8'>

01warning.py

import os
import logging
logger = logging.getLogger(__name__)

logging.basicConfig(level=getattr(logging, os.environ.get("LOGLEVEL", "INFO")))
f = open(__file__)
print(len(f.read().split("\n")))
logger.warn("xxxx")

PYTHONASYNCIODEBUG=1

asyncioのコードを確認するときにはdebugを有効にしておいた方が良いこともある(詳しくはドキュメントを)。色々な情報を出力してくれたりするので。今見てみたら、python -X devと書いても大丈夫のようでこちらのほうが楽かもしれない。

$ python 02*.py
INFO:__main__:hello
00hello.py
01warning.py
02asyncio.py
Makefile

INFO:__main__:bye


$ make 02
LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default 02*.py
DEBUG:asyncio:Using selector: EpollSelector
INFO:__main__:hello
DEBUG:asyncio:run shell command 'sleep 1 && ls' stdout=<pipe> stderr=<pipe>
DEBUG:asyncio:process 'sleep 1 && ls' created: pid 12225
DEBUG:asyncio:Read pipe 6 connected: (<_UnixReadPipeTransport fd=6 polling>, <ReadSubprocessPipeProto fd=1 pipe=<_UnixReadPipeTransport fd=6 polling>>)
DEBUG:asyncio:Read pipe 8 connected: (<_UnixReadPipeTransport fd=8 polling>, <ReadSubprocessPipeProto fd=2 pipe=<_UnixReadPipeTransport fd=8 polling>>)
INFO:asyncio:run shell command 'sleep 1 && ls': <_UnixSubprocessTransport pid=12225 running stdout=<_UnixReadPipeTransport fd=6 polling> stderr=<_UnixReadPipeTransport fd=8 polling>>
DEBUG:asyncio:<Process 12225> communicate: read stdout
DEBUG:asyncio:<Process 12225> communicate: read stderr
INFO:asyncio:poll took 1000.727 ms: 1 events
INFO:asyncio:<_UnixReadPipeTransport fd=6 polling> was closed by peer
INFO:asyncio:<_UnixReadPipeTransport fd=8 polling> was closed by peer
DEBUG:asyncio:process 12225 exited with returncode 0
INFO:asyncio:<_UnixSubprocessTransport pid=12225 running stdout=<_UnixReadPipeTransport closed fd=6 closed> stderr=<_UnixReadPipeTransport closed fd=8 closed>> exited with return code 0
DEBUG:asyncio:<Process 12225> communicate: close stdout
DEBUG:asyncio:<Process 12225> communicate: close stderr
00hello.py
01warning.py
02asyncio.py
Makefile

INFO:__main__:bye
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>

02asyncio.py

import os
import logging
import asyncio
import subprocess
logger = logging.getLogger(__name__)

logging.basicConfig(level=getattr(logging, os.environ.get("LOGLEVEL", "INFO")))


async def main(n):
    logger.info("hello")
    await asyncio.sleep(n)
    p = await asyncio.create_subprocess_shell(
        "sleep 1 && ls",
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
    )
    print((await p.communicate())[0].decode("utf-8"))
    logger.info("bye")


loop = asyncio.get_event_loop()
loop.run_until_complete(main(0.1))
loop.close()

その他 python -X tracemalloc とか指定したくなることもあるかもしれない。あるいはPYTHONTRACEMALLOCだとか(指定可能な環境変数man pythonに載っている)。

pyinspectというものを地味に作っている

github.com

pyinspectというものを地味に作っている。まだrepository上には一切のドキュメントがないし正式なリリースをしたというわけでもないのでしばらくは個人用。

コードリーディングのお供に

元々の動機はコードリーディングをしようとしているときに生まれた。コードリーディングで最初に行いたい事はどのようなモジュールが提供されているか大まかに把握することなのだけれど。ぶっちゃけるとドキュメントに書いてあるモチベーションみたいなものを覗いたあとはすぐにどのようなモジュールが存在しているかの一覧さえ見えれば良い。

そして大まかな構造を把握した後に個々のモジュールがどのような機能を持つかというふうに進んでいく。このときに欲しかったけれど存在しなかったものが作りたいものと言うことになる。

そんなわけで作り方も同様で、コードリーディングをしていきながら、その最中で欲しかった機能を加えつつ使いつつという形で育てていきたい。

最初はモジュールの一覧から

はじめの段階でpip install <package>でインストールした時に全体としてどのようなパッケージがあるか分かりづらい。とりあえず提供されているモジュールの一覧が欲しかったりする。

例として starlette を使うことにする。このパッケージを選んだ理由は特に無いけれど。

$ pip install starlette

pyinspect listで提供されているモジュールの一覧が見れる。ネストした階層のものも見れるので便利(pydoc(python -m pydoc)で隣接した階層のモジュールの一覧は見れるけれど。ネストした階層のモジュールは見ることができない)。

$ pyinspect list starlette
starlette
starlette.applications
starlette.authentication
starlette.background
starlette.concurrency
starlette.config
starlette.convertors
starlette.database
starlette.datastructures
starlette.endpoints
starlette.exceptions
starlette.formparsers
starlette.graphql
starlette.middleware
starlette.middleware.authentication
starlette.middleware.base
starlette.middleware.cors
starlette.middleware.database
starlette.middleware.errors
starlette.middleware.gzip
starlette.middleware.httpsredirect
starlette.middleware.lifespan
starlette.middleware.sessions
starlette.middleware.trustedhost
starlette.middleware.wsgi
starlette.requests
starlette.responses
starlette.routing
starlette.schemas
starlette.staticfiles
starlette.status
starlette.testclient
starlette.types
starlette.websockets

全体のモジュールを一覧で眺めてみて興味のありそうなモジュールの中を覗いていく。

次は物理的な位置を知りたい

今度は中のコードを読むために物理的な位置が知りたくなる。エディタやIDEから頑張って探したり定義位置へのジャンプで移動することもあるけれど。直接シェルから開きたくなることもある。

$ pyinspect resolve starlette.middleware
~/venvs/my/lib/python3.7/site-packages/starlette/middleware

# その他お気に入りのコマンドで
$ alias e
alias e='emacsclient -n'
$ e $(pyinspect resolve starlette.middleware)

特定のクラスに対する関係性を知りたい

pydocやsphinxなどで生成されるAPIドキュメントはそのモジュールの特定のクラスなどに対する情報は事細かに載っているけれど。知りたい情報が存在していないこともある。

具体的には以下の様な情報が知りたくなる。

  • 継承関係の全体
  • 階層的な呼び出し関係

きれいな可視化が欲しいのではなく、地図のようなものが欲しい。

継承関係の全体

これは特にjupyter notebook関係のコードを読んでいるときに思ったことなのだけれど。結構継承関係が深い。そして最終的にはtraitletsという謎のライブラリにたどり着くのだけれど。全体の継承関係が追いきれずにわからなかったりする。もちろん全体の継承関係自体はコードを書けばすぐに調べられることではあるのだけれど。コードを書かずに把握したい。

例えば例としてあげたstarletteで実際に試してみると、OpenAPIResponseはResponseを継承していることが分かる。

$ pyinspect inspect starlette.schemas:OpenAPIResponse
starlette.schemas:OpenAPIResponse <- starlette.responses:Response <- builtins:object

.. 省略 ..

この継承の全体を表示してくれる機能は特に外部のライブラリのクラスを継承しているときなどに便利だったりする。たとえばTestClientはrequestsで提供されているクラスを継承している。

$ pyinspect inspect starlette.testclient:TestClient
starlette.testclient:TestClient <- requests.sessions:Session <- requests.sessions:SessionRedirectMixin <- builtins:object

.. 省略 ..

あー、なるほどSessionを継承して作られているんだな−、なるほどなーと言うことが分かる。

階層的な呼び出し関係

特に責務が分割されていないクラスなど機能を多く持ったクラスは異様に多くのメソッドを持っていたりする。それらのメソッドは内部でしか使われないものであったり、トップレベルから呼ばれるものであったりする。それらの内の幾文かはpublicとprivate(_で始まるメソッド名のもの)の紳士協定で把握は可能なもののもう少し絞り込みたくなる。

自分自身のメソッドのコードからASTを取り出して、自身の持つメソッドを呼んでいるというときの呼び出し関係を可視化してあげれば理解に役立ちそうと感じた。例えば以下のようにあるメソッドの内部で呼ばれているメソッドはインデントされて表示される。

$ pyinspect inspect starlette.responses:Response
starlette.responses:Response <- builtins:object
    [method, OVERRIDE] __call__(self, receive: Callable[[], Awaitable[MutableMapping[str, Any]]], send: Callable[[MutableMapping[str, Any]], Awaitable[NoneType]]) -> None
    [method, OVERRIDE] __init__(self, content: Any = None, status_code: int = 200, headers: dict = None, media_type: str = None, background: starlette.background.BackgroundTask = None) -> None
        [method] init_headers(self, headers: Mapping[str, str] = None) -> None
        [method] render(self, content: Any) -> bytes
    [method] delete_cookie(self, key: str, path: str = '/', domain: str = None) -> None
        [method] set_cookie(self, key: str, value: str = '', max_age: int = None, expires: int = None, path: str = '/', domain: str = None, secure: bool = False, httponly: bool = False) -> None
    [property] headers

ここが先程まで省略されていた部分。例えば上の例ではdelete_cookie()の中でset_cookie()が呼ばれているし。__init__()の中でinit_headers()render()が呼ばれている(さらにネストされるようなものはインデントが深くなっていく)。

実際、init()delete_cookie()は以下の様なコード。

class Response:
# ...
    def delete_cookie(self, key: str, path: str = "/", domain: str = None) -> None:
        self.set_cookie(key, expires=0, max_age=0, path=path, domain=domain)

# 例をわかりやすくするためにメソッドの定義の順序とは変えて表示している
    def __init__(
        self,
        content: typing.Any = None,
        status_code: int = 200,
        headers: dict = None,
        media_type: str = None,
        background: BackgroundTask = None,
    ) -> None:
        if content is None:
            self.body = b""
        else:
            self.body = self.render(content)
        self.status_code = status_code
        if media_type is not None:
            self.media_type = media_type
        self.background = background
        self.init_headers(headers)

自分自身のメソッドだけが現れると意外と概観を掴むのに良い。

クラスに対してだけでなくモジュールに対しても同様のことをしたい

先程のクラスに対する構造の可視化を関数に対しても表示するようにしたくなった。以下の様な対応関係。

  • あるクラスの自身が持つメソッド内での呼び出し関係を出力
  • あるモジュールが持つ関数内での呼び出し関係を出力

なので最近ちょっと機能を追加した。雑な追加だったので幾つかバグが残っている。

例えば全てが関数扱いになってしまってたり。内部で呼ばれていた関数もトップレベルに表示されてしまったり。

例えばurllib.parse:urlparseの呼び出し関係は以下の様になっている。

$ pyinspect inspect urllib.parse:urlparse
[function] urlparse(url, scheme='', allow_fragments=True)
    [function] urlsplit(url, scheme='', allow_fragments=True)
        [function] SplitResult(scheme, netloc, path, query, fragment)
            [function] urlunsplit(components)
        [function] clear_cache()
    [function] ParseResult(scheme, netloc, path, params, query, fragment)
        [function] urlunparse(components)

ふわっと状況を把握するのに便利なのでは?という感じ。

その他、不足事項としては以下の様な再帰したコードが再帰とわかってほしい。だとか。そもそもコンソール以外への出力も念頭に置いて良いのではとか色々ある。

$ pyinspect inspect x:f
[function] f(x)
    [function] g(x, ans)

(実際のコードは以下)

def f(x):
    return g(x, 1)


def g(x, ans):
    if x == 0:
        return ans
    else:
        return g(x - 1, x * ans)