Почему предварительная компиляция файлов pyc не дает ожидаемых результатов?

Question

У меня есть ситуация, которую я действительно не могу объяснить: я запускаю скрипт Python в системе с файловой системой только для чтения с предварительно сгенерированным .pyc файлы для всех Python-модулей, и я запускаю его снова после перемонтирования файловой системы с возможностью записи. После второго запуска скрипт выполняется намного быстрее.

Это меня пока не удивило - может быть, предварительно сгенерированный .pyc-файлы не были сгенерированы правильно в первую очередь. На втором этапе они будут перегенерированы и записаны (расположены в __pycache__ папки) и повторно используется при третьем прогоне.

примечание: скрипт, с которым я экспериментирую, не делает ничего, кроме импорта некоторых собственных модулей Python (sys, os, argparseи т. д.) - другого кода, соответствующего производительности, нет. Таким образом, единственное различие, относящееся к производительности между каждым запуском, - это предварительно скомпилированный байт-код (о чем я могу думать). На машине нет других соответствующих процессов.

Странная вещь: содержание всего __pycache__ папки не меняются вообще. Я скопировал весь /usr/lib/python3.5 Папка и папка, содержащая мой скрипт до и после перемонтирования, и разницы нет.

Где Python хранит информацию, необходимую для более быстрой работы? Почему не .pyc файлы (или их отметка времени!) меняются?

Подробно:

В настоящее время я пытаюсь предварительно скомпилировать Python-скрипты, прежде чем развертывать их на внедренной цели с RO-файловой системой, и результаты не такие, как ожидалось (не наблюдается никакой разницы во времени).

Вот что я делаю, чтобы наблюдать за нежелательным поведением:

• войти в цель (rootfs установлен RO)
• запустить скрипт: time myscript.pyработает за 5,7 сек
• запустить скрипт: time myscript.pyработает за 5,7 сек
• ... (можно повторить, результат всегда один и тот же)
• scp содержание /usr/lib/python3.5/site-packages и папка, содержащая myscript.py в папку с именем before
• обновление: захват всех разрешений и отметок времени всех .pyc файлы
• перемонтировать RW: mount -o remount,rw /
• запустить скрипт: time myscript.pyработает чуть более 5,7 с
• запустить скрипт: time myscript.pyработает за 1.79сек
• запустить скрипт: time myscript.pyработает за 1.79сек
• ... (можно повторить, результат всегда один и тот же)
• scp содержание /usr/lib/python3.5/site-packages и папка, содержащая myscript.py в папку с именем after
• обновление: снова захват всех разрешений и отметок времени всех .pyc файлы

• сравнить папки, которые, как я подозревал, теперь содержат измененные .pyc-файлы:

  diff -r before after

  нет различий

• обновление: сравнение всех временных меток и разрешений, полученных ранее - без разницы

Я также пытался вручную изменить один из скопированных .pyc файлы, чтобы проверить, diff действительно сравнивает двоичные файлы, но это работает, как ожидалось.

После перезагрузки система также ведет себя так, как и ожидалось, когда файлы кэша были записаны (скрипт работает быстро).

Для тех, кто не верит мне:

root@machine:/data# cat myscript.py 
#!/usr/bin/env python3
# -*- coding: utf-8 -*-

import argparse
import logging
import signal
import sys, os, shutil

if __name__ == '__main__':
    print('hello')

root@machine:/data# time ./myscript.py 
hello
real    0m5.756s, user  0m4.326s, sys   0m0.773s

root@machine:/data# time ./myscript.py 
hello
real    0m5.740s, user  0m4.289s, sys   0m0.797s

root@machine:/data# mount -o remount,rw /

root@machine:/data# time ./myscript.py 
hello
real    0m6.005s, user  0m4.374s, sys   0m0.845s

root@machine:/data# time ./myscript.py 
hello
real    0m1.789s, user  0m1.283s, sys   0m0.288s

root@machine:/data# time ./myscript.py 
hello
real    0m1.787s, user  0m1.287s, sys   0m0.284s

(Я сократил некоторые результаты, но цифры верны)

(очень странно) Обновление:

Чтобы отслеживать метки времени всех .pyc файлы, которые я выполнил следующую команду до и после повторного запуска myscript.py:

find /usr/lib/python3.5/site-packages/ -name *.pyc -exec stat -t {} \; > file-details-before/after

Результат: file-details-before а также file-details-after абсолютно идентичны! Контент выглядит так (одинаково в обоих случаях):

...
/usr/lib/python3.5/site-packages/psutil/__pycache__/_psosx.cpython-35.pyc 10676 24 81a4 0 0 e 2221 1 0 0 1499781288 1499555909 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/_psbsd.cpython-35.pyc 12047 24 81a4 0 0 e 2223 1 0 0 1499781288 1499555909 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/_compat.cpython-35.pyc 8393 24 81a4 0 0 e 2222 1 0 0 1499781288 1499555910 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/_psmswindows.cpython-35.pyc 14488 32 81a4 0 0 e 2227 1 0 0 1499781288 1499555910 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/_pslinux.cpython-35.pyc 28030 56 81a4 0 0 e 2224 1 0 0 1499781288 1499555909 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/__init__.cpython-35.pyc 37069 80 81a4 0 0 e 2220 1 0 0 1499781288 1499555910 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/_psposix.cpython-35.pyc 3069 8 81a4 0 0 e 2219 1 0 0 1499781288 1499555909 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/error.cpython-35.pyc 2557 8 81a4 0 0 e 2226 1 0 0 1499781288 1499555910 1499781288 4096
/usr/lib/python3.5/site-packages/psutil/__pycache__/_common.cpython-35.pyc 6188 16 81a4 0 0 e 2225 1 0 0 1499781288 1499555909 1499781288 4096
...

Номер .pyc файлы, их разрешения и временные метки равны, т.е. diff file-details-before file-details-after не показывает никакой разницы.

Профилирование:

Перед повторным запуском с записываемой файловой системой:

time python3 -m cProfile -s cumtime ./myscript.py
hello
         11530 function calls (11346 primitive calls) in 2.423 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     19/1    0.020    0.001    2.423    2.423 {built-in method builtins.exec}
        1    0.001    0.001    2.423    2.423 myscript.py:4(<module>)
     21/4    0.004    0.000    2.422    0.605 <frozen importlib._bootstrap>:966(_find_and_load)
     21/4    0.002    0.000    2.418    0.605 <frozen importlib._bootstrap>:939(_find_and_load_unlocked)
     21/4    0.008    0.000    2.369    0.592 <frozen importlib._bootstrap>:659(_load_unlocked)
     16/4    0.003    0.000    2.353    0.588 <frozen importlib._bootstrap_external>:656(exec_module)
     42/8    0.010    0.000    2.319    0.290 <frozen importlib._bootstrap>:214(_call_with_frames_removed)
       16    0.009    0.001    1.815    0.113 <frozen importlib._bootstrap_external>:726(get_code)
       16    0.001    0.000    1.700    0.106 <frozen importlib._bootstrap_external>:718(source_to_code)
       16    1.689    0.106    1.689    0.106 {built-in method builtins.compile}
        1    0.003    0.003    0.687    0.687 __init__.py:24(<module>)
...
real    0m7.611s, user  0m5.861s, sys   0m0.877s

и после:

time python3 -m cProfile -s cumtime ./myscript.py
hello
         11050 function calls (10878 primitive calls) in 0.730 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     19/1    0.024    0.001    0.730    0.730 {built-in method builtins.exec}
        1    0.001    0.001    0.730    0.730 myscript.py:4(<module>)
     21/4    0.005    0.000    0.729    0.182 <frozen importlib._bootstrap>:966(_find_and_load)
     21/4    0.002    0.000    0.725    0.181 <frozen importlib._bootstrap>:939(_find_and_load_unlocked)
     21/4    0.005    0.000    0.684    0.171 <frozen importlib._bootstrap>:659(_load_unlocked)
     16/4    0.004    0.000    0.677    0.169 <frozen importlib._bootstrap_external>:656(exec_module)
     26/4    0.001    0.000    0.638    0.160 <frozen importlib._bootstrap>:214(_call_with_frames_removed)
        1    0.003    0.003    0.313    0.313 __init__.py:24(<module>)
        1    0.002    0.002    0.203    0.203 shutil.py:5(<module>)
       21    0.007    0.000    0.201    0.010 <frozen importlib._bootstrap>:879(_find_spec)
       19    0.001    0.000    0.187    0.010 <frozen importlib._bootstrap_external>:1130(find_spec)
...
real    0m3.102s, user  0m2.196s, sys   0m0.448s