`@time_imports` giving ` ERROR: type Pair has no field id` on nightly

[anandijain]

I should note that there is the odd behavior that if I start julia, do @time_imports using CSV then it will work, but if I do @time_imports using LocalDevPrivatePackage then it will fail with the below trace. Once this one fails, then all subsequent @time_imports fail. I also checked that just using LocalDevPrivatePackage works fine.

happy to provide more info, but im not sure what else is relevant here

mwe:

@time_imports using CSV # works 
@time_imports using PrivatePackage # fails 
@time_imports using CSV # fails 

trace:

julia> @time_imports using CSV
   95.2 ms  ERROR: type Pair has no field id
Stacktrace:
[1] getproperty
  @ ./Base.jl:37 [inlined]
[2] _include_from_serialized(pkg::Base.PkgId, path::String, ocachepath::String, depmods::Vector{Any})
  @ Base ./loading.jl:1024
[3] _tryrequire_from_serialized(modkey::Base.PkgId, path::String, ocachepath::String, sourcepath::String, depmods::Vector{Any})
  @ Base ./loading.jl:1332
[4] _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String, build_id::UInt128)
  @ Base ./loading.jl:1425
[5] _require(pkg::Base.PkgId, env::String)
  @ Base ./loading.jl:1760
[6] _require_prelocked(uuidkey::Base.PkgId, env::String)
  @ Base ./loading.jl:1643
[7] macro expansion
  @ ./loading.jl:1631 [inlined]
[8] macro expansion
  @ ./lock.jl:267 [inlined]
[9] require(into::Module, mod::Symbol)
  @ Base ./loading.jl:1594
[10] top-level scope
  @ ~/.juliaup/julia-b5d17ea2b3/share/julia/stdlib/v1.10/InteractiveUtils/src/macros.jl:243

versioninfo():

Julia Version 1.10.0-DEV.537
Commit b5d17ea2b3d (2023-02-08 09:40 UTC)
Platform Info:
OS: Linux (x86_64-linux-gnu)
CPU: 64 × AMD EPYC 7513 32-Core Processor
WORD_SIZE: 64
LIBM: libopenlibm
LLVM: libLLVM-14.0.6 (ORCJIT, znver3)
Threads: 8 on 64 virtual cores
Environment:
JULIA_NUM_THREADS = 8

I can't share my manifest due to a bunch of private packages.

[KristofferC]

Introduced in #48513 (which got backported to 1.9)

[gbaraldi]

I wasn't able to reproduce this, but the fix is pretty simple

                for extid in EXT_DORMITORY
                    if extid[2].id == pkg # <===
                        print(extid[2].parentid.name, " → ")  #<===
                        break
                    end
                end

dictionary iteration giving pairs is very big pet peeve of mine.

[vtjnash]

EXT_DORMATORY should not contain extid at this point in the code, so this part of the code is simply wrong

Also, looks like timing_imports code may be failing to handle IO exceptions correctly (or at all), which can be rather bad also (as seen here breaking using). Shouldn't this be using the logging system?

[gbaraldi]

IO exceptions aside, it seems this is just looking for the parent of the current extension #47945 though I will defer to @IanButterworth who wrote it.

[IanButterworth]

Mea culpa.. forgot to add tests in #47945

Shouldn't this be using the logging system?

AFAIK the logging system is too inflexible to:

• Report from multiple places in real time, as packages load
  AND
• Have cohesive formatting, rather than just a bunch of Info: prints

[IanButterworth]

From a UX perspective it's also supposed to be more aligned with @time than JULIA_DEBUG

[gbaraldi]

FYI #48513 broke the whole logic of your printing system :).

[IanButterworth]

Given you've started looking into this, it might be worth starting a PR with a test? I'm not sure when I'll have time

[gbaraldi]

I'll see if I can think of something, though we might defer loading extensions to the end after loading every normal package. We might want to invert and print the parent when loading the extension though.

[KristofferC]

As I said, building it on top of #48586 should be trivial. Just grab the extension from EXT_PRIMED (and thereby the parent)

[KristofferC]

Should be fixed in the second commit in #48586.

[gbaraldi]

Thanks!

[KristofferC]

We should still probably have a test for this.