Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Precompilation cache files are invalidated when the mtimes of the Julia installation change #50918

Closed
Tracked by #50667
DilumAluthge opened this issue Aug 15, 2023 · 19 comments · Fixed by #49866
Closed
Tracked by #50667
Labels
compiler:precompilation Precompilation of modules domain:packages Package management and loading kind:bug Indicates an unexpected problem or unintended behavior

Comments

@DilumAluthge
Copy link
Member

DilumAluthge commented Aug 15, 2023

Reproduced on:

  • Julia 1.8.5
  • Julia 1.9.2
  • Julia master (specifically, commit fd38d50)

MWE

Here is an MWE for Julia 1.8.5. Run the following commands in Bash.

Click to expand:
MY_DOWNLOAD_JULIA_FUNCTION () {
    cd ${WORKING_DIRECTORY:?}
    rm -rf ${MY_DOWNLOADS_DIRECTORY:?}
    mkdir ${MY_DOWNLOADS_DIRECTORY:?}
    cd ${MY_DOWNLOADS_DIRECTORY:?}
    JULIA_TARBALL_FILENAME="${JULIA_DIRECTORY:?}-${JULIA_PLATFORM:?}.tar.gz"
    JULIA_TARBALL_URL="https://julialang-s3.julialang.org/bin/${JULIA_OS:?}/${JULIA_ARCH:?}/${JULIA_MAJ:?}.${JULIA_MIN:?}/${JULIA_TARBALL_FILENAME:?}"
    curl --fail -L -O ${JULIA_TARBALL_URL:?}
    echo "${JULIA_TARBALL_SHA256:?}  ${JULIA_TARBALL_FILENAME:?}" | shasum -a 256 -c
    tar xzf ${JULIA_TARBALL_FILENAME:?}
    cd ${WORKING_DIRECTORY:?}
}

cd $(mktemp -d)

export JULIA_DEBUG=loading
export JULIA_PKG_PRECOMPILE_AUTO=0

WORKING_DIRECTORY="$(pwd)"
export JULIA_DEPOT_PATH="${WORKING_DIRECTORY:?}/mydepot"
MY_DOWNLOADS_DIRECTORY="${WORKING_DIRECTORY:?}/mydownloads"

JULIA_MAJ=1
JULIA_MIN=8
JULIA_PATCH=5
JULIA_OS="mac"
JULIA_ARCH="x64"
JULIA_PLATFORM=mac64
JULIA_TARBALL_SHA256=a1a859eda7fb41a0b55467339a11c3c1c0df78b27d1e160e80bc6758b3d8dae0

JULIA_DIRECTORY="julia-${JULIA_MAJ:?}.${JULIA_MIN:?}.${JULIA_PATCH:?}"
JULIA_CMD="${MY_DOWNLOADS_DIRECTORY:?}/${JULIA_DIRECTORY:?}/bin/julia"

rm -rf ${MY_DOWNLOADS_DIRECTORY:?}
MY_DOWNLOAD_JULIA_FUNCTION

MY_MBEDTLSJLLSOURCEFILE="${MY_DOWNLOADS_DIRECTORY:?}/${JULIA_DIRECTORY:?}/share/julia/stdlib/v${JULIA_MAJ:?}.${JULIA_MIN:?}/MbedTLS_jll/src/MbedTLS_jll.jl"

# Print mtime
# On macOS, use `stat -f %m`
# On Linux, use `stat -c %Y`
MY_STAT_MTIME_CMD="stat -f %m"

${MY_STAT_MTIME_CMD:?} ${MY_MBEDTLSJLLSOURCEFILE:?}

${JULIA_CMD:?} --version
${JULIA_CMD:?} -e 'import InteractiveUtils; InteractiveUtils.versioninfo()'

${JULIA_CMD:?} -e 'import Pkg; Pkg.add(; name = "HTTP", uuid = "cd3eb016-35fb-5094-929b-558a96fad6f3", version = "1.9.14")'
${JULIA_CMD:?} -e 'import Pkg; Pkg.precompile(; strict = true)'

${JULIA_CMD:?} -e 'import HTTP'

# Subsequent invocations of `import HTTP` do not have any precompilation.
${JULIA_CMD:?} -e 'import HTTP'
${JULIA_CMD:?} -e 'import HTTP'

${MY_STAT_MTIME_CMD:?} ${MY_MBEDTLSJLLSOURCEFILE:?}
touch "${MY_MBEDTLSJLLSOURCEFILE:?}"
${MY_STAT_MTIME_CMD:?} ${MY_MBEDTLSJLLSOURCEFILE:?}

# Expected behavior: no precompilation occurs
# Observed behavior: precompilation occurs for the first `import HTTP`, because
# the `mtime` has changed for one of the `.jl` source files in the stdlib.
${JULIA_CMD:?} -e 'import HTTP'

# Subsequent invocations of `import HTTP` do not have any precompilation.
${JULIA_CMD:?} -e 'import HTTP'
${JULIA_CMD:?} -e 'import HTTP'

Expected behavior

No precompilation occurs.

Observed behavior

Precompilation occurs for the first import HTTP, because the mtime has changed for one of the .jl source files in the stdlib.

Here are some examples of the observed log messages:

┌ Debug: Rejecting stale cache file [...]/mydepot/compiled/v1.8/MbedTLS_jll/u5NEn_aBpJv.ji (mtime 1.673165108e9) because file /private[...]/mydownloads/julia-1.8.5/share/julia/stdlib/v1.8/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.692064837872149e9) has changed
└ @ Base loading.jl:2155

┌ Debug: Rejecting cache file [...]/mydepot/compiled/v1.8/HTTP/zXWya_aBpJv.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID 2343483797027 is missing from the cache.
└ @ Base loading.jl:1010

┌ Debug: Rejecting stale cache file [...]/mydepot/compiled/v1.8/MbedTLS_jll/u5NEn_aBpJv.ji (mtime 1.673165108e9) because file /private[...]/mydownloads/julia-1.8.5/share/julia/stdlib/v1.8/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.692064837872149e9) has changed
└ @ Base loading.jl:2155

┌ Debug: Rejecting cache file [...]/mydepot/compiled/v1.8/MbedTLS/bf9T0_aBpJv.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID 2343483797027 is missing from the cache.
└ @ Base loading.jl:1010

┌ Debug: Rejecting stale cache file [...]/mydepot/compiled/v1.8/MbedTLS_jll/u5NEn_aBpJv.ji (mtime 1.673165108e9) because file /private[...]/mydownloads/julia-1.8.5/share/julia/stdlib/v1.8/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.692064837872149e9) has changed
└ @ Base loading.jl:2155

Motivation

I have found this to be a problem in CI environments where the Julia installation may be coming from one place (e.g. baked into a Docker image, or maybe available via the GitHub Actions toolcache), but the Julia depot .julia (including the precompilation cache at .julia/compiled) is cached via a different mechanism.

@DilumAluthge DilumAluthge added kind:bug Indicates an unexpected problem or unintended behavior domain:packages Package management and loading compiler:precompilation Precompilation of modules labels Aug 15, 2023
@IanButterworth
Copy link
Sponsor Member

I believe this mtime check should be being skipped

@debug "Skipping mtime check for file $f used by $cachefile, since it is a stdlib"

@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

Ah, it looks like that line was only added in Julia 1.9.0. My MWE above was run with Julia 1.8.5.

I suppose it's very unlikely that we'll get another Julia 1.8.x release? I have some private applications that are going to be stuck on Julia 1.8 for a little while longer.

EDIT: I am able to reproduce the issue on Julia 1.9.2.

@DilumAluthge DilumAluthge changed the title Precompilation cache files are invalidated when the mtimes of the Julia installation change [Julia 1.8] Precompilation cache files are invalidated when the mtimes of the Julia installation change Aug 15, 2023
@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

Let me run my MWE against Julia 1.9.2, to see if I can reproduce it.

EDIT: I am able to reproduce the issue on Julia 1.9.2.

@vchuravy
Copy link
Sponsor Member

Yeah we don't ship cache files for stdlibs in 1.8.

@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

I am able to reproduce this issue on Julia 1.9.2.

The details for the 1.9.2 tarball that I used:

JULIA_MAJ=1
JULIA_MIN=9
JULIA_PATCH=2
JULIA_OS="mac"
JULIA_ARCH="x64"
JULIA_PLATFORM=mac64
JULIA_TARBALL_SHA256=a2e8eb31a89b26e4a99349303aeff8e8ee780144bbdb1f7eda6f41024d42cadb

After I touch the src/MbedTLS_jll.jl source file, I see precompilation when I do import HTTP.

Here are the relevant log messages: (click to expand)
$ ${MY_STAT_MTIME_CMD:?} ${MY_MBEDTLSJLLSOURCEFILE:?}
1688551125
$ touch "${MY_MBEDTLSJLLSOURCEFILE:?}"
$ ${MY_STAT_MTIME_CMD:?} ${MY_MBEDTLSJLLSOURCEFILE:?}
1692071534
$ ${JULIA_CMD:?} -e 'import HTTP'
┌ Debug: Rejecting stale cache file [...]/mydepot/compiled/v1.9/MbedTLS_jll/u5NEn_2HLJw.ji (mtime 1.688551125e9) because file /private[...]/mydownloads/julia-1.9.2/share/julia/stdlib/v1.9/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.692071534639636e9) has changed
└ @ Base loading.jl:2849
┌ Debug: Rejecting cache file [...]/mydepot/compiled/v1.9/HTTP/zXWya_2HLJw.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID fafbfcfd-78a2-1d24-0000-00a4e8340cd3 is missing from the cache.
└ @ Base loading.jl:1475
┌ Debug: Precompiling HTTP [cd3eb016-35fb-5094-929b-558a96fad6f3]
└ @ Base loading.jl:2180
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/URIs/eec2u_2HLJw.dylib for URIs [5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/LoggingExtras/9fRHf_2HLJw.dylib for LoggingExtras [e6f89c97-d47a-5376-807f-9c37f3926c36]
└ @ Base loading.jl:1051
┌ Debug: Rejecting stale cache file [...]/mydepot/compiled/v1.9/MbedTLS_jll/u5NEn_2HLJw.ji (mtime 1.688551125e9) because file /private[...]/mydownloads/julia-1.9.2/share/julia/stdlib/v1.9/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.692071534639636e9) has changed
└ @ Base loading.jl:2849
┌ Debug: Rejecting cache file [...]/mydepot/compiled/v1.9/MbedTLS/bf9T0_2HLJw.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID fafbfcfd-78a2-1d24-0000-00a4e8340cd3 is missing from the cache.
└ @ Base loading.jl:1475
┌ Debug: Precompiling MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:2180
┌ Debug: Rejecting stale cache file [...]/mydepot/compiled/v1.9/MbedTLS_jll/u5NEn_2HLJw.ji (mtime 1.688551125e9) because file /private[...]/mydownloads/julia-1.9.2/share/julia/stdlib/v1.9/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.692071534639636e9) has changed
└ @ Base loading.jl:2849
┌ Debug: Precompiling MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:2180
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/MbedTLS_jll/u5NEn_2HLJw.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/MbedTLS_jll/u5NEn_2HLJw.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/MbedTLS/bf9T0_2HLJw.dylib for MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/BitFlags/sbYUO_2HLJw.dylib for BitFlags [d1d4a3ce-64b1-5f1a-9ba4-7e7e69966f35]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/Preferences/pWSk8_2HLJw.dylib for Preferences [21216c6a-2e73-6563-6e65-726566657250]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/JLLWrappers/7Zgw7_2HLJw.dylib for JLLWrappers [692b3bcd-3c85-4b1f-b108-f13ce0eb3210]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/OpenSSL_jll/M3X35_2HLJw.dylib for OpenSSL_jll [458c3c95-2e84-50aa-8efc-19380b2a3a95]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/OpenSSL/B4VRP_2HLJw.dylib for OpenSSL [4d8831e6-92b7-49fb-bdf8-b643e874388c]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/ExceptionUnwrapping/DKnWN_2HLJw.dylib for ExceptionUnwrapping [460bff9d-24e4-43bc-9d9f-a8973cb893f4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/ConcurrentUtilities/OtIZJ_2HLJw.dylib for ConcurrentUtilities [f0e56b4a-5159-44fe-b623-3e5288b988bb]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/TranscodingStreams/eJQ7D_2HLJw.dylib for TranscodingStreams [3bb67fe8-82b1-5028-8e26-92a6c54297fa]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/Zlib_jll/xjq3Q_2HLJw.dylib for Zlib_jll [83775a58-1f1d-513f-b197-d71354ab007a]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/CodecZlib/1TI30_2HLJw.dylib for CodecZlib [944b1d66-785c-5afd-91f1-9de20f533193]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/SimpleBufferStream/QbHsM_2HLJw.dylib for SimpleBufferStream [777ac1f9-54b0-4bf8-805c-2214025038e7]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/URIs/eec2u_2HLJw.dylib for URIs [5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/LoggingExtras/9fRHf_2HLJw.dylib for LoggingExtras [e6f89c97-d47a-5376-807f-9c37f3926c36]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/MbedTLS_jll/u5NEn_2HLJw.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/MbedTLS/bf9T0_2HLJw.dylib for MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/BitFlags/sbYUO_2HLJw.dylib for BitFlags [d1d4a3ce-64b1-5f1a-9ba4-7e7e69966f35]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/Preferences/pWSk8_2HLJw.dylib for Preferences [21216c6a-2e73-6563-6e65-726566657250]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/JLLWrappers/7Zgw7_2HLJw.dylib for JLLWrappers [692b3bcd-3c85-4b1f-b108-f13ce0eb3210]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/OpenSSL_jll/M3X35_2HLJw.dylib for OpenSSL_jll [458c3c95-2e84-50aa-8efc-19380b2a3a95]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/OpenSSL/B4VRP_2HLJw.dylib for OpenSSL [4d8831e6-92b7-49fb-bdf8-b643e874388c]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/ExceptionUnwrapping/DKnWN_2HLJw.dylib for ExceptionUnwrapping [460bff9d-24e4-43bc-9d9f-a8973cb893f4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/ConcurrentUtilities/OtIZJ_2HLJw.dylib for ConcurrentUtilities [f0e56b4a-5159-44fe-b623-3e5288b988bb]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/TranscodingStreams/eJQ7D_2HLJw.dylib for TranscodingStreams [3bb67fe8-82b1-5028-8e26-92a6c54297fa]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/Zlib_jll/xjq3Q_2HLJw.dylib for Zlib_jll [83775a58-1f1d-513f-b197-d71354ab007a]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/CodecZlib/1TI30_2HLJw.dylib for CodecZlib [944b1d66-785c-5afd-91f1-9de20f533193]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/SimpleBufferStream/QbHsM_2HLJw.dylib for SimpleBufferStream [777ac1f9-54b0-4bf8-805c-2214025038e7]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file [...]/mydepot/compiled/v1.9/HTTP/zXWya_2HLJw.dylib for HTTP [cd3eb016-35fb-5094-929b-558a96fad6f3]
└ @ Base loading.jl:1051

@DilumAluthge DilumAluthge changed the title [Julia 1.8] Precompilation cache files are invalidated when the mtimes of the Julia installation change Precompilation cache files are invalidated when the mtimes of the Julia installation change Aug 15, 2023
@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

In the logs for 1.9.2, I do not see any occurrences of the Skipping mtime check for file $f used by $cachefile, since it is a stdlib log message.

And I have export JULIA_DEBUG=loading.

@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

I can reproduce this issue on Julia master (specifically, commit fd38d50).

The log messages are different (e.g. a lot of detailed log messages explaining why the different pkgimages were rejected, etc.), but the overall bug is still the same - after touching the src/MbedTLS_jll.jl source file, the very next invocation of import HTTP causes precompilation, but then subsequent invocations of import HTTP do not cause precompilation.

@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

Here are the relevant log messages for Julia master (specifically, commit fd38d50).

Click to expand:
$ touch ./stdlib/MbedTLS_jll/src/MbedTLS_jll.jl
$ ./julia -e 'import HTTP'
┌ Debug: Rejecting stale cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.ji (mtime 1.692074982973298e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Ignoring cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] (fafbfcfd-53a2-fa72-0000-0281690eec2a) since it is does not provide desired build_id (fafbfcfd-ed72-4d9b-0000-03d1bc6516a0)
└ @ Base loading.jl:3053
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_SyEur.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = false, debug_level = 1, check_bounds = 0, inline = true, opt_level = 0
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_KDIIK.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = true, debug_level = 1, check_bounds = 1, inline = true, opt_level = 2
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/.julia/compiled/v1.11/HTTP/zXWya_V1nJs.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID fafbfcfd-ed72-4d9b-0000-03d1bc6516a0 is missing from the cache.
└ @ Base loading.jl:1554
┌ Debug: Rejecting stale cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.ji (mtime 1.692074982973298e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Ignoring cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] (fafbfcfd-53a2-fa72-0000-0281690eec2a) since it is does not provide desired build_id (fafbfcfd-ed72-4d9b-0000-03d1bc6516a0)
└ @ Base loading.jl:3053
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_SyEur.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = false, debug_level = 1, check_bounds = 0, inline = true, opt_level = 0
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_KDIIK.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = true, debug_level = 1, check_bounds = 1, inline = true, opt_level = 2
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/.julia/compiled/v1.11/HTTP/zXWya_V1nJs.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID fafbfcfd-ed72-4d9b-0000-03d1bc6516a0 is missing from the cache.
└ @ Base loading.jl:1554
┌ Debug: Precompiling HTTP [cd3eb016-35fb-5094-929b-558a96fad6f3]
└ @ Base loading.jl:2347
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/URIs/eec2u_V1nJs.dylib for URIs [5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/LoggingExtras/9fRHf_V1nJs.dylib for LoggingExtras [e6f89c97-d47a-5376-807f-9c37f3926c36]
└ @ Base loading.jl:1051
┌ Debug: Rejecting stale cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.ji (mtime 1.692074982973298e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Ignoring cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] (fafbfcfd-53a2-fa72-0000-0281690eec2a) since it is does not provide desired build_id (fafbfcfd-ed72-4d9b-0000-03d1bc6516a0)
└ @ Base loading.jl:3053
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_SyEur.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = false, debug_level = 1, check_bounds = 0, inline = true, opt_level = 0
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_KDIIK.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = true, debug_level = 1, check_bounds = 1, inline = true, opt_level = 2
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS/bf9T0_V1nJs.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID fafbfcfd-ed72-4d9b-0000-03d1bc6516a0 is missing from the cache.
└ @ Base loading.jl:1554
┌ Debug: Rejecting stale cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.ji (mtime 1.692074982973298e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Ignoring cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] (fafbfcfd-53a2-fa72-0000-0281690eec2a) since it is does not provide desired build_id (fafbfcfd-ed72-4d9b-0000-03d1bc6516a0)
└ @ Base loading.jl:3053
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_SyEur.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = false, debug_level = 1, check_bounds = 0, inline = true, opt_level = 0
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_KDIIK.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = true, debug_level = 1, check_bounds = 1, inline = true, opt_level = 2
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS/bf9T0_V1nJs.ji because required dependency MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] with build ID fafbfcfd-ed72-4d9b-0000-03d1bc6516a0 is missing from the cache.
└ @ Base loading.jl:1554
┌ Debug: Precompiling MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:2347
┌ Debug: Rejecting stale cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.ji (mtime 1.692074982973298e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Rejecting stale cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji (mtime 1.692072246726635e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_SyEur.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = false, debug_level = 1, check_bounds = 0, inline = true, opt_level = 0
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_KDIIK.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = true, debug_level = 1, check_bounds = 1, inline = true, opt_level = 2
└ @ Base loading.jl:3015
┌ Debug: Rejecting stale cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.ji (mtime 1.692074982973298e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Rejecting stale cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji (mtime 1.692072246726635e9) because file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl (mtime 1.69207499602758e9) has changed
└ @ Base loading.jl:3138
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_SyEur.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = false, debug_level = 1, check_bounds = 0, inline = true, opt_level = 0
└ @ Base loading.jl:3015
┌ Debug: Rejecting cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_KDIIK.ji for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1] since the flags are mismatched
│   current session: use_pkgimages = true, debug_level = 1, check_bounds = 0, inline = true, opt_level = 2
│   cache file:      use_pkgimages = true, debug_level = 1, check_bounds = 1, inline = true, opt_level = 2
└ @ Base loading.jl:3015
┌ Debug: Precompiling MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:2347
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS/bf9T0_V1nJs.dylib for MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/BitFlags/sbYUO_V1nJs.dylib for BitFlags [d1d4a3ce-64b1-5f1a-9ba4-7e7e69966f35]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/Preferences/pWSk8_V1nJs.dylib for Preferences [21216c6a-2e73-6563-6e65-726566657250]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/JLLWrappers/7Zgw7_V1nJs.dylib for JLLWrappers [692b3bcd-3c85-4b1f-b108-f13ce0eb3210]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/OpenSSL_jll/M3X35_V1nJs.dylib for OpenSSL_jll [458c3c95-2e84-50aa-8efc-19380b2a3a95]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/OpenSSL/B4VRP_V1nJs.dylib for OpenSSL [4d8831e6-92b7-49fb-bdf8-b643e874388c]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Test/JfdTE_lFHnE.dylib for Test [8dfed614-e22c-5e08-85e1-65c5234f0b40]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/ExceptionUnwrapping/DKnWN_V1nJs.dylib for ExceptionUnwrapping [460bff9d-24e4-43bc-9d9f-a8973cb893f4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/ConcurrentUtilities/OtIZJ_V1nJs.dylib for ConcurrentUtilities [f0e56b4a-5159-44fe-b623-3e5288b988bb]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/TranscodingStreams/eJQ7D_V1nJs.dylib for TranscodingStreams [3bb67fe8-82b1-5028-8e26-92a6c54297fa]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Zlib_jll/xjq3Q_lFHnE.dylib for Zlib_jll [83775a58-1f1d-513f-b197-d71354ab007a]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/CodecZlib/1TI30_V1nJs.dylib for CodecZlib [944b1d66-785c-5afd-91f1-9de20f533193]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/SimpleBufferStream/QbHsM_V1nJs.dylib for SimpleBufferStream [777ac1f9-54b0-4bf8-805c-2214025038e7]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/URIs/eec2u_V1nJs.dylib for URIs [5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/LoggingExtras/9fRHf_V1nJs.dylib for LoggingExtras [e6f89c97-d47a-5376-807f-9c37f3926c36]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS_jll/u5NEn_V1nJs.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS/bf9T0_V1nJs.dylib for MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/BitFlags/sbYUO_V1nJs.dylib for BitFlags [d1d4a3ce-64b1-5f1a-9ba4-7e7e69966f35]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/Preferences/pWSk8_V1nJs.dylib for Preferences [21216c6a-2e73-6563-6e65-726566657250]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/JLLWrappers/7Zgw7_V1nJs.dylib for JLLWrappers [692b3bcd-3c85-4b1f-b108-f13ce0eb3210]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/OpenSSL_jll/M3X35_V1nJs.dylib for OpenSSL_jll [458c3c95-2e84-50aa-8efc-19380b2a3a95]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/OpenSSL/B4VRP_V1nJs.dylib for OpenSSL [4d8831e6-92b7-49fb-bdf8-b643e874388c]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Test/JfdTE_lFHnE.dylib for Test [8dfed614-e22c-5e08-85e1-65c5234f0b40]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/ExceptionUnwrapping/DKnWN_V1nJs.dylib for ExceptionUnwrapping [460bff9d-24e4-43bc-9d9f-a8973cb893f4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/ConcurrentUtilities/OtIZJ_V1nJs.dylib for ConcurrentUtilities [f0e56b4a-5159-44fe-b623-3e5288b988bb]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/TranscodingStreams/eJQ7D_V1nJs.dylib for TranscodingStreams [3bb67fe8-82b1-5028-8e26-92a6c54297fa]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Zlib_jll/xjq3Q_lFHnE.dylib for Zlib_jll [83775a58-1f1d-513f-b197-d71354ab007a]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/CodecZlib/1TI30_V1nJs.dylib for CodecZlib [944b1d66-785c-5afd-91f1-9de20f533193]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/SimpleBufferStream/QbHsM_V1nJs.dylib for SimpleBufferStream [777ac1f9-54b0-4bf8-805c-2214025038e7]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/HTTP/zXWya_V1nJs.dylib for HTTP [cd3eb016-35fb-5094-929b-558a96fad6f3]
└ @ Base loading.jl:1051

@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

Okay, I think that #50919 fixes this (against Julia master), but I don't know enough about this part of the codebase to be able to say for sure.

Here is a relevant log snippet from me testing #50919 locally. AFAICT, with #50919, invocations of import HTTP do not cause precompilation, even after I touch the src/MbedTLS_jll.jl source file.

Click to expand:
$ ${MY_STAT_MTIME_CMD:?} ./stdlib/MbedTLS_jll/src/MbedTLS_jll.jl
1692080774
$ ${MY_STAT_MTIME_CMD:?} ./julia-5b50ca4870/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl
1692080395
$ touch ./stdlib/MbedTLS_jll/src/MbedTLS_jll.jl
$ touch ./julia-5b50ca4870/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl
$ ${MY_STAT_MTIME_CMD:?} ./stdlib/MbedTLS_jll/src/MbedTLS_jll.jl
1692081024
$ ${MY_STAT_MTIME_CMD:?} ./julia-5b50ca4870/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl
1692081030
$ ./julia -e 'import HTTP'
┌ Debug: Skipping mtime check for file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/MbedTLS_jll/src/MbedTLS_jll.jl used by /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.ji, since it is a stdlib
│   ispath(f) = true
└ @ Base loading.jl:3127
┌ Debug: Skipping mtime check for file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/Test/src/Test.jl used by /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Test/JfdTE_lFHnE.ji, since it is a stdlib
│   ispath(f) = true
└ @ Base loading.jl:3127
┌ Debug: Skipping mtime check for file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/Test/src/logging.jl used by /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Test/JfdTE_lFHnE.ji, since it is a stdlib
│   ispath(f) = true
└ @ Base loading.jl:3127
┌ Debug: Skipping mtime check for file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/Test/src/precompile.jl used by /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Test/JfdTE_lFHnE.ji, since it is a stdlib
│   ispath(f) = true
└ @ Base loading.jl:3127
┌ Debug: Skipping mtime check for file /Users/dilum/Downloads/julia/usr/share/julia/stdlib/v1.11/Zlib_jll/src/Zlib_jll.jl used by /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Zlib_jll/xjq3Q_lFHnE.ji, since it is a stdlib
│   ispath(f) = true
└ @ Base loading.jl:3127
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/URIs/eec2u_V1nJs.dylib for URIs [5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/LoggingExtras/9fRHf_V1nJs.dylib for LoggingExtras [e6f89c97-d47a-5376-807f-9c37f3926c36]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/MbedTLS_jll/u5NEn_lFHnE.dylib for MbedTLS_jll [c8ffd9c3-330d-5841-b78e-0817d7145fa1]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/MbedTLS/bf9T0_V1nJs.dylib for MbedTLS [739be429-bea8-5141-9913-cc70e7f3736d]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/BitFlags/sbYUO_V1nJs.dylib for BitFlags [d1d4a3ce-64b1-5f1a-9ba4-7e7e69966f35]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/Preferences/pWSk8_V1nJs.dylib for Preferences [21216c6a-2e73-6563-6e65-726566657250]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/JLLWrappers/7Zgw7_V1nJs.dylib for JLLWrappers [692b3bcd-3c85-4b1f-b108-f13ce0eb3210]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/OpenSSL_jll/M3X35_V1nJs.dylib for OpenSSL_jll [458c3c95-2e84-50aa-8efc-19380b2a3a95]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/OpenSSL/B4VRP_V1nJs.dylib for OpenSSL [4d8831e6-92b7-49fb-bdf8-b643e874388c]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Test/JfdTE_lFHnE.dylib for Test [8dfed614-e22c-5e08-85e1-65c5234f0b40]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/ExceptionUnwrapping/DKnWN_V1nJs.dylib for ExceptionUnwrapping [460bff9d-24e4-43bc-9d9f-a8973cb893f4]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/ConcurrentUtilities/OtIZJ_V1nJs.dylib for ConcurrentUtilities [f0e56b4a-5159-44fe-b623-3e5288b988bb]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/TranscodingStreams/eJQ7D_V1nJs.dylib for TranscodingStreams [3bb67fe8-82b1-5028-8e26-92a6c54297fa]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/Downloads/julia/usr/share/julia/compiled/v1.11/Zlib_jll/xjq3Q_lFHnE.dylib for Zlib_jll [83775a58-1f1d-513f-b197-d71354ab007a]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/CodecZlib/1TI30_V1nJs.dylib for CodecZlib [944b1d66-785c-5afd-91f1-9de20f533193]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/SimpleBufferStream/QbHsM_V1nJs.dylib for SimpleBufferStream [777ac1f9-54b0-4bf8-805c-2214025038e7]
└ @ Base loading.jl:1051
┌ Debug: Loading object cache file /Users/dilum/.julia/compiled/v1.11/HTTP/zXWya_V1nJs.dylib for HTTP [cd3eb016-35fb-5094-929b-558a96fad6f3]
└ @ Base loading.jl:1051

@DilumAluthge
Copy link
Member Author

Here's one of the things that I don't understand.

In all of my manual testing, it seems that ispath(f) is true for the stdlib files.

But in the current Julia master, the "skipping mtime check for stdlib" check is only performed if ispath(f) is false, which presumably implies that when that code was being written (in #47184, AFAICT), people were seeing cases where ispath(f) was false for the stdlib files.

So I don't really understand what causes us to go down one branch versus the other for the stdlib files.

@fatteneder
Copy link
Member

fatteneder commented Aug 15, 2023

Wouldn't an implementation of #45541 also fix the problem?

FWIW I have an implementation of that already working in #49886 which one could extract into a separate PR.

@DilumAluthge
Copy link
Member Author

Wouldn't an implementation of #45541 also fix the problem?

Yeah, I believe that #45541 would fix this (and would be a nice thing to have in general).

FWIW I have an implementation of that already working in #49886 which one could extract into a separate PR.

Is this the correct link?

@fatteneder
Copy link
Member

Is this the correct link?

Yes, problem is the implementation is buried in the changes there.

@DilumAluthge
Copy link
Member Author

DilumAluthge commented Aug 15, 2023

FWIW I have an implementation of that already working in #49886 which one could extract into a separate PR.

Is this the correct link?

@fatteneder You wrote #49886. Did you mean to write #49866?

@fatteneder
Copy link
Member

Ups, sorry, yes I meant #49866.

@DilumAluthge
Copy link
Member Author

which one could extract into a separate PR.

@fatteneder Would you be able to extract the "file hashing" functionality from #49866 out into a separate PR? I'd like to get a sense of how big that one specific change is.

@fatteneder
Copy link
Member

fatteneder commented Aug 24, 2023

Below is a patch I extracted from #49866 which should contain the relevant changes, but did not test in isolation.
I am planing to start finishing up #49866 this weekend.

patch
diff --git a/base/loading.jl b/base/loading.jl
index 6ab2a1cd53..0be7a18f83 100644
--- a/base/loading.jl
+++ b/base/loading.jl
@@ -1653,7 +1653,7 @@ const include_callbacks = Any[]
 
 # used to optionally track dependencies when requiring a module:
 const _concrete_dependencies = Pair{PkgId,UInt128}[] # these dependency versions are "set in stone", and the process should try to avoid invalidating them
-const _require_dependencies = Any[] # a list of (mod, path, mtime) tuples that are the file dependencies of the module currently being precompiled
+const _require_dependencies = Any[] # a list of (mod, path, fsize, hash) tuples that are the file dependencies of the module currently being precompiled
 const _track_dependencies = Ref(false) # set this to true to track the list of file dependencies
 function _include_dependency(mod::Module, _path::AbstractString)
     prev = source_path(nothing)
@@ -1664,7 +1664,12 @@ function _include_dependency(mod::Module, _path::AbstractString)
     end
     if _track_dependencies[]
         @lock require_lock begin
-        push!(_require_dependencies, (mod, path, mtime(path)))
+            fsize, hash = if isfile(path)
+                UInt64(filesize(path)), open(_crc32c, path, "r")
+            else
+                UInt64(0), UInt32(0)
+            end
+            push!(_require_dependencies, (mod, path, fsize, hash))
         end
     end
     return path, prev
@@ -1779,7 +1784,7 @@ function __require(into::Module, mod::Symbol)
         end
         uuidkey, env = uuidkey_env
         if _track_dependencies[]
-            push!(_require_dependencies, (into, binpack(uuidkey), 0.0))
+            push!(_require_dependencies, (into, binpack(uuidkey), UInt64(0), UInt32(0)))
         end
         return _require_prelocked(uuidkey, env)
     finally
@@ -2497,7 +2502,8 @@ end
 struct CacheHeaderIncludes
     id::PkgId
     filename::String
-    mtime::Float64
+    fsize::UInt64
+    hash::UInt32
     modpath::Vector{String}   # seemingly not needed in Base, but used by Revise
 end
 
@@ -2525,8 +2531,10 @@ function parse_cache_header(f::IO)
         end
         depname = String(read(f, n2))
         totbytes -= n2
-        mtime = read(f, Float64)
+        fsize = read(f, UInt64)
         totbytes -= 8
+        hash = read(f, UInt32)
+        totbytes -= 4
         n1 = read(f, Int32)
         totbytes -= 4
         # map ids to keys
@@ -2616,7 +2624,7 @@ end
 
 function cache_dependencies(f::IO)
     _, (includes, _), modules, _... = parse_cache_header(f)
-    return modules, map(chi -> (chi.filename, chi.mtime), includes)  # return just filename and mtime
+    return modules, map(chi -> chi.filename, includes)  # return just filename
 end
 
 function cache_dependencies(cachefile::String)
@@ -2967,7 +2975,7 @@ end
         if build_id != UInt128(0)
             id_build = (UInt128(checksum) << 64) | id.second
             if id_build != build_id
-                @debug "Ignoring cache file $cachefile for $modkey ($((UUID(id_build)))) since it is does not provide desired build_id ($((UUID(build_id))))"
+                @debug "Ignoring cache file $cachefile for $modkey ($((UUID(id_build)))) since it does not provide desired build_id ($((UUID(build_id))))"
                 return true
             end
         end
@@ -3005,13 +3013,13 @@ end
         # check if this file is going to provide one of our concrete dependencies
         # or if it provides a version that conflicts with our concrete dependencies
         # or neither
-        skip_timecheck = false
+        skip_hashcheck = false
         for (req_key, req_build_id) in _concrete_dependencies
             build_id = get(modules, req_key, UInt64(0))
             if build_id !== UInt64(0)
                 build_id |= UInt128(checksum) << 64
                 if build_id === req_build_id
-                    skip_timecheck = true
+                    skip_hashcheck = true
                     break
                 end
                 @debug "Rejecting cache file $cachefile because it provides the wrong build_id (got $((UUID(build_id)))) for $req_key (want $(UUID(req_build_id)))"
@@ -3019,42 +3027,40 @@ end
             end
         end
 
-        # now check if this file is fresh relative to its source files
-        if !skip_timecheck
+        # now check if this file's content hash has changed relative to its source files
+        if !skip_hashcheck
             if !samefile(includes[1].filename, modpath) && !samefile(fixup_stdlib_path(includes[1].filename), modpath)
                 @debug "Rejecting cache file $cachefile because it is for file $(includes[1].filename) not file $modpath"
                 return true # cache file was compiled from a different path
             end
             for (modkey, req_modkey) in requires
                 # verify that `require(modkey, name(req_modkey))` ==> `req_modkey`
-                if identify_package(modkey, req_modkey.name) != req_modkey
-                    @debug "Rejecting cache file $cachefile because uuid mapping for $modkey => $req_modkey has changed"
+                pkg = identify_package(modkey, req_modkey.name)
+                if pkg != req_modkey
+                    @debug "Rejecting cache file $cachefile because uuid mapping for $modkey => $req_modkey has changed, expected $modkey => $pkg"
                     return true
                 end
             end
             for chi in includes
-                f, ftime_req = chi.filename, chi.mtime
+                f, fsize_req, hash_req = chi.filename, chi.fsize, chi.hash
                 if !ispath(f)
                     _f = fixup_stdlib_path(f)
                     if isfile(_f) && startswith(_f, Sys.STDLIB)
                         # mtime is changed by extraction
-                        @debug "Skipping mtime check for file $f used by $cachefile, since it is a stdlib"
+                        @debug "Skipping hash check for file $f used by $cachefile, since it is a stdlib"
                         continue
                     end
                     @debug "Rejecting stale cache file $cachefile because file $f does not exist"
                     return true
                 end
-                ftime = mtime(f)
-                is_stale = ( ftime != ftime_req ) &&
-                           ( ftime != floor(ftime_req) ) &&           # Issue #13606, PR #13613: compensate for Docker images rounding mtimes
-                           ( ftime != ceil(ftime_req) ) &&            # PR: #47433 Compensate for CirceCI's truncating of timestamps in its caching
-                           ( ftime != trunc(ftime_req, digits=6) ) && # Issue #20837, PR #20840: compensate for GlusterFS truncating mtimes to microseconds
-                           ( ftime != 1.0 )  &&                       # PR #43090: provide compatibility with Nix mtime.
-                           !( 0 < (ftime_req - ftime) < 1e-6 )        # PR #45552: Compensate for Windows tar giving mtimes that may be incorrect by up to one microsecond
-                if is_stale
-                    @debug "Rejecting stale cache file $cachefile (mtime $ftime_req) because file $f (mtime $ftime) has changed"
+                fsize = filesize(f)
+                if fsize != fsize_req
+                    @debug "Rejecting stale cache file $cachefile (file size $fsize_req) because file $f (file size $fsize) has changed"
                     return true
                 end
+                hash = open(_crc32c, f, "r")
+                if hash != hash_req
+                    @debug "Rejecting stale cache file $cachefile (hash $hash_req) because file $f (hash $hash) has changed"
             end
         end
 
diff --git a/base/sysimg.jl b/base/sysimg.jl
index 04de951dc0..285719d08b 100644
--- a/base/sysimg.jl
+++ b/base/sysimg.jl
@@ -90,8 +90,9 @@ let
             print_time(stdlib, tt)
         end
         for dep in Base._require_dependencies
-            dep[3] == 0.0 && continue
-            push!(Base._included_files, dep[1:2])
+            mod, path, fsize = dep[1], dep[2], dep[3]
+            fsize == 0 && continue
+            push!(Base._included_files, (mod, path))
         end
         empty!(Base._require_dependencies)
         Base._track_dependencies[] = false
diff --git a/src/staticdata.c b/src/staticdata.c
index c05422fd10..58656fc7d0 100644
--- a/src/staticdata.c
+++ b/src/staticdata.c
@@ -2678,7 +2678,7 @@ static void jl_write_header_for_incremental(ios_t *f, jl_array_t *worklist, jl_a
     write_uint8(f, jl_cache_flags());
     // write description of contents (name, uuid, buildid)
     write_worklist_for_header(f, worklist);
-    // Determine unique (module, abspath, mtime) dependencies for the files defining modules in the worklist
+    // Determine unique (module, abspath, hash, fsize) dependencies for the files defining modules in the worklist
     // (see Base._require_dependencies). These get stored in `udeps` and written to the ji-file header.
     // Also write Preferences.
     // last word of the dependency list is the end of the data / start of the srctextpos
diff --git a/src/staticdata_utils.c b/src/staticdata_utils.c
index bf1a830b60..1ff59929bd 100644
--- a/src/staticdata_utils.c
+++ b/src/staticdata_utils.c
@@ -1,11 +1,6 @@
 // inverse of backedges graph (caller=>callees hash)
 jl_array_t *edges_map JL_GLOBALLY_ROOTED = NULL; // rooted for the duration of our uses of this
 
-static void write_float64(ios_t *s, double x) JL_NOTSAFEPOINT
-{
-    write_uint64(s, *((uint64_t*)&x));
-}
-
 // Decide if `t` must be new, because it points to something new.
 // If it is new, the object (in particular, the super field) might not be entirely
 // valid for the cache, so we want to finish transforming it before attempting
@@ -719,7 +714,8 @@ static int64_t write_dependency_list(ios_t *s, jl_array_t* worklist, jl_array_t
         size_t slen = jl_string_len(dep);
         write_int32(s, slen);
         ios_write(s, jl_string_data(dep), slen);
-        write_float64(s, jl_unbox_float64(jl_fieldref(deptuple, 2)));  // mtime
+        write_uint64(s, jl_unbox_uint64(jl_fieldref(deptuple, 2)));  // fsize
+        write_uint32(s, jl_unbox_uint32(jl_fieldref(deptuple, 3)));  // hash
         jl_module_t *depmod = (jl_module_t*)jl_fieldref(deptuple, 0);  // evaluating module
         jl_module_t *depmod_top = depmod;
         while (depmod_top->parent != jl_main_module && depmod_top->parent != depmod_top)
diff --git a/test/precompile.jl b/test/precompile.jl
index 31ceb49475..942f6f5e5a 100644
--- a/test/precompile.jl
+++ b/test/precompile.jl
@@ -374,7 +374,7 @@ precompile_test_harness(false) do dir
         @test string(Base.Docs.doc(Foo.Bar)) == "Bar module\n"
 
         modules, (deps, requires), required_modules, _... = Base.parse_cache_header(cachefile)
-        discard_module = mod_fl_mt -> (mod_fl_mt.filename, mod_fl_mt.mtime)
+        discard_module = mod_fl_mt -> mod_fl_mt.filename
         @test modules == [ Base.PkgId(Foo) => Base.module_build_id(Foo) % UInt64 ]
         @test map(x -> x.filename, deps) == [ Foo_file, joinpath(dir, "foo.jl"), joinpath(dir, "bar.jl") ]
         @test requires == [ Base.PkgId(Foo) => Base.PkgId(string(FooBase_module)),
@@ -545,12 +545,12 @@ precompile_test_harness(false) do dir
     fb_uuid = Base.module_build_id(FooBar)
     sleep(2); touch(FooBar_file)
     insert!(DEPOT_PATH, 1, dir2)
-    @test Base.stale_cachefile(FooBar_file, joinpath(cachedir, "FooBar.ji")) === true
+    @test Base.stale_cachefile(FooBar_file, joinpath(cachedir, "FooBar.ji")) isa Tsc
     @eval using FooBar1
     @test !isfile(joinpath(cachedir2, "FooBar.ji"))
     @test !isfile(joinpath(cachedir, "FooBar1.ji"))
     @test isfile(joinpath(cachedir2, "FooBar1.ji"))
-    @test Base.stale_cachefile(FooBar_file, joinpath(cachedir, "FooBar.ji")) === true
+    @test Base.stale_cachefile(FooBar_file, joinpath(cachedir, "FooBar.ji")) isa Tsc
     @test Base.stale_cachefile(FooBar1_file, joinpath(cachedir2, "FooBar1.ji")) isa Tsc
     @test fb_uuid == Base.module_build_id(FooBar)
     fb_uuid1 = Base.module_build_id(FooBar1)

@fatteneder
Copy link
Member

Should be fixed now on master. Close?

@DilumAluthge
Copy link
Member Author

Fixed by #49866

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
compiler:precompilation Precompilation of modules domain:packages Package management and loading kind:bug Indicates an unexpected problem or unintended behavior
Projects
None yet
4 participants