JuliaWeb / HTTP.jl

HTTP for Julia
https://juliaweb.github.io/HTTP.jl/stable/
Other
635 stars 177 forks source link

Regression in (allocations and thus) loading speed #945

Open PallHaraldsson opened 1 year ago

PallHaraldsson commented 1 year ago

A.

For Kristoffer at #704 (unclear which Julia and HTTP versions used):

julia> @time using HTTP
0.113877 seconds (64.19 k allocations: 5.825 MiB, 7.65% compilation time)

vs. for me on 1.5.0, and Julia 1.8.1 (I don't think I had MbedTLS nor that it would matter):

julia> @time using HTTP
  1.059004 seconds (940.95 k allocations: 55.518 MiB, 1.12% gc time, 73.60% compilation time: 69% of which was recompilation)

julia> @time using HTTP
  1.133385 seconds (963.83 k allocations: 51.194 MiB, 1.46% gc time, 99.99% compilation time: 100% of which was recompilation)

julia> @time using HTTP
  0.000122 seconds (109 allocations: 9.203 KiB)

for:
$ julia -O0
julia> @time using HTTP
  0.660626 seconds (940.95 k allocations: 55.518 MiB, 1.80% gc time, 60.65% compilation time: 75% of which was recompilation)

It's common if you time using three times in a row, that second time is also slow, I think it's an indication of something (packages that load quick tend to have second (and third) fast). Here I think it's unusual that there are more allocations the second time. I've not noticed such before, not sure why or if some hint. It may not be unusual, only me noticing first now.

1.4.0 had slightly lower allocations, so also a regression, which brings me to an unrelated point:

B. Strange installation experience.

(@v1.8) pkg> add HTTP
   Resolving package versions...
    Updating `~/.julia/environments/v1.8/Project.toml`
  [cd3eb016] + HTTP v1.4.0
  No Changes to `~/.julia/environments/v1.8/Manifest.toml`

why did I not get 1.5.0 straight away, which was installable? To be fair, the installation of 1.4.0 was smooth (didn't crash my computer), unlike for 1.5.0.

For 1.5.0, from syslog, julia add triggered OOM, felt unresponsive for like 15 min. recovered, even firefox, even though sub-process of killed:

Oct 19 11:23:21 ryksugan kernel: [4115675.187575] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/user.slice/user-1000.slice/session-c2.scope,task=Isolated Web Co,pid=1557663,uid=1000
Oct 19 11:23:21 ryksugan kernel: [4115675.187682] Out of memory: Killed process 1557663 (Isolated Web Co) total-vm:3217872kB, anon-rss:659940kB, file-rss:0kB, shmem-rss:1680kB, UID:1000 pgtables:4168kB oom_score_adj:167
Oct 19 11:23:22 ryksugan systemd[1]: session-c2.scope: A process of this unit has been killed by the OOM killer.

To my surprise this DID install (i.e. no other packages blocking going to new[est] version; the problems not related to your package, and "fatal" not really fatal), also way to many upgrades, thus precompilation, e.g. Graphviz_jll must be unrelated to HTTP:

(@v1.8) pkg> add HTTP@1.5.0
[..]
    Updating `~/.julia/environments/v1.8/Project.toml`
  [cd3eb016] ↑ HTTP v1.4.0 ⇒ v1.5.0
    Updating `~/.julia/environments/v1.8/Manifest.toml`
  [b552c78f] ↑ DiffRules v1.11.1 ⇒ v1.12.0
  [31c24e10] ↑ Distributions v0.25.75 ⇒ v0.25.76
  [1a297f60] ↑ FillArrays v0.13.4 ⇒ v0.13.5
  [cd3eb016] ↑ HTTP v1.4.0 ⇒ v1.5.0
  [842dd82b] ↑ InlineStrings v1.2.0 ⇒ v1.2.2
  [85b6ec6f] ↑ MethodAnalysis v0.4.10 ⇒ v0.4.11
  [0b3b1443] ↑ MicroMamba v0.1.9 ⇒ v0.1.10
  [6fe1bfb0] ↑ OffsetArrays v1.12.7 ⇒ v1.12.8
  [4d8831e6] ↑ OpenSSL v1.2.1 ⇒ v1.3.0
  [69de0a69] ↑ Parsers v2.4.0 ⇒ v2.4.2
  [ccf2f8ad] ↑ PlotThemes v3.0.0 ⇒ v3.1.0
  [6099a3de] ↑ PythonCall v0.9.6 ⇒ v0.9.8
  [3cdcf5f2] ↑ RecipesBase v1.3.0 ⇒ v1.3.1
  [91c51154] ↑ SentinelArrays v1.3.15 ⇒ v1.3.16
  [bd369af6] ↑ Tables v1.9.0 ⇒ v1.10.0
  [aaaaf01e] ↑ GStreamer_jll v1.18.3+0 ⇒ v1.20.3+0
  [3c863552] + Graphviz_jll v2.50.0+1
  [33b9d88c] ↑ OpenCV_jll v4.5.2+0 ⇒ v4.6.0+0
  [cf2c5f97] ↑ pprof_jll v1.0.0+0 ⇒ v1.0.0+1
Precompiling project...
  Progress [=======================>                 ]  34/60
  ✓ OpenSSL
  ◒ ProfileView
  ✓ PrettyTables
  ◒ Term
  ◒ Distributions
  ✓ HTTP
  ◑ OpenCV
  ◑ CSV
  ◑ SIMDDualNumbers
  ◒ PythonCall
  ◑ GR
  ◑ SDL2_jll
  ◒ DataFrames
^Cfatal: error thrown and no exception handler available.
InterruptException()
jl_mutex_unlock at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/julia_locks.h:129 [inlined]
ijl_task_get_next at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/partr.c:567
poptask at ./task.jl:921
wait at ./task.jl:930
task_done_hook at ./task.jl:634
jfptr_task_done_hook_56370.clone_1 at /home/pharaldsson/.julia/juliaup/julia-1.8.1+0.x64/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/gf.c:2367 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/gf.c:2549
jl_apply at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/julia.h:1838 [inlined]
jl_finish_task at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/task.c:254
start_task at /cache/build/default-amdci5-0/julialang/julia-release-1-dot-8/src/task.c:942
ERROR: InterruptException:
Stacktrace:
 [1] poptask(W::Base.InvasiveLinkedListSynchronized{Task})
   @ Base ./task.jl:921
 [2] wait()
   @ Base ./task.jl:930
 [3] wait(c::Base.GenericCondition{SpinLock})
   @ Base ./condition.jl:124
 [4] wait(x::Base.Process)
   @ Base ./process.jl:661
 [5] success(x::Base.Process)
   @ Base ./process.jl:523
 [6] run(::Cmd; wait::Bool)
   @ Base ./process.jl:480
 [7] run
   @ ./process.jl:477 [inlined]
 [8] repl_cmd(cmd::Cmd, out::Base.TTY)
   @ Base ./client.jl:69
 [9] top-level scope
   @ none:1

Note I killed with CTRL-C (which usually works, just losing the blinking cursor, as here; a known problem), likely would have finished otherwise (or OOM, and julia Pkg sub-process failed, still recovered). I'm not blaming your package (some other might), and too much memory on install a known problem (fixed in newer Julia allegedly, but then seems the fix maybe didn't work).

KristofferC commented 1 year ago

It's common if you time using three times in a row, that second time is also slow, I think it's an indication of something (packages that load quick tend to have second (and third) fast). Here I think it's unusual that there are more allocations the second time. I've not noticed such before, not sure why or if some hint. It may not be unusual, only me noticing first now.

This is when loading the package causes the code loading code itself to get invalidated.

I don't really understand the rest of the post.