Bug 13186 - Precompiled python3 bytecode is stale
Summary: Precompiled python3 bytecode is stale
Status: RESOLVED FIXED
Alias: None
Product: OE-Core
Classification: Build System, Metadata & Runtime
Component: devtools / tool chain (show other bugs)
Version: unspecified
Hardware: Other Multiple
: Medium normal
Target Milestone: 3.1
Assignee: Robert Yang
QA Contact:
URL:
Whiteboard:
Depends on:
Blocks:
 
Reported: 2019-02-18 11:14 UTC by Tristan Ramseyer
Modified: 2019-11-07 16:19 UTC (History)
8 users (show)

See Also:
OS type for building Yocto: ---
Type of Regression: ---
Verified:
Documentation change: No (bug/feature does not impact docs)


Attachments
Proposed patch for creation of data.tar (625 bytes, application/octet-stream)
2019-02-19 08:23 UTC, Tristan Ramseyer
no flags Details
Test .pyc for stale (2.53 KB, text/plain)
2019-02-25 09:34 UTC, Tristan Ramseyer
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Tristan Ramseyer 2019-02-18 11:14:58 UTC
With both "sumo" 3.5.5 (97ee1f80870745bf6c542ee2f184c9e468672714) and "master" 3.7.2 (c92e780c85523fe860602b947b029d7782afa47a) python3 recipes the generated .pyc files are stale.

This issue can be observed best using a "readonly" rfs and starting the python3 interpreter with -vv such as 'python3 -vv -c ""'. Many messages like "bytecode is stale for 'site'" should appear indicating that the timestamp in the header of the .pyc files differs from the mtime of the corresponding .py file.

For a possible solution, python's 3.7 newly introduced hash-based (CHECKED_HASH) or even (UNCHECKED_HASH) invalidation mode could also be used.

Remark: Reading out the mtime from a .pyc file is described at https://qiita.com/amedama/items/698a7c4dbdd34b03b427 whereas python 3.7 has an additional 4-byte value between "magic_str" and "mtime_str" as described in https://www.python.org/dev/peps/pep-0552/.
Comment 1 Tristan Ramseyer 2019-02-19 08:23:09 UTC
Created attachment 4434 [details]
Proposed patch for creation of data.tar
Comment 2 Tristan Ramseyer 2019-02-19 08:25:42 UTC
With the kind help of Richard Purdie, it was possible to pinpoint the exact cause of the .py files timestamps being altered: http://git.yoctoproject.org/cgit.cgi/opkg-utils/commit/?id=682f8c5e35b8854a9bb858b8ee1714d27e0c00db

The issue is that upon creation of data.tar.$cext, the flags --mtime is used which alters the mtime of every file in it.

I have tested the attached patch successfully on my embedded system.
The python3 interpreter startup time is significantly faster and "-vv" does not show any stale .pyc's.
Comment 3 Alejandro del Castillo 2019-02-19 19:46:01 UTC
Sent patch to opkg mailing list [1] and to OE mailing list [2]

[1] https://groups.google.com/forum/#!topic/opkg-devel/fGbjrKXbOG4
[2] http://lists.openembedded.org/pipermail/openembedded-core/2019-February/279217.html
Comment 4 Richard Purdie 2019-02-21 15:43:16 UTC
The fix was merged into master: http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=a79bc39033c07e5cb0aa5ca95afe8f035c403f33  (thanks Alejandro)

I'd really like to have a test case for this to close the issue out, would you be able to help with that?
Comment 5 Alexander Kanavin 2019-02-21 15:58:20 UTC
Just to get you started with the test, this is the right place for it:

https://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/meta/lib/oeqa/runtime/cases/python.py

The existing test gives a good example of how to run python and check the output. (I guess checking for absence of certain strings would be right).
Comment 6 Alexander Kanavin 2019-02-21 16:08:36 UTC
On second thought, this might not be the right place. By the time the test would be run (on a read-write filesystem), python might have already rebuilt all the .pyc files (with dnf tests running ahead of python tests in particular).

So not sure how to test this, really. There is a test for read-only images in meta/lib/oeqa/selftest/cases/buildoptions.py, but it only tests that the image builds, and won't boot it (but could be extended for that).
Comment 7 Tristan Ramseyer 2019-02-25 09:33:54 UTC
I have written a working test for this (for .ipk's only at the moment).
The test itself is located in do_package_write_ipk_append.
This solution works for my build process and if you deem it worthy for merging it into the master, feel free to do it :).
Comment 8 Tristan Ramseyer 2019-02-25 09:34:49 UTC
Created attachment 4445 [details]
Test .pyc for stale
Comment 9 Alexander Kanavin 2019-02-25 11:06:06 UTC
You can place this into insane.bbclass, then it will work for all package types as part of package_qa() task, and for all packages that contain .py/.pyc.
Comment 10 Tristan Ramseyer 2019-02-25 20:56:06 UTC
As of now the test is done by taking a .py file which is believed to be in every python3 installation "__future.py__".
The test would have to be adopted to e.g. take the first .pyc it finds and the corresponding .py file or even to the test all .pyc files.

Also it would have to be ideally able to extract any package format the build process may generate: ipk, deb, rpm and possibly tar.
Whereas for extracting rpm files "rpm2cpio" and "cpio" or similar tools are required, which (I guess) would result in a such dependency of every recipe using the insane.bbclass.
Is this really what we want?
Might it be better to split this up into two tests?:
- QA: Test if .pyc files in PKGDEST are not stale (this should be doable without special tools)
- ??: Test if package manager's are packing files using undesired options such as --mtime.
Comment 11 Leon Woestenberg 2019-03-08 22:50:46 UTC
sumo yocto-2.5.2-127-gd3ad243 (d3ad2438222050faf33e83598c1f6ecd25ff65b6) with .deb packages, I am getting stale .pyc on my read-only target filesystem.

I am using reproducible builds, and the .py files have timestamp 0 seconds since epoch, whereas the 4 byte timestamp (at byte offset 4) in each .pyc file are substantially larger.

By erasing the timestamp in a .pyc file (remounting rw, dd if=/dev/zero of=some.pyc bs=1 count=4 seek=4 conv=notrunc) the .pyc file is no longer considered stale.

Has this issue been fixed for all package types?
Comment 12 Leon Woestenberg 2019-03-08 23:18:58 UTC
I have debugged my case further, and the issue seems not so much in the python build itself, but in the fact that my files end up with timestamp 0 seconds since epoch on my read-only filesystem, whereas the .py files have file timestamp matching SOURCE_DATE_EPOCH=1517788422, which also matches the internal timestamp in the .pyc file.

my local.conf:
INHERIT += "reproducible_build"
BUILD_REPRODUCIBLE_BINARIES="1"
REPRODUCIBLE_TIMESTAMP_ROOTFS="1549187940"
LDCONFIGDEPEND=""


temp/run.do_compile.3316:83:export SOURCE_DATE_EPOCH="1517788422"

this matches the last modification time of the .py file in image/

00:06 $ ls -a --full-time image/usr/lib/python3.5/json/encoder.py
-rw-r--r-- 3 leon leon 15961 2018-02-05 00:53:42.000000000 +0100 image/usr/lib/python3.5/json/encoder.py

or directly printing last modification time of the file as seconds since epoch:

00:08 $ find image/usr/lib/python3.5/json/encoder.py | xargs -L1 stat -c%Y
1517788422

which in turn matches the internal timestamp in .pyc:

dd if=./image/usr/lib/python3.5/json/__pycache__/encoder.cpython-35.pyc skip=4 bs=1 count=4 | od -An -tu4
4+0 records in
4+0 records out
4 bytes copied, 4.6492e-05 s, 86.0 kB/s
 1517788422

However on the target the .py files are 0 seconds since epoch:

root@adesys-octalarm:/usr/bin# ls --full-time -ald /usr/lib/python3.5/json/encoder.py     
-rw-r--r-- 3 root root 15961 1970-01-01 01:00:00.000000000 +0100 /usr/lib/python3.5/json/encoder.py
Comment 13 Leon Woestenberg 2019-03-08 23:42:34 UTC
I found that this is probably due to my filesystem being an OSTree deployment; meta-updater / meta-ostree.

More info here:

https://github.com/advancedtelematic/meta-updater/issues/461
Comment 14 Randy MacLeod 2019-05-30 15:28:55 UTC
Robert, we think this has come down to needed some self-test for the consistency of the py and pyc file timestamaps. Richard can give you more guidance as needed.
Comment 15 Ross Burton 2019-11-07 16:19:59 UTC
Since https://www.python.org/dev/peps/pep-0552/ the cache files are invalidated based on file hashes not timestamps and the pyc files are hash based, so I believe this is resolved now.

Closing.  If anyone disagrees, please reopen.