memo

2017-02-20

flatpak に入れた python アプリケーションの起動がやけに遅い

先日 flatpak に python アプリケーションを入れてみたわけだけど、 flatpak をかぶせることによる起動コストの増加はどんなもんだろうか、 と気になったので、 time を使ってテキトウに計ってみる。

普通に実行した場合:

(venv) $ time konnyaku --help
Usage: konnyaku [OPTIONS] COMMAND [ARGS]...

Options:
  --debug / --no-debug
  --db-debug / --no-db-debug
  --help                      Show this message and exit.

Commands:
  add      add site
  check    check site updates
  links    list links
  list     list sites
  modify   modify site
  oneshot  add & check but not save
  remove   remove site
  show     show site information
konnyaku --help  0.74s user 0.06s system 99% cpu 0.806 total

0.8秒くらい。

続いて flatpak に入れたヤツ:

$ time flatpak run org.u7fa9.konnyaku --help
Usage: konnyaku [OPTIONS] COMMAND [ARGS]...

Options:
  --debug / --no-debug
  --db-debug / --no-db-debug
  --help                      Show this message and exit.

Commands:
  add      add site
  check    check site updates
  links    list links
  list     list sites
  modify   modify site
  oneshot  add & check but not save
  remove   remove site
  show     show site information
flatpak run org.u7fa9.konnyaku --help  0.06s user 0.02s system 2% cpu 2.899 total

2.9秒くらい。

思ってた以上に遅い。何だこれ。

調査

ひとまず python ではなくて、明らかに一瞬で実行が終わるはずのコマンドを実行させてみる:

$ time flatpak run --command=/bin/true org.u7fa9.konnyaku
flatpak run --command=/bin/true org.u7fa9.konnyaku  0.06s user 0.02s system 36% cpu 0.229 total

0.2秒くらい。これが flatpak を立ち上げるのに必要なコスト。じゃあさっきの2秒近い差はどっから出てきた?

python アプリケーションで起動が思いのほか遅いというような場合、 .pyc ファイルを作成し忘れたケースが考えられる。 flatpak では runtime/application は read-only で mount されるため、パッケージング時に含めそびれると、実行時には作成できない (作成しても保存できない) ので、毎回 .py ファイルを読み込むことになる。

ファイルがあるか確認してみる。

$ flatpak run --command=/bin/sh org.u7fa9.konnyaku
~ $ ls -l /app/lib/python3.5/site-packages/konnyaku/
total 36
-rwxr--r--  231 nakamuray nakamuray         0 Jan  1  1970 __init__.py
drwxr-xr-x    2 nakamuray nakamuray         8 Jan  1  1970 __pycache__
-rwxr--r--    2 nakamuray nakamuray      6281 Jan  1  1970 cli.py
-rwxr--r--    2 nakamuray nakamuray      1599 Jan  1  1970 concurrentutils.py
-rwxr--r--    2 nakamuray nakamuray        39 Jan  1  1970 exceptions.py
-rwxr--r--    2 nakamuray nakamuray      3287 Jan  1  1970 models.py
-rwxr--r--    2 nakamuray nakamuray      3594 Jan  1  1970 tasks.py
~ $ ls -l /app/lib/python3.5/site-packages/konnyaku/__pycache__/
total 31
-rwxr--r--    2 nakamuray nakamuray       136 Jan  1  1970 __init__.cpython-35.pyc
-rwxr--r--    2 nakamuray nakamuray      6502 Jan  1  1970 cli.cpython-35.pyc
-rwxr--r--    2 nakamuray nakamuray      1915 Jan  1  1970 concurrentutils.cpython-35.pyc
-rwxr--r--    2 nakamuray nakamuray       310 Jan  1  1970 exceptions.cpython-35.pyc
-rwxr--r--    2 nakamuray nakamuray      3957 Jan  1  1970 models.cpython-35.pyc
-rwxr--r--    2 nakamuray nakamuray      3004 Jan  1  1970 tasks.cpython-35.pyc

ちゃんとある...が、なんだこのタイムスタンプは?

原因

どうやら flatpak (が内部で使ってる ostree) はファイルの更新日時等々を保存しないらしく、 そのためそこからファイルを取り出すと 1970-01-01 00:00:00 (UTC), unix time で "0" が更新日時として設定されるらしい。

さて、 python は .pyc ファイル中に元のソースファイルの更新日時を保存していて、 これが現在のソースファイルの日時と異なっている場合はファイル内容に変更があると見なし、 .pyc を読み込まないようになっている。

で、全てのファイルの更新日時が 1970-01-01 00:00:00 に 変更 されてしまったため、 全ての .pyc ファイルでこのチェックに引っかかるようになってしまい、 また先述したように新規で .pyc ファイルを作成することも出来ないので、 結果として毎回 .py ファイルを読み込むようになってしまっているようだ。

その分が起動時間の差に現れていると考えられる。

対策

.pyc ファイル中に記録されている更新日時情報が 1970-01-01 00:00:00 を指すように、データを書き換える。

この情報は 4-7 bytes の範囲に書かれているようなので、 dd を使ってゼロ埋めしてやればよい。

ということで、前回のパッケージングスクリプトに以下のような変更を加えて作り直す:

diff -r 43abc9291d3b flatpak/build-konnyaku-runtime.bash
--- a/flatpak/build-konnyaku-runtime.bash       Mon Feb 20 15:21:54 2017 +0900
+++ b/flatpak/build-konnyaku-runtime.bash       Mon Feb 20 21:23:24 2017 +0900
@@ -53,6 +53,10 @@
 run_in_rootfs apk update
 run_in_rootfs apk add "${RUNTIME_PACKAGES[@]}" || true

+# XXX: fix .pyc's timestamp information to match "1970-01-01 00:00:00",
+#      files checked out from ostree will be.
+run_in_rootfs find /usr/lib/python3.5 -name "*.pyc" -exec dd if=/dev/zero of="{}" bs=4 seek=1 count=1 conv=notrunc ";" 2>/dev/null
+
 # create sdk based on runtime
 cp -a "${rootfs_dir}" "${sdk_dir}"/

diff -r 43abc9291d3b flatpak/build-konnyaku.bash
--- a/flatpak/build-konnyaku.bash       Mon Feb 20 15:21:54 2017 +0900
+++ b/flatpak/build-konnyaku.bash       Mon Feb 20 21:23:24 2017 +0900
@@ -22,5 +22,10 @@
 flatpak build "${build_location}" python3 -m venv /app
 flatpak build --share=network "${build_location}" /app/bin/pip install -U pip
 flatpak build --share=network "${build_location}" /app/bin/pip install "${URL}"
+
+# XXX: fix .pyc's timestamp information to match "1970-01-01 00:00:00",
+#      files checked out from ostree will be.
+flatpak build "${build_location}" find /app -name "*.pyc" -exec dd if=/dev/zero of="{}" bs=4 seek=1 count=1 conv=notrunc ";" 2>/dev/null
+
 flatpak build-finish "${BUILD_FINISH_ARGS[@]}" "${build_location}"
 flatpak build-export "${REPOSITORY}" "${build_location}" "${VERSION}"

結果

$ time flatpak run org.u7fa9.konnyaku --help
Usage: konnyaku [OPTIONS] COMMAND [ARGS]...

Options:
  --debug / --no-debug
  --db-debug / --no-db-debug
  --help                      Show this message and exit.

Commands:
  add      add site
  check    check site updates
  links    list links
  list     list sites
  modify   modify site
  oneshot  add & check but not save
  remove   remove site
  show     show site information
flatpak run org.u7fa9.konnyaku --help  0.06s user 0.02s system 7% cpu 1.139 total

直接実行した場合の0.8秒と比べて、0.3秒くらいの差。 true を実行した時の0.2秒にかなり近くなった。

余談

flatpak-builder にはコレと同様の対応処理が入っているようなので、 コイツで python アプリケーションが普通にパッケージングできるようになれば、こんなこと気にしなくてよくなるのかも。