Add debug log for monitoring @require time

[IanButterworth]

Adds a debug log so you can monitor @requires that get triggered and the time spent running code

julia> ENV["JULIA_DEBUG"]="Requires"
"Requires"

julia> using Foo
┌ Debug: Requires conditionally ran code in 0.917808094 seconds: `Ratios` detected `FixedPointNumbers`
└ @ Requires ~/.julia/packages/Ratios/xLeZh/src/Ratios.jl:123
┌ Debug: Requires conditionally ran code in 0.531145239 seconds: `ArrayInterface` detected `SuiteSparse`
└ @ Requires ~/.julia/packages/ArrayInterface/mI7ab/src/ArrayInterface.jl:675
┌ Debug: Requires conditionally ran code in 0.002734456 seconds: `ArrayInterface` detected `Adapt`
└ @ Requires ~/.julia/packages/ArrayInterface/mI7ab/src/ArrayInterface.jl:760
┌ Debug: Requires conditionally ran code in 0.029623663 seconds: `ArrayInterface` detected `StaticArrays`
└ @ Requires ~/.julia/packages/ArrayInterface/mI7ab/src/ArrayInterface.jl:690
┌ Debug: Requires conditionally ran code in 0.006599821 seconds: `ArrayInterface` detected `OffsetArrays`
└ @ Requires ~/.julia/packages/ArrayInterface/mI7ab/src/ArrayInterface.jl:1116
┌ Debug: Requires conditionally ran code in 0.022674606 seconds: `HDF5` detected `FileIO`
└ @ Requires ~/.julia/packages/HDF5/pIJra/src/HDF5.jl:2133
┌ Debug: Requires conditionally ran code in 0.002288416 seconds: `RandomNumbers` detected `Random123`
└ @ Requires ~/.julia/packages/RandomNumbers/3pD1N/src/RandomNumbers.jl:38
┌ Debug: Requires conditionally ran code in 1.708197842 seconds: `CUDA` detected `SpecialFunctions`
└ @ Requires ~/.julia/packages/CUDA/sCev8/src/initialization.jl:35
┌ Debug: Requires conditionally ran code in 0.0126559 seconds: `ArrayInterface` detected `Adapt`
└ @ Requires ~/.julia/packages/ArrayInterface/mI7ab/src/ArrayInterface.jl:796
┌ Debug: Requires conditionally ran code in 0.029985851 seconds: `ArrayInterface` detected `CUDA`
└ @ Requires ~/.julia/packages/ArrayInterface/mI7ab/src/ArrayInterface.jl:795
┌ Debug: Requires conditionally ran code in 2.06503522 seconds: `Zygote` detected `CUDA`
└ @ Requires ~/.julia/packages/Zygote/umM0L/src/lib/broadcast.jl:251
┌ Debug: Requires conditionally ran code in 0.211960078 seconds: `Zygote` detected `Distances`
└ @ Requires ~/.julia/packages/Zygote/umM0L/src/Zygote.jl:45
┌ Debug: Requires conditionally ran code in 0.258361828 seconds: `Zygote` detected `LogExpFunctions`
└ @ Requires ~/.julia/packages/Zygote/umM0L/src/Zygote.jl:46
┌ Debug: Requires conditionally ran code in 0.003038184 seconds: `Zygote` detected `Colors`
└ @ Requires ~/.julia/packages/Zygote/umM0L/src/Zygote.jl:60
┌ Debug: Requires conditionally ran code in 0.284711345 seconds: `ImageMorphology` detected `ImageMetadata`
└ @ Requires ~/.julia/packages/ImageMorphology/6oqcS/src/ImageMorphology.jl:65
┌ Debug: Requires conditionally ran code in 0.002487405 seconds: `RegisterCore` detected `ImageMetadata`
└ @ Requires ~/.julia/packages/RegisterCore/YuSsR/src/RegisterCore.jl:397

julia> 

cc. @ChrisRackauckas I think you were also after something like this

[ChrisRackauckas]

Beautiful!

[codecov]

Codecov Report

Merging #107 (7cce756) into master (4c301db) will increase coverage by 2.26%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master     #107      +/-   ##
==========================================
+ Coverage   62.66%   64.93%   +2.26%     
==========================================
  Files           3        3              
  Lines          75       77       +2     
==========================================
+ Hits           47       50       +3     
+ Misses         28       27       -1     

Impacted Files	Coverage Δ
src/Requires.jl	66.66% <ø> (ø)
src/require.jl	78.57% <100.00%> (+2.64%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 010426f...7cce756. Read the comment docs.

[KristofferC]

Nice, looks like a good idea to me at least.

[ChrisRackauckas]

Yeah I don't know how to understand this. When I run it, I get:

using Profile
ENV["JULIA_DEBUG"]="Requires"
@time @profile using DifferentialEquations 

┌ Debug: Requires conditionally ran code in 0.0024978 seconds: `ArrayInterface` detected `SuiteSparse`
└ @ Requires C:\Users\accou\.julia\packages\ArrayInterface\TCj9U\src\ArrayInterface.jl:677
┌ Debug: Requires conditionally ran code in 0.0158724 seconds: `ArrayInterface` detected `StaticArrays`
└ @ Requires C:\Users\accou\.julia\packages\ArrayInterface\TCj9U\src\ArrayInterface.jl:692
┌ Debug: Requires conditionally ran code in 0.0029026 seconds: `ArrayInterface` detected `LabelledArrays`        
└ @ Requires C:\Users\accou\.julia\packages\ArrayInterface\TCj9U\src\ArrayInterface.jl:772
┌ Debug: Requires conditionally ran code in 0.0025199 seconds: `ArrayInterface` detected `Adapt`
└ @ Requires C:\Users\accou\.julia\packages\ArrayInterface\TCj9U\src\ArrayInterface.jl:762
┌ Debug: Requires conditionally ran code in 0.0168244 seconds: `Polyester` detected `ForwardDiff`
└ @ Requires C:\Users\accou\.julia\packages\Polyester\hFLHn\src\Polyester.jl:19
┌ Debug: Requires conditionally ran code in 0.0026288 seconds: `Setfield` detected `StaticArrays`
└ @ Requires C:\Users\accou\.julia\packages\Setfield\9IaGB\src\Setfield.jl:31
┌ Debug: Requires conditionally ran code in 0.0060201 seconds: `ArrayInterface` detected `OffsetArrays`
└ @ Requires C:\Users\accou\.julia\packages\ArrayInterface\TCj9U\src\ArrayInterface.jl:914
┌ Debug: Requires conditionally ran code in 0.0020892 seconds: `RandomNumbers` detected `Random123`
└ @ Requires C:\Users\accou\.julia\packages\RandomNumbers\3pD1N\src\RandomNumbers.jl:38
┌ Debug: Requires conditionally ran code in 0.0042834 seconds: `ArrayInterface` detected `BandedMatrices`        
└ @ Requires C:\Users\accou\.julia\packages\ArrayInterface\TCj9U\src\ArrayInterface.jl:809
  6.158199 seconds (19.59 M allocations: 1.412 GiB, 4.35% gc time, 14.08% compilation time)

using ProfileView
ProfileView.view()

And this has puzzled me for weeks. I think the debug timings are correct because I mentioned to @KristofferC a few weeks ago that I went through DiffEq's stack and just removed all of the Requires usage from almost all downstream packages and saw almost no compile-time reduction, and those timings of about a 0.02 change match what I saw. So then it really confuses me that it takes 6 seconds and the profile says almost all of those 6 seconds are in Requires.jl. Either the profile is wrong or Requires.jl is doing something really horrifying even when it's not used to init.

[vchuravy]

What is ProfileView.view(;C=true)?

[ChrisRackauckas]

A nice cityscape when viewed from a distance.

Including the profile:

diffeq_requires_profile_with_C.zip

though it's really easy to recreate it if you need it locally.

[IanButterworth]

I just ran this myself. The orange bars are loading.jl, _include_from_serialized for me. I can't see Requires in any of the big blocks? Am I missing something, or am I getting different behavior?

[ChrisRackauckas]

OOOOOOOOOOOOOOOOOOOOOOOOOOOOH, loading.jl require, not Requires 😅 . Carry on. This debug information looks to match the profile then where I see little ArrayInterface.jl mountains which are ultimately insignificant. Awesome!

[IanButterworth]

haha! Great.
On mine, I've only found Requires in the section I'm hovering over here

[IanButterworth]

Tim's handled the last few merges and releases here, but seems pretty busy. Does anyone else have merge & release rights?

[timholy]

We could clear out all the warnings (now that Julia 1.7 does this automatically), but that could be a separate PR.

[timholy]

Thanks! JuliaRegistries/General#52183

Tim's handled the last few merges and releases here, but seems pretty busy

Yup. Race against time to make progress on latency before the semester starts in earnest...