rearrange inlining of `ensureroom` and speed it up #27874

JeffBezanson · 2018-06-29T23:07:59Z

If you look at the IR for write(::IOBuffer, ::UInt8), it is absurdly large since both ensureroom and compact get inlined, plus there are spurious error checks for cases that don't happen. This separates the rare part of ensureroom into its own noinline function, and tightens up some of the rest of the code. This benchmark:

function buf()
    b = IOBuffer()
    for i = 1:100000
        write(b, '\u2200')
    end
    String(take!(b))
end

gets almost 2x faster plus code size is significantly reduced.

vtjnash · 2018-06-29T23:43:19Z

base/iobuffer.jl

+
+@inline ensureroom(io::GenericIOBuffer, nshort::Int) = ensureroom(io, UInt(nshort))
+@inline function ensureroom(io::GenericIOBuffer, nshort::UInt)
+    if !io.writable || !io.seekable


Can we make this !io.writable || (!io.seekable && io.ptr > 1)? One extra comparison and branch here shouldn't be much extra cost, but that would restore the expected fastpath for !seekable.

KristofferC · 2018-06-30T10:21:52Z

@nanosoldier runbenchmarks(ALL, vs = ":master")

nanosoldier · 2018-06-30T16:17:26Z

Your benchmark job has completed - possible performance regressions were detected. A full report can be found here. cc @ararslan

vtjnash · 2018-06-30T17:51:47Z

String join is probably a test of this, and shows a large regression, but within the variance sometimes observed. So may need to check that locally

ararslan · 2018-07-02T03:38:33Z

@nanosoldier runbenchmarks("string" && "join", vs=":master")

nanosoldier · 2018-07-02T04:47:58Z

Your benchmark job has completed - no performance regressions were detected. A full report can be found here. cc @ararslan

JeffBezanson · 2018-07-02T21:53:12Z

Hmm, this now seems to have an unusually large effect on sysimg build time. Will need to investigate; it might turn up something generally interesting.

KristofferC · 2018-08-16T21:02:15Z

Indeed, including Base goes from 27 to 74 seconds with this...

vtjnash · 2018-10-22T19:45:55Z

rebase this and see if it's better now?

KristofferC · 2018-10-22T19:53:07Z

Base  ─────────── 78.449089 seconds

KristofferC · 2018-10-22T20:32:42Z

FWIW, I found that almost all slowdown is from including show.jl which on this branch takes 47 seconds compared to 2.7 seconds on master. The rest of the files seems have fairly similar timing.

KristofferC · 2018-10-22T20:49:39Z

In fact, evaluating the following method definition seems to account for the full slowdown:

julia/base/show.jl

Lines 1567 to 1586 in c162219

    
           function show(io::IO, src::CodeInfo) 
        
               # Fix slot names and types in function body 
        
               print(io, "CodeInfo(") 
        
               lambda_io::IOContext = io 
        
               if src.slotnames !== nothing 
        
                   lambda_io = IOContext(lambda_io, :SOURCE_SLOTNAMES => sourceinfo_slotnames(src)) 
        
               end 
        
               @assert src.codelocs !== nothing 
        
               if isempty(src.linetable) || src.linetable[1] isa LineInfoNode 
        
                   println(io) 
        
                   # TODO: static parameter values? 
        
                   IRShow.show_ir(lambda_io, src) 
        
               else 
        
                   # this is a CodeInfo that has not been used as a method yet, so its locations are still LineNumberNodes 
        
                   body = Expr(:block) 
        
                   body.args = src.code 
        
                   show(lambda_io, body) 
        
               end 
        
               print(io, ")") 
        
           end

Hopefully that is enough to figure out what is going on.

KristofferC · 2018-10-22T20:56:47Z

In fact, replacing that function definition with

g() = @assert 1==1

is enough to trigger the slowdown so it has something to do with the string stuff in the @assert macro.

Note that

g() = @assert true

does not lead to a slowdown.

vtjnash · 2018-10-22T21:12:13Z

defining show(io::IO, src::CodeInfo) = @assert 1 == 1 is effectively equivalent to calling string(:(1 == 1))

KristofferC · 2018-10-22T21:24:07Z

Liked @vtjnash said, just putting a string(:(1 == 1)) at top level is enough to trigger it.

KristofferC · 2018-10-22T21:41:02Z

We have

string(xs...) = print_to_string(xs...)

and

julia> @which string(:(1==1))
string(xs...) in Base at strings/io.jl:155

but evaluating

print_to_string(:(1==1))

does not give a slowdown while

string(:(1==1))

does. I think I am reaching my limit here :)

vtjnash · 2018-10-22T21:47:51Z

Quite strange. You could try enabling JL_DEBUG_METHOD_INVALIDATION (in gf.c) and/or set --trace-compile= during compilation and see if there are substantive differences.

KristofferC · 2018-10-23T14:24:16Z

Commenting out the compact call

https://github.com/JuliaLang/julia/pull/27874/files#diff-1cac367ddf750f99a052d3119eb8381fR288

makes precompile(Tuple{typeof(Base.string), Expr})

go from 56 seconds to 0.4 seconds.

Also inserting a

precompile(Tuple{typeof(Base.compact), Base.GenericIOBuffer{Array{UInt8,1}}})

before the call to

precompile(Tuple{typeof(Base.string), Expr})

makes it fast.

Forcing interrupt (for the long case) gives

sig_match_simple at /Users/kristoffer/julia/src/typemap.c:175
jl_typemap_entry_assoc_exact at /Users/kristoffer/julia/src/typemap.c:781
jl_typemap_assoc_exact at /Users/kristoffer/julia/src/./julia_internal.h:879 [inlined]
jl_lookup_generic_ at /Users/kristoffer/julia/src/gf.c:2148
jl_apply_generic at /Users/kristoffer/julia/src/gf.c:2194
pure_eval_call at ./compiler/abstractinterpretation.jl:496
abstract_call at ./compiler/abstractinterpretation.jl:729
abstract_eval_call at ./compiler/abstractinterpretation.jl:765
abstract_eval at ./compiler/abstractinterpretation.jl:850
typeinf_local at ./compiler/abstractinterpretation.jl:1093
typeinf_nocycle at ./compiler/abstractinterpretation.jl:1149
typeinf at ./compiler/typeinfer.jl:15
typeinf_edge at ./compiler/typeinfer.jl:492
abstract_call_method at ./compiler/abstractinterpretation.jl:324
abstract_call_gf_by_type at ./compiler/abstractinterpretation.jl:81
abstract_call at ./compiler/abstractinterpretation.jl:736
abstract_eval_call at ./compiler/abstractinterpretation.jl:765
abstract_eval at ./compiler/abstractinterpretation.jl:850
typeinf_local at ./compiler/abstractinterpretation.jl:1093
typeinf_nocycle at ./compiler/abstractinterpretation.jl:1149
typeinf at ./compiler/typeinfer.jl:15
...

over and over.

I tried to do some profiling but didn't get anything reasonable

KristofferC · 2018-10-23T15:15:25Z

Commenting out the

    copyto!(io.data, 1, io.data, ptr, bytes_to_move)

in compact makes it fast.

KristofferC · 2018-10-23T16:05:54Z

I pushed a commit that works around the inference problem. Good ol' outlining to the rescue...

@nanosoldier runbenchmarks(ALL, vs = ":master")

ararslan · 2018-10-23T17:21:06Z

Nanosoldier needs code quoting around the command for whatever reason. @nanosoldier runbenchmarks(ALL, vs=":master")

KristofferC · 2018-10-23T18:13:56Z

@vtjnash noted that this PR didn't follow the styleguide proposed in #29727 and therefore gave the compiler a bit of extra headache (fixing it didn't remove the need of the first workaround, however):

julia> @code_warntype Base.ensureroom_slowpath(IOBuffer(), UInt64(5))
Body::Union{Nothing, Int64, GenericIOBuffer{Array{UInt8,1}}}

Fixed in the last commit.

KristofferC · 2018-10-23T18:14:52Z

Im curious if that changed the benchmarks anything

@nanosoldier runbenchmarks(ALL, vs=":master")

nanosoldier · 2018-10-24T00:08:24Z

Your benchmark job has completed - possible performance regressions were detected. A full report can be found here. cc @ararslan

nanosoldier · 2018-10-24T01:00:10Z

Your benchmark job has completed - possible performance regressions were detected. A full report can be found here. cc @ararslan

KristofferC · 2018-10-24T02:04:59Z

On 1.0.1 I don't see compact getting inlined (but it does seem to get inlined on master) but I can't reproduce the performance improvements in the OP.

master:

julia> @btime buf();
  3.334 ms (20 allocations: 514.55 KiB)

1.0.1:

julia> @btime buf();
  3.311 ms (19 allocations: 514.58 KiB)

PR:

julia> @btime buf();
  3.313 ms (19 allocations: 514.53 KiB)

But less code bloat is good anyway?

KristofferC · 2018-10-29T17:54:27Z

What should be done here now that #29795 is merged? If the @noinline is no longer needed, should I just drop that and then we merge here? Or just merge as is? @vtjnash

vtjnash

lgtm. do we need a nanosoldier run or any such other test?

KristofferC · 2018-10-29T20:00:46Z

There hasn't been any change here since the last nanosoldier run so presumably not.

JeffBezanson added performance Must go faster io Involving the I/O subsystem: libuv, read, write, etc. strings "Strings!" labels Jun 29, 2018

vtjnash reviewed Jun 29, 2018

View reviewed changes

JeffBezanson force-pushed the jb/iobufinl branch from 08b3ad6 to 2e0dd24 Compare July 2, 2018 15:31

JeffBezanson added the DO NOT MERGE Do not merge this PR! label Sep 7, 2018

rearrange inlining of ensureroom and speed it up

cae3724

KristofferC force-pushed the jb/iobufinl branch from 2e0dd24 to 9c406a6 Compare October 23, 2018 16:05

work around inference problem with recursive string calls

198e452

KristofferC force-pushed the jb/iobufinl branch from 9c406a6 to 198e452 Compare October 23, 2018 16:07

fix return value of ensureroom_slowpath

8cb29c7

KristofferC added the potential benchmark Could make a good benchmark in BaseBenchmarks label Oct 24, 2018

vtjnash mentioned this pull request Oct 24, 2018

inference performance: drop some unnecessary edges, cache more #29795

Merged

vtjnash approved these changes Oct 29, 2018

View reviewed changes

JeffBezanson removed the DO NOT MERGE Do not merge this PR! label Oct 29, 2018

KristofferC merged commit e2f7b2f into master Oct 30, 2018

KristofferC deleted the jb/iobufinl branch October 30, 2018 20:08

JeffBezanson mentioned this pull request Dec 19, 2018

package precompile is slow #15048

Closed

KristofferC mentioned this pull request Jan 27, 2020

Tab-completion in REPL hangs JuliaData/CSV.jl#537

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

rearrange inlining of `ensureroom` and speed it up #27874

rearrange inlining of `ensureroom` and speed it up #27874

JeffBezanson commented Jun 29, 2018

vtjnash Jun 29, 2018

KristofferC commented Jun 30, 2018

nanosoldier commented Jun 30, 2018

vtjnash commented Jun 30, 2018

ararslan commented Jul 2, 2018

nanosoldier commented Jul 2, 2018

JeffBezanson commented Jul 2, 2018

KristofferC commented Aug 16, 2018 •

edited

Loading

vtjnash commented Oct 22, 2018

KristofferC commented Oct 22, 2018

KristofferC commented Oct 22, 2018

KristofferC commented Oct 22, 2018

KristofferC commented Oct 22, 2018 •

edited

Loading

vtjnash commented Oct 22, 2018

KristofferC commented Oct 22, 2018 •

edited

Loading

KristofferC commented Oct 22, 2018 •

edited

Loading

vtjnash commented Oct 22, 2018

KristofferC commented Oct 23, 2018 •

edited

Loading

KristofferC commented Oct 23, 2018 •

edited

Loading

KristofferC commented Oct 23, 2018

ararslan commented Oct 23, 2018

KristofferC commented Oct 23, 2018 •

edited

Loading

KristofferC commented Oct 23, 2018

nanosoldier commented Oct 24, 2018

nanosoldier commented Oct 24, 2018

KristofferC commented Oct 24, 2018

KristofferC commented Oct 29, 2018 •

edited

Loading

vtjnash left a comment

KristofferC commented Oct 29, 2018

rearrange inlining of ensureroom and speed it up #27874

rearrange inlining of ensureroom and speed it up #27874

Conversation

JeffBezanson commented Jun 29, 2018

vtjnash Jun 29, 2018

Choose a reason for hiding this comment

KristofferC commented Jun 30, 2018

nanosoldier commented Jun 30, 2018

vtjnash commented Jun 30, 2018

ararslan commented Jul 2, 2018

nanosoldier commented Jul 2, 2018

JeffBezanson commented Jul 2, 2018

KristofferC commented Aug 16, 2018 • edited Loading

vtjnash commented Oct 22, 2018

KristofferC commented Oct 22, 2018

KristofferC commented Oct 22, 2018

KristofferC commented Oct 22, 2018

KristofferC commented Oct 22, 2018 • edited Loading

vtjnash commented Oct 22, 2018

KristofferC commented Oct 22, 2018 • edited Loading

KristofferC commented Oct 22, 2018 • edited Loading

vtjnash commented Oct 22, 2018

KristofferC commented Oct 23, 2018 • edited Loading

KristofferC commented Oct 23, 2018 • edited Loading

KristofferC commented Oct 23, 2018

ararslan commented Oct 23, 2018

KristofferC commented Oct 23, 2018 • edited Loading

KristofferC commented Oct 23, 2018

nanosoldier commented Oct 24, 2018

nanosoldier commented Oct 24, 2018

KristofferC commented Oct 24, 2018

KristofferC commented Oct 29, 2018 • edited Loading

vtjnash left a comment

Choose a reason for hiding this comment

KristofferC commented Oct 29, 2018

rearrange inlining of `ensureroom` and speed it up #27874

rearrange inlining of `ensureroom` and speed it up #27874

KristofferC commented Aug 16, 2018 •

edited

Loading

KristofferC commented Oct 22, 2018 •

edited

Loading

KristofferC commented Oct 22, 2018 •

edited

Loading

KristofferC commented Oct 22, 2018 •

edited

Loading

KristofferC commented Oct 23, 2018 •

edited

Loading

KristofferC commented Oct 23, 2018 •

edited

Loading

KristofferC commented Oct 23, 2018 •

edited

Loading

KristofferC commented Oct 29, 2018 •

edited

Loading