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

How much is spent in optimizer vs in inference? (Answer: about a half) #1

Closed
wants to merge 1 commit into from

Conversation

tkf
Copy link
Owner

@tkf tkf commented Sep 2, 2021

I patched the compiler with simple timing instrumentation.

Then, after first precompiling Plots and GR I removed just Plots:

shell> rm -rf ~/.julia/compiled/v1.8/Plots

Just precompiling Plots shows me

julia> @time using Plots
[ Info: Precompiling Plots [91a5bcdd-55d7-5caf-9e0b-520d859cae80]
Compiler.StopWatches: inf=23.0033577 opt=8.303108823 ratio=0.36095203714542945 meanopt=0.00011737833728688966
 35.439623 seconds (9.59 M allocations: 625.895 MiB, 1.32% gc time, 0.12% compilation time)

which indicates:

  • inf=23.0033577: 23 seconds spent in inference and optimizer
  • opt=8.303108823: 8 seconds spent in optimizer
  • ratio=0.36095203714542945: 36% is in optimizer
  • meanopt=0.00011737833728688966: average second took in optimizer for each function

Actually running plot shows a higher ratio:

julia> show(devnull, "image/png", plot(1:3))

julia> exit()
Compiler.StopWatches: inf=2.96327332 opt=1.585064293 ratio=0.5349031701874871 meanopt=0.00013306449739758228

Eyeballing the outputs from the precompilation of other packages, it looks like it typically ranges from 40% to 60% are spent in the optimizer. So, I guess "about a half" is probably a good rough idea.

@tkf tkf closed this Sep 2, 2021
KristofferC pushed a commit that referenced this pull request Aug 31, 2022
…Lang#45790)

Currently the `@nospecialize`-d `push!(::Vector{Any}, ...)` can only
take a single item and we will end up with runtime dispatch when we try
to call it with multiple items:
```julia
julia> code_typed(push!, (Vector{Any}, Any))
1-element Vector{Any}:
 CodeInfo(
1 ─      $(Expr(:foreigncall, :(:jl_array_grow_end), Nothing, svec(Any, UInt64), 0, :(:ccall), Core.Argument(2), 0x0000000000000001, 0x0000000000000001))::Nothing
│   %2 = Base.arraylen(a)::Int64
│        Base.arrayset(true, a, item, %2)::Vector{Any}
└──      return a
) => Vector{Any}

julia> code_typed(push!, (Vector{Any}, Any, Any))
1-element Vector{Any}:
 CodeInfo(
1 ─ %1 = Base.append!(a, iter)::Vector{Any}
└──      return %1
) => Vector{Any}
```

This commit adds a new specialization that it can take arbitrary-length
items. Our compiler should still be able to optimize the single-input 
case as before via the dispatch mechanism.
```julia
julia> code_typed(push!, (Vector{Any}, Any))
1-element Vector{Any}:
 CodeInfo(
1 ─      $(Expr(:foreigncall, :(:jl_array_grow_end), Nothing, svec(Any, UInt64), 0, :(:ccall), Core.Argument(2), 0x0000000000000001, 0x0000000000000001))::Nothing
│   %2 = Base.arraylen(a)::Int64
│        Base.arrayset(true, a, item, %2)::Vector{Any}
└──      return a
) => Vector{Any}

julia> code_typed(push!, (Vector{Any}, Any, Any))
1-element Vector{Any}:
 CodeInfo(
1 ─ %1  = Base.arraylen(a)::Int64
│         $(Expr(:foreigncall, :(:jl_array_grow_end), Nothing, svec(Any, UInt64), 0, :(:ccall), Core.Argument(2), 0x0000000000000002, 0x0000000000000002))::Nothing
└──       goto JuliaLang#7 if not true
2 ┄ %4  = φ (#1 => 1, JuliaLang#6 => %14)::Int64
│   %5  = φ (#1 => 1, JuliaLang#6 => %15)::Int64
│   %6  = Base.getfield(x, %4, true)::Any
│   %7  = Base.add_int(%1, %4)::Int64
│         Base.arrayset(true, a, %6, %7)::Vector{Any}
│   %9  = (%5 === 2)::Bool
└──       goto #4 if not %9
3 ─       goto JuliaLang#5
4 ─ %12 = Base.add_int(%5, 1)::Int64
└──       goto JuliaLang#5
5 ┄ %14 = φ (#4 => %12)::Int64
│   %15 = φ (#4 => %12)::Int64
│   %16 = φ (#3 => true, #4 => false)::Bool
│   %17 = Base.not_int(%16)::Bool
└──       goto JuliaLang#7 if not %17
6 ─       goto #2
7 ┄       return a
) => Vector{Any}
```

This commit also adds the equivalent implementations for `pushfirst!`.
KristofferC pushed a commit that referenced this pull request Aug 31, 2022
When calling `jl_error()` or `jl_errorf()`, we must check to see if we
are so early in the bringup process that it is dangerous to attempt to
construct a backtrace because the data structures used to provide line
information are not properly setup.

This can be easily triggered by running:

```
julia -C invalid
```

On an `i686-linux-gnu` build, this will hit the "Invalid CPU Name"
branch in `jitlayers.cpp`, which calls `jl_errorf()`.  This in turn
calls `jl_throw()`, which will eventually call `jl_DI_for_fptr` as part
of the backtrace printing process, which fails as the object maps are
not fully initialized.  See the below `gdb` stacktrace for details:

```
$ gdb -batch -ex 'r' -ex 'bt' --args ./julia -C invalid
...
fatal: error thrown and no exception handler available.
ErrorException("Invalid CPU name "invalid".")

Thread 1 "julia" received signal SIGSEGV, Segmentation fault.
0xf75bd665 in std::_Rb_tree<unsigned int, std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo>, std::_Select1st<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> >, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__k=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h:1277
1277    /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h: No such file or directory.
 #0  0xf75bd665 in std::_Rb_tree<unsigned int, std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo>, std::_Select1st<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> >, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__k=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h:1277
 #1  std::map<unsigned int, JITDebugInfoRegistry::ObjectInfo, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__x=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_map.h:1258
 #2  jl_DI_for_fptr (fptr=4155049385, symsize=symsize@entry=0xffffcfa8, slide=slide@entry=0xffffcfa0, Section=Section@entry=0xffffcfb8, context=context@entry=0xffffcf94) at /cache/build/default-amdci5-4/julialang/julia-master/src/debuginfo.cpp:1181
 #3  0xf75c056a in jl_getFunctionInfo_impl (frames_out=0xffffd03c, pointer=4155049385, skipC=0, noInline=0) at /cache/build/default-amdci5-4/julialang/julia-master/src/debuginfo.cpp:1210
 #4  0xf7a6ca98 in jl_print_native_codeloc (ip=4155049385) at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:636
 JuliaLang#5  0xf7a6cd54 in jl_print_bt_entry_codeloc (bt_entry=0xf0798018) at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:657
 JuliaLang#6  jlbacktrace () at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:1090
 JuliaLang#7  0xf7a3cd2b in ijl_no_exc_handler (e=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:605
 JuliaLang#8  0xf7a3d10a in throw_internal (ct=ct@entry=0xf070c010, exception=<optimized out>, exception@entry=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:638
 JuliaLang#9  0xf7a3d330 in ijl_throw (e=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:654
 JuliaLang#10 0xf7a905aa in ijl_errorf (fmt=fmt@entry=0xf7647cd4 "Invalid CPU name \"%s\".") at /cache/build/default-amdci5-4/julialang/julia-master/src/rtutils.c:77
 JuliaLang#11 0xf75a4b22 in (anonymous namespace)::createTargetMachine () at /cache/build/default-amdci5-4/julialang/julia-master/src/jitlayers.cpp:823
 JuliaLang#12 JuliaOJIT::JuliaOJIT (this=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/jitlayers.cpp:1044
 JuliaLang#13 0xf7531793 in jl_init_llvm () at /cache/build/default-amdci5-4/julialang/julia-master/src/codegen.cpp:8585
 JuliaLang#14 0xf75318a8 in jl_init_codegen_impl () at /cache/build/default-amdci5-4/julialang/julia-master/src/codegen.cpp:8648
 JuliaLang#15 0xf7a51a52 in jl_restore_system_image_from_stream (f=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2131
 JuliaLang#16 0xf7a55c03 in ijl_restore_system_image_data (buf=0xe859c1c0 <jl_system_image_data> "8'\031\003", len=125161105) at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2184
 JuliaLang#17 0xf7a55cf9 in jl_load_sysimg_so () at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:424
 JuliaLang#18 ijl_restore_system_image (fname=0x80a0900 "/build/bk_download/julia-d78fdad601/lib/julia/sys.so") at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2157
 JuliaLang#19 0xf7a3bdfc in _finish_julia_init (rel=rel@entry=JL_IMAGE_JULIA_HOME, ct=<optimized out>, ptls=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/init.c:741
 JuliaLang#20 0xf7a3c8ac in julia_init (rel=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/init.c:728
 JuliaLang#21 0xf7a7f61d in jl_repl_entrypoint (argc=<optimized out>, argv=0xffffddf4) at /cache/build/default-amdci5-4/julialang/julia-master/src/jlapi.c:705
 JuliaLang#22 0x080490a7 in main (argc=3, argv=0xffffddf4) at /cache/build/default-amdci5-4/julialang/julia-master/cli/loader_exe.c:59
```

To prevent this, we simply avoid calling `jl_errorf` this early in the
process, punting the problem to a later PR that can update guard
conditions within `jl_error*`.
vtjnash pushed a commit that referenced this pull request Sep 27, 2023
This makes it easier to correlate LLVM IR with the originating source
code by including both argument name and argument type in the LLVM
argument variable.

<details>
<summary>Example 1</summary>

```julia
julia> function f(a, b, c, d, g...)
           e = a + b + c + d
           f = does_not_exist(e) + e
           f
       end
f (generic function with 1 method)

julia> @code_llvm f(0,0,0,0,0)
```
```llvm
;  @ REPL[1]:1 within `f`
define nonnull {}* @julia_f_141(i64 signext %"a::Int64", i64 signext %"b::Int64", i64 signext %"c::Int64", i64 signext %"d::Int64", i64 signext %"g[0]::Int64") #0 {
top:
  %0 = alloca [2 x {}*], align 8
  %gcframe3 = alloca [4 x {}*], align 16
  %gcframe3.sub = getelementptr inbounds [4 x {}*], [4 x {}*]* %gcframe3, i64 0, i64 0
  %1 = bitcast [4 x {}*]* %gcframe3 to i8*
  call void @llvm.memset.p0i8.i64(i8* align 16 %1, i8 0, i64 32, i1 true)
  %thread_ptr = call i8* asm "movq %fs:0, $0", "=r"() JuliaLang#7
  %tls_ppgcstack = getelementptr i8, i8* %thread_ptr, i64 -8
  %2 = bitcast i8* %tls_ppgcstack to {}****
  %tls_pgcstack = load {}***, {}**** %2, align 8
;  @ REPL[1]:3 within `f`
  %3 = bitcast [4 x {}*]* %gcframe3 to i64*
  store i64 8, i64* %3, align 16
  %4 = getelementptr inbounds [4 x {}*], [4 x {}*]* %gcframe3, i64 0, i64 1
  %5 = bitcast {}** %4 to {}***
  %6 = load {}**, {}*** %tls_pgcstack, align 8
  store {}** %6, {}*** %5, align 8
  %7 = bitcast {}*** %tls_pgcstack to {}***
  store {}** %gcframe3.sub, {}*** %7, align 8
  %Main.does_not_exist.cached = load atomic {}*, {}** @0 unordered, align 8
  %iscached.not = icmp eq {}* %Main.does_not_exist.cached, null
  br i1 %iscached.not, label %notfound, label %found

notfound:                                         ; preds = %top
  %Main.does_not_exist.found = call {}* @ijl_get_binding_or_error({}* nonnull inttoptr (i64 139831437630272 to {}*), {}* nonnull inttoptr (i64 139831600565400 to {}*))
  store atomic {}* %Main.does_not_exist.found, {}** @0 release, align 8
  br label %found

found:                                            ; preds = %notfound, %top
  %Main.does_not_exist = phi {}* [ %Main.does_not_exist.cached, %top ], [ %Main.does_not_exist.found, %notfound ]
  %8 = bitcast {}* %Main.does_not_exist to {}**
  %does_not_exist.checked = load atomic {}*, {}** %8 unordered, align 8
  %.not = icmp eq {}* %does_not_exist.checked, null
  br i1 %.not, label %err, label %ok

err:                                              ; preds = %found
  call void @ijl_undefined_var_error({}* inttoptr (i64 139831600565400 to {}*))
  unreachable

ok:                                               ; preds = %found
  %.sub = getelementptr inbounds [2 x {}*], [2 x {}*]* %0, i64 0, i64 0
;  @ REPL[1]:2 within `f`
; ┌ @ operators.jl:587 within `+` @ int.jl:87
   %9 = add i64 %"b::Int64", %"a::Int64"
   %10 = add i64 %9, %"c::Int64"
; │ @ operators.jl:587 within `+`
; │┌ @ operators.jl:544 within `afoldl`
; ││┌ @ int.jl:87 within `+`
     %11 = add i64 %10, %"d::Int64"
     %12 = getelementptr inbounds [4 x {}*], [4 x {}*]* %gcframe3, i64 0, i64 3
     store {}* %does_not_exist.checked, {}** %12, align 8
; └└└
;  @ REPL[1]:3 within `f`
  %13 = call nonnull {}* @ijl_box_int64(i64 signext %11)
  %14 = getelementptr inbounds [4 x {}*], [4 x {}*]* %gcframe3, i64 0, i64 2
  store {}* %13, {}** %14, align 16
  store {}* %13, {}** %.sub, align 8
  %15 = call nonnull {}* @ijl_apply_generic({}* nonnull %does_not_exist.checked, {}** nonnull %.sub, i32 1)
  store {}* %15, {}** %12, align 8
  %16 = call nonnull {}* @ijl_box_int64(i64 signext %11)
  store {}* %16, {}** %14, align 16
  store {}* %15, {}** %.sub, align 8
  %17 = getelementptr inbounds [2 x {}*], [2 x {}*]* %0, i64 0, i64 1
  store {}* %16, {}** %17, align 8
  %18 = call nonnull {}* @ijl_apply_generic({}* inttoptr (i64 139831370516384 to {}*), {}** nonnull %.sub, i32 2)
  %19 = load {}*, {}** %4, align 8
  %20 = bitcast {}*** %tls_pgcstack to {}**
  store {}* %19, {}** %20, align 8
;  @ REPL[1]:4 within `f`
  ret {}* %18
}
```
</details>

<details>
<summary>Example 2</summary>

```julia
julia> function g(a, b, c, d; kwarg=0)
           a + b + c + d + kwarg
       end
g (generic function with 1 method)

julia> @code_llvm g(0,0,0,0,kwarg=0)
```
```llvm
;  @ REPL[3]:1 within `g`
define i64 @julia_g_160([1 x i64]* nocapture noundef nonnull readonly align 8 dereferenceable(8) %"#1::NamedTuple", i64 signext %"a::Int64", i64 signext %"b::Int64", i64 signext %"c::Int64", i64 signext %"d::Int64") #0 {
top:
  %0 = getelementptr inbounds [1 x i64], [1 x i64]* %"#1::NamedTuple", i64 0, i64 0
; ┌ @ REPL[3]:2 within `#g#1`
; │┌ @ operators.jl:587 within `+` @ int.jl:87
    %1 = add i64 %"b::Int64", %"a::Int64"
    %2 = add i64 %1, %"c::Int64"
; ││ @ operators.jl:587 within `+`
; ││┌ @ operators.jl:544 within `afoldl`
; │││┌ @ int.jl:87 within `+`
      %3 = add i64 %2, %"d::Int64"
; │││└
; │││ @ operators.jl:545 within `afoldl`
; │││┌ @ int.jl:87 within `+`
      %unbox = load i64, i64* %0, align 8
      %4 = add i64 %3, %unbox
; └└└└
  ret i64 %4
}
```
</details>
vtjnash added a commit that referenced this pull request Oct 30, 2023
…#51489)

This exposes the GC "stop the world" API to the user, for causing a
thread to quickly stop executing Julia code. This adds two APIs (that
will need to be exported and documented later):
```
julia> @CCall jl_safepoint_suspend_thread(#=tid=#1::Cint, #=magicnumber=#2::Cint)::Cint # roughly tkill(1, SIGSTOP)

julia> @CCall jl_safepoint_resume_thread(#=tid=#1::Cint)::Cint # roughly tkill(1, SIGCONT)
```

You can even suspend yourself, if there is another task to resume you 10
seconds later:
```
julia> ccall(:jl_enter_threaded_region, Cvoid, ())

julia> t = @task let; Libc.systemsleep(10); print("\nhello from $(Threads.threadid())\n"); @CCall jl_safepoint_resume_thread(0::Cint)::Cint; end; ccall(:jl_set_task_tid, Cint, (Any, Cint), t, 1); schedule(t);

julia> @time @CCall jl_safepoint_suspend_thread(0::Cint, 2::Cint)::Cint

hello from 2
  10 seconds (6 allocations: 264 bytes)
1
```

The meaning of the magic number is actually the kind of stop that you
want:
```
// n.b. suspended threads may still run in the GC or GC safe regions
// but shouldn't be observable, depending on which enum the user picks (only 1 and 2 are typically recommended here)
// waitstate = 0 : do not wait for suspend to finish
// waitstate = 1 : wait for gc_state != 0 (JL_GC_STATE_WAITING or JL_GC_STATE_SAFE)
// waitstate = 2 : wait for gc_state != 0 (JL_GC_STATE_WAITING or JL_GC_STATE_SAFE) and that GC is not running on that thread
// waitstate = 3 : wait for full suspend (gc_state == JL_GC_STATE_WAITING) -- this may never happen if thread is sleeping currently
// if another thread comes along and calls jl_safepoint_resume, we also return early
// return new suspend count on success, 0 on failure
```
Only magic number 2 is currently meaningful to the user though. The
difference between waitstate 1 and 2 is only relevant in C code which is
calling this from JL_GC_STATE_SAFE, since otherwise it is a priori known
that GC isn't running, else we too would be running the GC. But the
distinction of those states might be useful if we have a concurrent
collector.

Very important warning: if the stopped thread is holding any locks
(e.g. for codegen or types) that you then attempt to acquire, your
thread will deadlock. This is very likely, unless you are very careful.
A future update to this API may try to change the waitstate to give the
option to wait for the thread to release internal or known locks.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant